Tracing and profiling an application
You use tracing and profiling to debug and tune an application.
When you run an application, you can generate an execution trace file.
You use the trace file to create a profile of
your application.
The profile shows you which functions and events were called
by which other functions and events, how often they were called,
when garbage collection occurred, when objects were created and
destroyed, and how long each activity took to complete. This information
will help you find errors in the application’s logic and
identify areas that you should rewrite to improve performance.
PBDebug tracing You can also generate a simple text trace file without timer
values by checking Enable PBDebug Tracing in the System Options
dialog box.
For more about PBDebug, see “Generating a trace file
without timing information”.
When you can trace an application
You can create a trace file when you run an application in
the PowerBuilder environment, and when you run an executable outside PowerBuilder.
For machine-code executable files, the trace file is only generated
if you check the Trace Information checkbox when you build the executable.
When you run an application with tracing turned on, PowerBuilder records
a timer value in a data file every time a specific activity occurs.
You control when logging begins and ends and which activities are
recorded.
Creating profiles
Once you have generated a trace file, you can create several
different profiles or views of the application by extracting different
types of information from the trace file.
On Windows, PowerBuilder provides three profiling tools that
create profiles (views) of the application for you, but you can
also create your own analysis tools.
Profiler sample application The profiling tools are based on the Profiler sample application.
You can download the application from the PowerBuilder sample applications
web page, which is accessible from the PowerBuilder Help menu.
Using profiling to tune an application
Examining these views tells you where the application is spending
the most time. You can also find routines that are being called
too often or that are being called from classes or routines that
you did not expect to call. You may find routines that are not being
called at all. Follow these suggestions for tuning an application:
- The database connection process is often slow. Although
you may not be able to speed this up, you may be able to enhance
the user’s perception of performance by moving the database
connection process to a different place in your application. - Use profiling to tune algorithms. Algorithmic fixes
will yield greater performance enhancements than changing single
lines of code. - Optimizing an inefficient function is not as effective
as removing unneeded calls to that function. - Focus on optimizing the routines that are called
most often. - If you cannot speed up a routine, consider adding
some user feedback, such as updating MicroHelp or displaying a progress
bar.
Collecting trace information
There are three ways to collect trace information. You can
use:
- The Profiling tab on the System Options dialog box
- A window similar to the Profiling tab
- Trace objects and functions
Use the Profiling tab if you want to trace an entire application
run in the development environment. For more information see “Tracing an entire application
in PowerBuilder”.
Use a window or trace objects and functions if you want to
create a trace file for selected parts of the application or the
entire application, either in the development environment or when
running an executable file. See “Using a window” and “Collecting trace information
using PowerScript functions”.
Collection time The timer values in the trace file exclude the time taken
to collect the trace data. 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 minimize idle time. Percentages are less meaningful when you
create a trace file for a complete application.
Whichever method you use, you can specify:
- The name and location
of the trace file and optional labels for blocks of trace data - The kind of timer used in the trace file
- The activities you want recorded in the trace file
Trace file names and labels
The default name of the trace file is the name of the application
with the extension PBP. The trace file is saved in the directory
where the PBL or executable file resides and overwrites any existing
file of the same name. If you run several different tests on the
same application, you will want to change the trace file name for
each test.
You can also associate a label with the trace data. If you
are tracing several different parts of an application in a single
test run, you can associate a different label with the trace data
for each part, called a trace block.
Timer kinds
There are three kinds of timer: clock, process, and thread.
If your analysis does not require timing information, you can omit
timing information from the trace file to improve performance.
On Windows If you don’t specify a timer kind, the time at which
each activity begins and ends is recorded using the clock timer,
which measures an absolute time with reference to an external activity,
such as the machine’s startup time. The clock timer measures
time in microseconds. Depending on the speed of your machine’s
central processing unit, the clock timer can offer a resolution
of less than one microsecond. A timer’s resolution is the
smallest unit of time the timer can measure.
You can also use process or thread timers, which measure time
in microseconds with reference to when the process or thread being
executed started. You should always use the thread timer for distributed
applications. Both process and thread timers exclude the time taken
by any other running processes or threads so that they give you
a more accurate measurement of how long the process or thread is
taking to execute, but both have a lower resolution than the clock
timer.
On UNIX Specifying a different timer kind has no effect on UNIX. Times
are always recorded using the thread timer.
Trace activities
You can choose to record in the trace file the time at which
any of the following activities occurs. If you’re using
the System Options dialog box or a window, you select the checkboxes
for the activities you want. If you are using PowerScript functions
to collect trace information, you use the TraceActivity enumerated
type to identify the activity.
| Trace Activities checkbox | What is recorded | TraceActivity value |
|---|---|---|
| Routine Entry/Exit | Routine entry or exit | ActRoutine! |
| Routine Line Hits | Execution of any line in any routine | ActLine! |
| Embedded SQL | Use of an embedded SQL verb | ActESQL! |
| Object Creation/ Destruction |
Object creation or destruction | ActObjectCreate!, ActObjectDestroy! |
| User Defined Activities | A user-defined activity that records an informational message |
ActUser! |
| System Errors | A system error or warning | ActError! |
| Garbage Collection | Garbage collection | ActGarbageCollect! |
| Not available | Routine entry and exit, embedded SQL verbs, object creation and destruction, and garbage collection |
ActProfile! |
| Not available | All except ActLine! | ActTrace! |
When you begin and end tracing, an activity of type ActBegin!
is automatically recorded in the trace file. User-defined activities,
which you use to log informational messages to the trace file, are
the only trace activities enabled by default.
Tracing an entire applicationin PowerBuilder
Use the Profiling tab on the System Options dialog box if
you want to collect trace data for an entire application run in
the PowerBuilder development environment.
To trace an entire application in PowerBuilder:
-
Select Window>System Options from
the PowerBar and select the Profiling tab.
-
Select the trace options you want and click OK.
When you run the application, the activities you selected
are logged in the trace file.
Using a window
The PBL provided with the Profiler sample application includes
a window that is similar to the Profiling tab on the System Options
dialog box. The Profiler sample application is available on the
PowerBuilder sample applications web page, which is accessible from
the PowerBuilder Help menu.
The Start button on the window opens a trace file, enables
the trace activities you requested, and starts tracing. The Stop
button stops tracing and closes the trace file. The View Output
button opens the Profiler.
If you add this window to your application, you can easily
trace specific parts of the application as you develop it. If you
want to, you can include it in a deployed application so that users
can generate a trace file.
To use the w_starttrace window in an
application:
-
In the Library painter, copy w_starttrace
from the sample PROFILE.PBL to your application PBL. -
Add a script that opens the w_starttrace
window.For example, you could add a command button to the application’s
main window and code open(w_starttrace) in
the button’s Clicked event.
Collecting trace informationusing PowerScript functions
You use the following PowerScript system functions to collect
information in a trace file. Each of these functions returns a value
of type ErrorReturn, an enumerated data type.
| Use this PowerScript function | To do this |
|---|---|
| TraceOpen | Open a named trace file and set the timer kind |
| TraceEnableActivity | Enable logging of the specified activity |
| TraceBegin | Start logging all enabled activities. You can pass an optional label for the trace block |
| TraceError | Log a severity level and error message to the trace file |
| TraceUser | Log a reference number and informational message to the trace file |
| TraceEnd | Stop logging all enabled activities |
| TraceDisableActivity | Disable logging of the specified activity |
| TraceClose | Close the open trace file |
In general, you call the functions in the order shown in the
table. That is, you must call TraceOpen before you call any other
trace functions. You call TraceClose when you have finished tracing.
TraceEnableActivity and TraceDisableActivity can only be called
when a trace file is open but tracing has not begun or has stopped–that
is, before you call TraceBegin or after you call TraceEnd.
TraceUser and TraceError can only be called when the trace
file is open and tracing is active–that is, after you call
TraceBegin and before you call TraceEnd.
About TraceUser and TraceError You can use TraceUser to record specific events in the trace
file, such as the beginning and end of a body of code. You can also
record the execution of a statement you never expected to reach,
such as the DEFAULT statement in a CASE statement. TraceError works
just like TraceUser, but you can use it to signal more severe problems.
Both TraceUser and TraceError take a number and text string
as arguments. You can use a simple text string that states what
activity occurred, or you can build a string that provides more
diagnostic information by including some context, such as the current
values of variables. Run the application with only ActUser! or ActError!
tracing turned on and then use the Profiling Trace View to pinpoint
problems quickly.
For detailed information about these functions,
see the PowerScript Reference
.
Example: trace data collection In this example, the user selects a timer kind from a dropdown
listbox and enters a name for the trace file in a single-line edit box.
The example only uses the ErrorReturn return value from the TraceOpen call
to return an error message if the call fails, but typically you
would do this for every trace call.
Several trace activities are disabled for a second trace block.
The activities that are not
specifically disabled
remain enabled until TraceClose is called.
|
1 |
ErrorReturn le_err<br />integer li_key<br />TimerKind ltk_kind<br /><br />CHOOSE CASE ddlb_timerkind.Text<br /> CASE "None"<br /> ltk_kind = TimerNone!<br /> CASE "Clock"<br /> ltk_kind = Clock!<br /> CASE "Process"<br /> ltk_kind = Process!<br /> CASE "Thread"<br /> ltk_kind = Thread!<br />END CHOOSE<br /><br />// Open the trace file and return an error message<br />// if the open fails<br />le_err = <i>TraceOpen</i> ( sle_fileName.Text, ltk_kind )<br />IF le_err <> Success! THEN &<br /> of_errmsg(le_err,'TraceOpen failed')<br /> RETURN<br />END IF<br /><br />// Enable trace activities. Enabling ActLine!<br />// enables ActRoutine! implicitly<br />TraceEnableActivity(ActESQL!)<br />TraceEnableActivity(ActUser!)<br />TraceEnableActivity(ActError!)<br />TraceEnableActivity(ActLine!)<br />TraceEnableActivity(ActObjectCreate!)<br />TraceEnableActivity(ActObjectDestroy!)<br />TraceEnableActivity(ActGarbageCollect!)<br /><br /><i>TraceBegin</i> ("Trace_block_1")<br />// first block of code to be traced<br />// this block has the label Trace_block_1<br />...<i><br /><br />TraceEnd</i> ()<br /><br />// disable trace activities not needed for<br />// second block<br />TraceDisableActivity(ActLine! )<br />TraceDisableActivity(ActObjectCreate!)<br />TraceDisableActivity(ActObjectDestroy!)<br />TraceDisableActivity(ActGarbageCollect!)<br /><br /><i>TraceBegin</i> ("Trace_block_2")<br />// second block of code to be traced<br />...<i><br /><br />TraceEnd</i> ()<br /><i>TraceClose</i> () |
Analyzing trace information using profiling tools
Once you’ve 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:
- Profiling
Class View shows information about the objects that were used in the
application run. - Profiling Routine View shows information about all the routines (functions and events)
that were used in the application run. - 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. The Profiler sample application
is provided on the PowerBuilder sample applications web page so that
you can use it as a model for your own analysis tools.
When you’re 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 events. It displays
statistics only for those objects that were active while tracing
was enabled. The Class view has three tabs:
- Numbers Statistics only
- Graph Statistics in a bar graph
- Source Statistics along with 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 (including both PowerBuilder objects and user objects). As
you expand the TreeView control, each node is a routine and subnodes
represent called routines.
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 There are five metrics displayed in the Class view (accessed
from instances of the ProfileCall and ProfileRoutine objects). Times are
displayed using the time scale specified in the Preferences dialog
box:
| 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 along with detailed statistics - Calling routines The bottom DataWindow lists functions and events that call
the routine displayed in the middle DataWindow
The Routine view uses the call graph model to show the call
chain along with cumulative statistics for routines and called routines.
The Routine view has two tabs:
- Detail Statistics only
- Source Statistics along with source code for those routines that originated
in PowerScript source
You can control 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 There are nine metrics displayed in Routine view (the profiling
tool accesses them from instances of the ProfileCall and ProfileRoutine
objects). Times are displayed using the time scale specified in the
Preferences dialog box:
| 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 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.
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 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
Trace view metrics There are two metrics displayed in Trace view (the profiling
tool accesses them 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 entryThis 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 MessageBox 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. Check the
Aggregate Calls 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 the box is not checked, 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
will see one entry with five hits; with no aggregation, you’ll
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.
Analyzing trace informationprogrammatically
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
You use the following PowerScript functions and PowerBuilder objects
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
data type 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.
For more information about these functions
and objects, see the PowerScript Reference
and Objects
and Controls
.
Using the BuildModel function
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.
For a more complete version of the example,
see the Profiler sample application.
|
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
Once you’ve built a call graph model of the application,
you can extract detailed information from it.
For routines and lines, you can extract the following timing
information 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: 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.
For more detailed examples of this and similar
functions, see the Profiler sample application.
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 |
Building a trace tree model
You use the following PowerScript functions and PowerBuilder objects
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 EntryList and GetChildrenList 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 |
For more information about these functions
and objects, see the PowerScript Reference
and Objects
and Controls
.
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”.
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 data type, 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. (For a more
detailed example, see the Profiler sample application.)
|
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. Here’s 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 following PowerScript functions and PowerBuilder objects
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 more information about these functions
and objects, see the PowerScript Reference
and Objects
and Controls
. 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 data type, 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() |
Here’s 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 |
Generating a trace filewithout timing information
If you want to generate an activity log with no timing information
in a text file, you can turn on PBDebug tracing in the System Options
dialog box. The PBDebug trace file contains a log showing which
object functions and instructions and system DLL functions were
executed in chronological order.
To generate a simple trace file:
-
Select Window>System Options and
check the Enable PBDebug Tracing checkbox. -
(Optional) Specify a pathname for the PBDebug
output file. - Restart PowerBuilder and run your application
If you don’t specify an output file path, PowerBuilder creates
an output file in the same directory as the PowerBuilder executable
file. The output file has the same name as the PowerBuilder executable
with the extension DBG. If you don’t have write permission
to this directory, you must specify a value for the output file
path.
Managing trace files
Each time you run your application
with
PBDebug on, PowerBuilder appends the new trace output to the same
trace file. A long session with PBDebug turned on can produce a
large trace file, so you must ensure you have adequate disk space.
Each time the PowerBuilder development environment
is started
with PBDebug on, the trace file is overwritten.
If you want to save the data in the existing trace file, rename
the output file between sessions.
Turning PBDebug off Running your application with PBDebug on will slow down execution.
Be sure to clear the Enable PBDebug Tracing checkbox on the System
Options dialog box if you don’t need this trace information.
For information on creating the same kind
of diagnostic trace file when you run your compiled application
outside PowerBuilder, see “Tracing execution”.