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 Table 33-8 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.
|
1 |
Profiling lpro_model<br />lpro_model = CREATE Profiling<br />ib_cancel = FALSE<br />lpro_model.SetTraceFileName(is_fileName )<br /> <br />open(w_progress)<br />// call the of_init window function to initialize<br />// the w_progress window<br />w_progress.of_init(lpro_model.numberofactivities, &<br /> 'Building Model', this, 'ue_cancel')<br /> <br />// Build the call graph model<br />lpro_model.BuildModel(this, 'ue_progress', 5)<br /> <br />// clicking the cancel button in w_progress<br />// sets ib_cancel to TRUE and<br />// returns FALSE to ue_progress<br />IF ib_cancel THEN &<br /> close(w_progress)<br /> RETURN -1<br />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 Table 33-9 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.
|
1 |
str_func_detail lstr_result<br />ProfileClass lproclass_class<br />ProfileRoutine lprort_routine<br /> <br />// get the name of the called routine<br />// from the calledroutine property of<br />// the ProfileCall object passed to the function<br />lprort_routine = a_pcall.Calledroutine<br />lstr_result.Name = ""<br />lproclass_class = a_pcall.Class<br />IF isValid(lproclass_class) THEN &<br /> lstr_result.Name += lproclass_class.Name + "."<br />lstr_result.name += a_pcall.Name<br /> <br />lstr_result.hits = a_pcall.HitCount<br />lstr_result.selfTime = a_pcall. &<br /> AbsoluteSelfTime * timeScale<br />lstr_result.totalTime = a_pcall. &<br /> AbsoluteTotalTime * timeScale<br />lstr_result.percentSelf = a_pcall.PercentSelfTime<br />lstr_result.percentTotal= a_pcall.PercentTotalTime<br />lstr_result.index = al_index<br /> <br />RETURN lstr_result |
Analyzing structure and flow using a trace tree
model
You use the PowerScript functions and PowerBuilder objects
listed in Table 33-10 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:
|
1 |
TraceTree ltct_treemodel<br />ltct_treemodel = CREATE TraceTree<br />ltct_treeModel.SetTraceFileName(is_fileName )<br /> <br />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:
|
1 |
TraceTreeNode ltctn_list[], ltctn_node<br />long ll_index, ll_limit<br />string ls_line <br />str_node lstr_node<br /> <br />ltct_treemodel.EntryList(ltctn_list)<br />ll_limit = UpperBound(ltctn_list)<br />FOR ll_index = 1 to ll_limit <br /> ltctn_node = ltctn_list[ll_index]<br /> of_dumpnode(ltctn_node, lstr_node)<br /> // insert code to handle display of<br /> // the information in the structure here<br /> ...<br />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:
|
1 |
string ls_exit, ls_label, ls_routinename<br />long ll_node_cnt<br />TraceTreeNode ltctn_list[]<br />errorreturn l_err<br /> <br />astr_node.Children = FALSE<br />astr_node.Label = ''<br />IF NOT isvalid(atctn_node) THEN RETURN<br />CHOOSE CASE atctn_node.ActivityType<br /> CASE ActRoutine!<br /> TraceTreeRoutine ltctrt_routin <br /> ltctrt_routine = atctn_node<br /> IF ltctrt_routine.Classname = '' THEN &<br /> ls_routinename = ltctrt_routine.ClassName + "."<br /> END IF <br /> ls_routinename += ltctrt_routine.Name<br /> ltctrt_routine.GetChildrenList(ltctn_list)<br /> ll_node_cnt = UpperBound(ltctn_list)<br /> <br /> ls_label = "Execute " + ls_routinename + ' :' + &<br /> space(ii_offset) + String(l_timescale * &<br /> (ltctrt_routine.ExitTimerValue - &<br /> ltctrt_routine.EnterTimerValue), '0.000000')<br /> astr_node.Children = (ll_node_cnt > 0)<br /> astr_node.Label = ls_label<br /> astr_node.Time = ltctrt_routine.EnterTimerValue<br /> RETURN<br /> CASE ActLine!<br /> TraceTreeLine tctln_treeLine <br /> tctln_treeLine = atctn_node <br /> ls_label = LINEPREFIX + &<br /> String(tctln_treeLine.LineNumber )<br /> astr_node.time = tctln_treeLine.Timervalue<br /> ...<br /> // CASE statements omitted<br /> ...<br /> CASE ELSE<br /> ls_label = "INVALID NODE"<br /> END CHOOSE<br /> <br /> astr_node.label = ls_label<br /> RETURN |
Accessing trace data directly
You use the PowerScript functions and PowerBuilder objects
listed in Table 33-11 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.
|
1 |
string ls_fileName<br />TraceFile ltcf_file<br />TraceActivityNode ltcan_node<br />string ls_line<br /> <br />ls_fileName = sle_filename.Text<br />ltcf_file = CREATE TraceFile<br />ltcf_file.Open(ls_fileName)<br />ls_line = "CollectionTime = " + &<br /> String(Truncate(ltcf_file.CollectionTime, 6)) &<br /> + "~r~n" + "Number of Activities = " + &<br /> String(ltcf_file.NumberOfActivities) + "~r~n" + &<br /> "Time Stamp " + "Activity" + "~r~n"<br /> <br />mle_output.text = ls_line<br /> <br />ltcan_node = ltcf_file.NextActivity()<br />DO WHILE IsValid(ltcan_node)<br /> ls_line += of_dumpActivityNode(ltcan_node)<br /> ltcan_node = ltcf_file.NextActivity()<br />LOOP<br /> <br />mle_output.text = ls_line<br />ltcf_file.Close() |
The following code shows part of of_dumpActivityNode:
|
1 |
string lstr_result<br /> <br />lstr_result = String(Truncate(atcan_node. &<br /> TimerValue, 6)) + " "<br />CHOOSE CASE atcan_node.ActivityType<br /> CASE ActRoutine!<br /> TraceRoutine ltcrt_routine<br /> ltcrt_routine = atcan_node<br /> IF ltcrt_routine.IsEvent THEN<br /> lstr_result += "Event: "<br /> ELSE<br /> lstr_result += "Function: "<br /> END IF<br /> lstr_result += ltcrt_routine.ClassName + "." + &<br /> ltcrt_routine.name + "(" + &<br /> ltcrt_routine.LibraryName + ") " &<br /> + String(ltcrt_routine.ObjectId) + "~r~n"<br /> CASE ActLine!<br /> TraceLine ltcln_line<br /> ltcln_line = atcan_node<br /> lstr_result += "Line: " + &<br /> String(ltcln_line.LineNumber) + "~r~n"<br /> CASE ActESQL! <br /> TraceESQL ltcsql_esql<br /> ltcsql_esql = atcan_node<br /> lstr_result += "ESQL: " + ltcsql_esql.Name &<br /> + "~r~n"<br /> <br /> // CASE statements and code omitted<br /> ...<br /> CASE ActBegin!<br /> IF atcan_node.Category = TraceIn! THEN<br /> lstr_result += "Begin Tracing~r~n"<br /> ELSE<br /> lstr_result += "End Tracing~r~n"<br /> END IF<br /> CASE ActGarbageCollect!<br /> lstr_result += "Garbage Collection~r~n"<br /> CASE else<br /> lstr_result += "Unknown Activity~r~n"<br />END CHOOSE<br /> <br />RETURN lstr_result |