Analyzing trace information programmatically

PowerBuilder provides three ways to analyze trace information using built-in system objects and functions:

  • Analyze performance by building a call graph model

    A call graph model contains information about all the routines in the trace file: how many times each routine was called, which routines called it and which routines it called, and the execution time taken by the routine itself and any routines it called.

  • Analyze program structure and logical flow by building a trace tree model

    A trace tree model contains information about all recorded activities in the trace file in chronological order, with the elapsed time for each activity.

  • Access the data in the trace file directly

    Trace objects and functions let you build your own model and analysis tools by giving you access to all the data in the trace file.

The profiling tools use the first two ways. The Class and Routine views are based on a call graph model, and the Trace view is based on a trace tree model.

Supporting files needed

To create a profile from a trace file, PowerBuilder must also access the PBL, PBD, or executable file used to create the trace file, and the PBL, PBD, or executable file must be in the same location as when the trace file was created.

Analyzing performance with a call graph model

You use the PowerScript functions and PowerBuilder objects listed in The following table to analyze the performance of an application.

Use this function

With this object

To do this

SetTraceFileName

Profiling

Set the name of the trace file to be analyzed.

BuildModel

Profiling

Build a call graph model based on the trace file. You can pass optional parameters that let you track the progress of the build.

RoutineList

Profiling and ProfileClass

Get a list of routines in the model or in a class.

ClassList

Profiling

Get a list of classes in the model.

SystemRoutine

Profiling

Get the name of the routine node that represents the root of the model.

IncomingCallList

ProfileRoutine

Get a list of routines that called a specific routine.

OutgoingCallList

ProfileRoutine and ProfileLine

Get a list of routines called by a specific routine or from a specific line.

LineList

ProfileRoutine

Get a list of lines in the routine in line order.

DestroyModel

Profiling

Destroy the current performance analysis model and all the objects associated with it.


Each of these functions returns a value of the enumerated datatype ErrorReturn. The objects contain information such as the number of times a line or routine was executed, and the amount of time spent in a line or routine and in any routines called from that line or routine.

Using the BuildModel function to build a call graph model

The call graph model that you create with the BuildModel function contains all the routines in the trace file and can take a long time to build. If you want to monitor the progress of the build or you want to be able to interrupt it while the model is being built, you can pass optional arguments to BuildModel.

BuildModel arguments

BuildModel takes three arguments: the name of an object of type PowerObject, the name of a user event, and a long value representing how often the user event should be triggered as a percentage of the build completed.

The user event returns a boolean value and has two arguments: the number of the current activity, and the total number of activities in the trace file.

Destroying existing models

Before you call BuildModel, you can call DestroyModel to clean up any objects remaining from an existing model.

Example: building a call graph model

In the following example, the user event argument to BuildModel is called ue_progress and is triggered each time five percent of the activities have been processed. The progress of the build is shown in a window called w_progress that has a cancel button.

Profiling lpro_model
lpro_model = CREATE Profiling
ib_cancel = FALSE
lpro_model.SetTraceFileName(is_fileName )

open(w_progress)
// call the of_init window function to initialize
// the w_progress window
w_progress.of_init(lpro_model.numberofactivities, &
   'Building Model', this, 'ue_cancel')

// Build the call graph model
lpro_model.BuildModel(this, 'ue_progress', 5)

// clicking the cancel button in w_progress
// sets ib_cancel to TRUE and
// returns FALSE to ue_progress
IF ib_cancel THEN &
   close(w_progress)
   RETURN -1
END IF

Extracting information from the call graph model

After you have built a call graph model of the application, you can extract detailed information from it.

For routines and lines, you can extract the timing information shown in the following table from the ProfileRoutine and ProfileLine objects.

Property

What it means

AbsoluteSelfTime

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.

MinSelfTime

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.

MaxSelfTime

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.

AbsoluteTotalTime

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.

MinTotalTime

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.

MaxTotalTime

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.

PercentSelfTime

AbsoluteSelfTime as a percentage of the total time tracing was active.

PercentTotalTime

AbsoluteTotalTime as a percentage of the total time tracing was active.


Example: extracting information from a call graph model

The following function extracts information from a call graph model about the routines called from a specific routine. You would use similar functions to extract information about the routines that called the given routine and about the routine itself.

The function takes a ProfileCall object and an index as arguments and returns a structure containing the number of times the called routine was executed and execution times for the called routine.

str_func_detail lstr_result
ProfileClass lproclass_class
ProfileRoutine lprort_routine

// get the name of the called routine
// from the calledroutine property of
// the ProfileCall object passed to the function
lprort_routine = a_pcall.Calledroutine
lstr_result.Name = ""
lproclass_class = a_pcall.Class
IF isValid(lproclass_class) THEN &
   lstr_result.Name += lproclass_class.Name + "."
lstr_result.name += a_pcall.Name

lstr_result.hits = a_pcall.HitCount
lstr_result.selfTime = a_pcall. &
   AbsoluteSelfTime * timeScale
lstr_result.totalTime = a_pcall. &
   AbsoluteTotalTime * timeScale
lstr_result.percentSelf = a_pcall.PercentSelfTime
lstr_result.percentTotal= a_pcall.PercentTotalTime
lstr_result.index = al_index

RETURN lstr_result

Analyzing structure and flow using a trace tree model

You use the PowerScript functions and PowerBuilder objects listed in the following table to build a nested trace tree model of an application.

Use this function

With this object

To do this

SetTraceFileName

TraceTree

Set the name of the trace file to be analyzed.

BuildModel

TraceTree

Build a trace tree model based on the trace file. You can pass optional parameters that let you track the progress of the build.

EntryList

TraceTree

Get a list of the top-level entries in the trace tree model.

GetChildrenList

TraceTreeRoutine, TraceTreeObject, and TraceTreeGarbageCollect

Get a list of the children of the routine or object—that is, all the routines called directly by the routine, or the destructor called as a result of the object's deletion.

DestroyModel

TraceTree

Destroy the current trace tree model and all the objects associated with it.


Each of these functions returns a value of type ErrorReturn.

Each TraceTreeNode object returned by the EntryList and GetChildrenList functions represents a single node in the trace tree model and contains information about the parent of the node and the type of activity it represents.

Inherited objects

The following objects inherit from TraceTreeNode and contain additional information, including timer values:

  • TraceTreeError

  • TraceTreeESQL

  • TraceTreeGarbageCollect

  • TraceTreeLine

  • TraceTreeObject

  • TraceTreeRoutine

  • TraceTreeUser

Using BuildModel to build a trace tree model

You use the same approach to building a trace tree model as you do to building a call graph model, except that you build a model of type TraceTree instead of type Profiling.

For example:

TraceTree ltct_treemodel
ltct_treemodel = CREATE TraceTree
ltct_treeModel.SetTraceFileName( is_fileName )
ltct_treeModel.BuildModel(this, 'ue_progress', 1)

For more about using BuildModel, see Using the BuildModel function to build a call graph model.

Extracting information from the trace tree model

To extract information from a tree model, you can use the EntryList function to create a list of top-level entries in the model and then loop through the list, extracting information about each node. For each node, determine its activity type using the TraceActivity enumerated datatype, and then use the appropriate TraceTree object to extract information.

Example: trace tree model

The following simple example extracts information from an existing trace tree model and stores it in a structure:

TraceTreeNode ltctn_list[], ltctn_node
long ll_index, ll_limit
string ls_line 
str_node lstr_node

ltct_treemodel.EntryList(ltctn_list)
ll_limit = UpperBound(ltctn_list)
FOR ll_index = 1 to ll_limit   
   ltctn_node = ltctn_list[ll_index]
   of_dumpnode(ltctn_node, lstr_node)
   // insert code to handle display of
   // the information in the structure here
   …
NEXT

The of_dumpnode function takes a TraceTreeNode object and a structure as arguments and populates the structure with information about each node. The following code shows part of the function:

string ls_exit, ls_label, ls_routinename
long ll_node_cnt
TraceTreeNode ltctn_list[]
errorreturn l_err

astr_node.Children = FALSE
astr_node.Label = ''
IF NOT isvalid(atctn_node) THEN RETURN
CHOOSE CASE atctn_node.ActivityType
   CASE ActRoutine!
     TraceTreeRoutine ltctrt_routin   
     ltctrt_routine = atctn_node
     IF ltctrt_routine.Classname = '' THEN &
        ls_routinename = ltctrt_routine.ClassName + "."
     END IF   
     ls_routinename += ltctrt_routine.Name
     ltctrt_routine.GetChildrenList(ltctn_list)
     ll_node_cnt = UpperBound(ltctn_list)

     ls_label = "Execute " + ls_routinename + ' :' + &
         space(ii_offset) + String(l_timescale * &
         (ltctrt_routine.ExitTimerValue - &
         ltctrt_routine.EnterTimerValue), '0.000000')
     astr_node.Children = (ll_node_cnt > 0)
     astr_node.Label = ls_label
     astr_node.Time = ltctrt_routine.EnterTimerValue
     RETURN
   CASE ActLine!
     TraceTreeLine tctln_treeLine   
     tctln_treeLine = atctn_node   
     ls_label = LINEPREFIX + &
        String(tctln_treeLine.LineNumber )
     astr_node.time = tctln_treeLine.Timervalue
     ...
     // CASE statements omitted
     ...
   CASE ELSE
     ls_label = "INVALID NODE"
   END CHOOSE

   astr_node.label = ls_label
   RETURN

Accessing trace data directly

You use the PowerScript functions and PowerBuilder objects listed in the following table to access the data in the trace file directly so that you can develop your own analysis tools.

Use this function

With this object

To do this

Open

TraceFile

Opens the trace file to be analyzed.

NextActivity

TraceFile

Returns the next activity in the trace file. The value returned is of type TraceActivityNode.

Reset

TraceFile

Resets the next activity to the beginning of the trace file.

Close

TraceFile

Closes the open trace file.


With the exception of NextActivity, each of these functions returns a value of type ErrorReturn. Each TraceActivityNode object includes information about the category of the activity, the timer value when the activity occurred, and the activity type.

Timer values

The category of the activity is either TraceIn! or TraceOut! for activities that have separate beginning and ending points, such as routines, garbage collection, and tracing itself. Each such activity has two timer values associated with it: the time when it began and the time when it completed.

Activities that have only one associated timer value are in the category TraceAtomic!. ActLine!, ActUser!, and ActError! are all atomic activities.

Inherited objects

The following objects inherit from TraceActivityNode and contain data about the associated activity type:

  • TraceBeginEnd

  • TraceError

  • TraceESQL

  • TraceGarbageCollect

  • TraceLine

  • TraceObject

  • TraceRoutine

  • TraceUser

TraceTreeNode and TraceActivityNode objects

The objects that inherit from TraceActivityNode are analogous to those that inherit from TraceTreeNode, and you can use similar techniques when you write applications that use them.

For a list of activity types, see Trace activities.

Using the TraceFile object

To access the data in the trace file directly, you create a TraceFile object, open a trace file, and then use the NextActivity function to access each activity in the trace file sequentially. For each node, determine what activity type it is by examining the TraceActivity enumerated datatype, and then use the appropriate trace object to extract information.

Example: direct access to trace data

The following example creates a TraceFile object, opens a trace file called ltcf_file, and then uses a function called of_dumpActivityNode to report the appropriate information for each activity depending on its activity type.

string ls_fileName
TraceFile ltcf_file
TraceActivityNode ltcan_node
string ls_line

ls_fileName = sle_filename.Text
ltcf_file = CREATE TraceFile
ltcf_file.Open(ls_fileName)
ls_line = "CollectionTime = " + &
   String(Truncate(ltcf_file.CollectionTime, 6)) &
   + "~r~n" + "Number of Activities = " + &
   String(ltcf_file.NumberOfActivities) + "~r~n" + &
   "Time Stamp " + "Activity" + "~r~n"

mle_output.text = ls_line

ltcan_node = ltcf_file.NextActivity()
DO WHILE IsValid(ltcan_node)
   ls_line += of_dumpActivityNode(ltcan_node)
   ltcan_node = ltcf_file.NextActivity()
LOOP

mle_output.text = ls_line
ltcf_file.Close()

The following code shows part of of_dumpActivityNode:

string lstr_result

lstr_result = String(Truncate(atcan_node. &
   TimerValue, 6)) + " "
CHOOSE CASE atcan_node.ActivityType
   CASE ActRoutine!
      TraceRoutine ltcrt_routine
      ltcrt_routine = atcan_node
      IF ltcrt_routine.IsEvent THEN
        lstr_result += "Event: "
      ELSE
        lstr_result += "Function: "
      END IF
      lstr_result += ltcrt_routine.ClassName + "." + &
         ltcrt_routine.name + "(" + &
         ltcrt_routine.LibraryName + ") " &
         + String(ltcrt_routine.ObjectId) + "~r~n"
   CASE ActLine!
      TraceLine ltcln_line
      ltcln_line = atcan_node
      lstr_result += "Line: " +     &
         String(ltcln_line.LineNumber) + "~r~n"
   CASE ActESQL!   
      TraceESQL ltcSQL_eSQL
      ltcSQL_eSQL = atcan_node
      lstr_result += "ESQL: " + ltcSQL_eSQL.Name &
          + "~r~n"

   // CASE statements and code omitted
   ...
   CASE ActBegin!
      IF atcan_node.Category = TraceIn! THEN
         lstr_result += "Begin Tracing~r~n"
      ELSE
         lstr_result += "End Tracing~r~n"
      END IF
   CASE ActGarbageCollect!
      lstr_result += "Garbage Collection~r~n"
   CASE else
      lstr_result += "Unknown Activity~r~n"
END CHOOSE

RETURN lstr_result