Analyzing trace information using profiling tools

After you have created a trace file, the easiest way to analyze it is to use the profiling tools provided on the Tool tab of the New dialog box. There are three tools:

  • The Profiling Class View shows information about the objects that were used in the application

  • The Profiling Routine View shows information about all the routines (functions and events) that were used in the application

  • The Profiling Trace View shows the elapsed time taken by each activity in chronological order

Using the profiling tools as a model

Even if you want to develop your own analysis tools, using the profiling tools is a good way to learn about these models and about profiling in PowerBuilder. When you are ready to develop your own tools, see Analyzing trace information programmatically for an overview of the approaches you can take.

Profiling Class View

The Class view uses a TreeView control to display statistics for PowerBuilder objects, their functions, and their events. It displays statistics only for those objects that were active while tracing was enabled. The Class view has three tabs:

  • Numbers

    Shows statistics only

  • Graph

    Shows statistics in a bar graph

  • Source

    Shows statistics and source code for those routines that originated in PowerScript source

For each object, the Class view shows all the routines called from each class with the number of times each routine was called (hit) as well as timing information for each call. The following illustration shows part of a Class view. Embedded SQL commands are shown as being called from a pseudo class called ESQL.


The Class view includes both PowerBuilder system-level objects (such as DataWindow and SystemFunction) and user-defined classes (such as windows and user objects). Each top-level node is a PowerBuilder class. As you expand the TreeView control, each node represents a routine and each subnode represents a called routine.

The Class view uses the call graph model to show cumulative statistics for objects, routines, and called routines. The information displayed on the right side of the display differs depending on the current node on the left.

Current node

Statistics displayed

Application

Statistics for each object

Object

Cumulative statistics for the object and detailed statistics for the object's routines

Routine

Cumulative statistics for the routine and detailed statistics for called routines


You can sort items on the right by clicking the heading.

Class view metrics

The Class view displays five metrics. The profiling tool accesses these metrics from instances of the ProfileCall and ProfileRoutine objects. The time scale you specified in the Preferences dialog box determines how times are displayed.

Metric

What it means

Hits

The number of times a routine executed in a particular context.

Self

The time spent in the routine or line itself. If the routine or line was executed more than once, this is the total time spent in the routine or line itself; it does not include time spent in routines called by this routine.

%Self

Self as a percentage of the total time the calling routine was active.

Self+Called

The time spent in the routine or line and in routines or lines called from the routine or line. If the routine or line was executed more than once, this is the total time spent in the routine or line and in called routines or lines.

%Self+Called

Self+Called as a percentage of the total time that tracing was enabled.


About percentages

The percentages captured in the trace file are based on the total time tracing was enabled. Because an application can be idle (while displaying a MessageBox, for example), percentage metrics are most meaningful when you control tracing programmatically, which can help to minimize idle time. Percentages are least meaningful when you create a trace file for a complete application.

Profiling Routine View

The Routine view displays statistics for a routine, its calling routines, and its called routines. It uses multiple DataWindow objects to display information for a routine:

  • Called routines

    The top DataWindow lists functions and events called by the current routine.

  • Current routine

    The middle DataWindow and the DataWindow on the right highlight the current routine and show detailed statistics.

  • Calling routines

    The bottom DataWindow lists functions and events that call the routine displayed in the middle DataWindow.

The Routine view has two tabs:

  • Detail

    Shows statistics only

  • Source

    Shows statistics and source code for those routines that originated in PowerScript source

The Routine view uses the call graph model to show the call chain and cumulative statistics for routines and called routines.


You can specify the current routine by clicking in the various DataWindows.

To do this

Click here

Establish a new current routine in the current routine DataWindow

On the routine. The profiling tool updates the top and bottom DataWindows with information on called and calling routines.

Select a calling routine as the new routine

On the routine in the top DataWindow. The profiling tool makes it the current routine in the middle DataWindow.

Select a called routine as the new routine

On the routine in the bottom DataWindow. The profiling tool makes it the current routine in the middle DataWindow.


You can sort items by clicking the column headings.

Routine view metrics

The Routine view displays nine metrics. The profiling tool accesses these metrics from instances of the ProfileCall and ProfileRoutine objects. The time scale you specified in the Preferences dialog box determines how times are displayed.

Metric

What it means

Hits (Called on Detail tab)

The number of times a routine executed in a particular context.

Self

The time spent in the routine or line itself. If the routine or line was executed more than once, this is the total time spent in the routine or line itself; it does not include time spent in routines called by this routine.

%Self

Self as a percentage of the total time the calling routine was active.

Self Min

The shortest time spent in the routine or line itself. If the routine or line was executed only once, this is the same as AbsoluteSelfTime.

Self Max

The longest time spent in the routine or line itself. If the routine or line was executed only once, this is the same as AbsoluteSelfTime.

Self+Called

The time spent in the routine or line and in routines or lines called from the routine or line. If the routine or line was executed more than once, this is the total time spent in the routine or line and in called routines or lines.

%Self+Called

Self+Called as a percentage of the total time that tracing was enabled.

Self+Called Min

The shortest time spent in the routine or line and in called routines or lines. If the routine or line was executed only once, this is the same as AbsoluteTotalTime.

Self+Called Max

The longest time spent in the routine or line and in called routines or lines. If the routine or line was executed only once, this is the same as AbsoluteTotalTime.


Profiling Trace View

The Trace view uses a TreeView control to display the events and functions in the trace file. The initial display shows top-level routines. Each node expands to show the sequence of routine execution. The fully expanded TreeView shows the complete sequence of executed instructions for the trace file.

The Trace view uses the trace tree model to show the sequence of execution. It includes statistics and (for those routines that originated in PowerScript source) source code.

You can use the Trace View Options section of the Preferences dialog box to control the display:

  • System routines

    This option controls whether the Trace view includes information for lines that execute PowerBuilder system routines.

  • Line information

    This option controls whether the Trace view includes line numbers.

The following screen shows a Trace view with several nodes expanded. The number to the right of each item is the execution time for that item.


Trace view metrics

The Trace view displays two metrics. The profiling tool accesses these metrics from instances of the TraceTree and TraceTreeNode objects.

Entry

What it means

Routine or line number

The routine or line number that was executed.

Execution time

Total execution time for the Tree view entry. This is total time from the start of the entry to the end of the entry. For example, if you call the MessageBox function, this value reflects the elapsed time from when the message box was opened until the user provided some kind of response.


About preferences

The specifications you make in the Preferences dialog box control whether the Trace view displays system functions and line numbers.

Setting call aggregation preferences

You can control how the profiling tools display information using the Preferences dialog box. To open it, select Options>Preferences from any profiling view's menu bar.

In both Class and Routine views, you can choose how functions and events that are called more than once are displayed. Select the Aggregate Calls check box if you want the view to display a single line for each called function or event that represents a sum of all the times it was called. If you do not select the check box, the view displays statistics for each call on a separate line.

For example, if aggregation is enabled and a function calls another function five times, you see one entry with five hits; with no aggregation, you see five separate entries for the same function.

Internally, the profiling tool controls aggregation by using the AggregateDuplicateRoutineCalls boolean argument to the OutgoingCallList and IncomingCallList functions on the ProfileRoutine object.