Portlet Factory, Version 6.1.2

 

Starting builder call timing tracing

To analyze the time that builder calls take during regeneration, you can start builder call timing tracing. You may have to perform this task to analyze slow regeneration of a model. You can do this tracing both in IBM® WebSphere Portlet Factory Designer and on the server. The tracing collects timing data on builder calls during regeneration of a model. During regeneration, each builder in the model is called in sequence by its order in the builder call list.

  1. Change the builderCallTiming property in the log4j.properties file.

    1. Navigate to and open the appropriate properties file.

      • For WebSphere Portlet Factory Designer 
        install_root/WPFDesigner/eclipse/plugins/com.bowstreet.designer.core_x.y.z/config/log4j.properties

      • For the server 
        WEB-INF/config/log4j.properties
    2. In the file, find the following line. 
      log4j.category.bowstreet.system.builderCallTiming=WARN,BuilderCallTiming
    3. Change the property value to DEBUG, save, and close the file. 
      log4j.category.bowstreet.system.builderCallTiming=DEBUG,BuilderCallTiming

  2. To start logging, restart WebSphere Portlet Factory Designer.

    If you changed the property for the server, restart the application server or portal server.

    The logging of builder call timing data starts on the console and in the log file.

  3. To stop logging, change the property value back to WARN and restart WebSphere Portlet Factory Designer and the server.

  4. Examine the log file that contains the builder call timing data.

    1. Navigate to and open the logging file.

      • For WebSphere Portlet Factory Designer 
        workspace/.metadata/.plugins/com.bowstreet.designer.core/logs/builderCallTiming.txt

      • For the server 
        WEB-INF/logs/builderCallTiming.txt

The output is very similar to system trace output that is produced by model action tracing. The log file has the following structure.

  • Each regeneration phase is placed in its own section. The phase name is enclosed in square brackets ([ and ]) with the model name.

  • On each line are two time values in milliseconds and an associated builder type preceded by a period character ( . ) and a name.

    Multiple periods before a builder type indicates nested builder calls, for example, when a higher-level builder calls a constituent builder.

  • Generation traces for subordinate models (for example, a Linked Model builder) are shown in line.

  • If a builder that runs in the PostConstruction phase calls another builder, you see a transition back to the Construction phase (for example, [Construction (temporary):). 
*-- TIME: [2007-05-08 15:20:48,579] --* Category: bowstreet.system.builderCallTiming Priority: INFO Thread:   main Msg:
 13314 15173    Start Request: Generate SimpleTest
     0     0    [Construction: SimpleTest]
    78    78    .Action List: main
    47    47    .Page: page1
    15    15    .Method: doSomething
In the logged data, look for the following trends.

  • Lengthy time accessing an external source. For example, an SQL Call builder performing schema generation.

  • Excessive number of builder calls. Often, one builder call results in a substantially larger number of other builder calls.

  • One model accessing another model by the Imported Model builder. The other model may be causing the poor regeneration performance. You may have to restructure your model usage.

Parent topic: Overview: debugging an application

Library | Support |