Tracing and Profiling Applications -

About 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 helps 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 generated only if you check the Trace Information check box 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

After 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.

PowerBuilder provides three profiling tools that create profiles (views) of the application for you, but you can also create your own analysis tools.

Using profiling to tune an application

Examining the profiles generated by the profiling tools tells you where the application is spending the most time. You can also find routines that are being called too often, routines being called that you did not expect to call, or routines that are not being called at all. Follow these suggestions for tuning an application:

The database connection process is often slow. Although you might not be able to speed this up, you might 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

Tracing an entire application in PowerBuilder
Using a window
Collecting trace information using PowerScript functions

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 should 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 (the trace block) for each part of the application.

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.

If you do not 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 computer's start-up time. The clock timer measures time in microseconds. Depending on the speed of your computer'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.

Trace activities

You can choose to record in the trace file the time at which any of the following activities occurs. If you are using the System Options dialog box or a window, you select the check boxes 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 check box	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 application in 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 Tools>System Options from the PowerBar and select the Profiling tab.
Specify a name for the trace file, 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

You can create a window that is similar to the Profiling tab on the System Options dialog box and add it to any application that is under development, so that you can start and stop tracing when testing specific actions.

The w_profiler window is available in the PB Code Profiler sample in the PowerBuilder Code Samples at https://www.appeon.com/developers/library/code-samples-for-pb. This sample also shows the code used to create the profiling tools described in Analyzing trace information using profiling tools.

The w_profiler window lets you specify a trace file name, label, and timer kind, as well as which activities you want to trace:

The following instance variables are defined for the window:

TimerKind itk_kind
string is_title = 'Trace Options '
string is_starttext

The open event for the window sets some defaults:

application lapp_current
lapp_current = getapplication()
itk_kind = Clock!
is_starttext = cb_startstop.text
sle_filename.text = classname(lapp_current)+'.pbp'

The following code shows the script for the Clicked event of the Start Trace button. The text for the button is set to Start Trace in the painter. When the user clicks Start Trace, the button label changes to Stop Trace. The Clicked event script checks the text on the button before either starting or stopping tracing. This script uses the functions described in Collecting trace information using PowerScript functions:

// instance variables:
// errorreturn le_errorreturn
integer li_key

// Check that the button label is Start Trace
// and a trace file name has been entered
if this.text = is_starttext then

   if len(trim(sle_filename.text)) = 0 then
       messagebox(parent.title, &
         'Trace file name is required',information!)
       sle_filename.setfocus()
       return
   end if

   // If Prompt for overwrite is checked and the
   // file exists, pop up a response window
   if cbx_prompt.checked and &
      fileexists(sle_filename.text) then
      li_key = messagebox(parent.title, &
         'OK to overwrite '+sle_filename.text, &
         question!,okcancel!,1)
      if li_key = 2 then return
   end if
      
   // Open the trace file
   TraceOpen( sle_filename.text, itk_kind )
   
   // Enable tracing for checked activities
   // For each activity, check for errors and close
   // the trace file if an error occurs
   if cbx_embeddedSQL.checked then 
      le_errorreturn = TraceEnableActivity( ActESQL! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
            'TraceEnableActivity( ActESQL! )')
          le_errorreturn = Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if

   if cbx_routineentry.checked then 
      le_errorreturn =TraceEnableActivity(ActRoutine!)
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
            'TraceEnableActivity( ActRoutine! )')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if

   if cbx_userdefined.checked then 
      le_errorreturn = TraceEnableActivity( ActUser! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
            'TraceEnableActivity( ActUser! )')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if

   if cbx_systemerrors.checked then 
      le_errorreturn = TraceEnableActivity(ActError! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
            'TraceEnableActivity( ActError! )')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if

   if cbx_routineline.checked then 
      le_errorreturn = TraceEnableActivity( ActLine! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
            ' TraceEnableActivity( ActLine! )')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if
   if cbx_objectcreate.checked then 
      le_errorreturn = &
         TraceEnableActivity( ActObjectCreate! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
            'TraceEnableActivity( ActObject! )')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
      le_errorreturn = &
         TraceEnableActivity( ActObjectDestroy! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
           'TraceEnableActivity(ActObjectDestroy!)')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if

   if cbx_garbagecoll.checked then 
      le_errorreturn = &
         TraceEnableActivity( ActGarbageCollect! )
      if le_errorreturn <> Success! then
         of_errmsg(le_errorreturn, &
          'TraceEnableActivity(ActGarbageCollect! )')
         Traceclose()
         if le_errorreturn <> Success! then
            of_errmsg(le_errorreturn,'TraceClose')
         end if
         return
      end if
   end if

   // Start tracing
   le_errorreturn =TraceBegin( sle_tracelabel.text )
   if le_errorreturn <> Success! then
      of_errmsg(le_errorreturn,'TraceBegin')
      return
   end if
   
   // Change the title of the window and the 
   // text of the Start Trace button
   parent.title = is_title + '(Tracing)'
   this.text = 'Stop &Tracing'

// If the button label is Stop Trace, stop tracing
// and close the trace file
else
   le_errorreturn =TraceEnd()
   if le_errorreturn <> Success! then
      of_errmsg(le_errorreturn,'TraceEnd')
      return
   end if

   le_errorreturn =TraceClose()
   if le_errorreturn <> Success! then
      of_errmsg(le_errorreturn,'TraceClose')
   end if
   this.text = is_starttext
   parent.title = is_title 
end if

of_errmsg function

The window uses two functions to handle error messages. The of_errmsg function displays a message box:

// of_errmsg
Messagebox( this.title,'Error executing '+ as_msg + &
   '. Error code : '+ of_converterror(ae_error) )

of_converterror function

The of_converterror function converts the ErrorReturn parameter to a string:

// of_converterror: convert enumerated type 
// ErrorReturn parameter to text.
String ls_result
choose case a_error
   Case Success!
      ls_result =  "Success!"
   Case FileCloseError!
      ls_result =  "FileCloseError!"
   Case FileOpenError!
      ls_result =  "FileOpenError!"
   Case FileReadError!
      ls_result =  "FileReadError!"
   Case FileWriteError!
      ls_result =  "FileWriteError!"
   Case FileNotOpenError!
      ls_result =  "FileNotOpenError!"
   Case FileAlreadyOpenError!
      ls_result =  "FileAlreadyOpenError!"
   Case FileInvalidFormatError!
      ls_result =  "FileInvalidFormatError!"
   Case FileNotSetError!
      ls_result =  "FileNotSetError!"
   Case EventNotExistError!
      ls_result =  "EventNotExistError!"
   Case EventWrongPrototypeError!
      ls_result =  "EventWrongPrototypeError!"
   Case ModelNotExistsError!
      ls_result =  "ModelNotExistsError!"
   Case ModelExistsError!
      ls_result =  "ModelExistsError!"
   Case TraceStartedError!
      ls_result =  "TraceStartedError!"
   Case TraceNotStartedError!
      ls_result =  "TraceNotStartedError!"
   Case TraceNoMoreNodes!
      ls_result =  "TraceNoMoreNodes!"
   Case TraceGeneralError!
      ls_result =  "TraceGeneralError!"
   Case FeatureNotSupportedError!
      ls_result =  "FeatureNotSupportedError!"
   Case else
      ls_result =  "Unknown Error Code"
end choose
return ls_result

Collecting trace information using PowerScript functions

You use the PowerScript system functions listed in the following table to collect information in a trace file. Each of these functions returns a value of type ErrorReturn, an enumerated datatype.

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 be called only 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 be called only 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 CHOOSE CASE block. 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.

Example: trace data collection

In this example, the user selects a timer kind from a drop-down list and enters a name for the trace file in a single-line edit box. Typically you would use the ErrorReturn return value from every trace call to return an error message if the call fails. For brevity, the example shows this only for the TraceOpen call.

Several trace activities are disabled for a second trace block. The activities that are not specifically disabled remain enabled until TraceClose is called.

ErrorReturn le_err
integer li_key
TimerKind ltk_kind

CHOOSE CASE ddlb_timerkind.Text
   CASE "None"
      ltk_kind = TimerNone!
   CASE "Clock"
      ltk_kind = Clock!
   CASE "Process"
      ltk_kind = Process!
   CASE "Thread"
      ltk_kind = Thread!
END CHOOSE

// Open the trace file and return an error message
// if the open fails
le_err = TraceOpen( sle_fileName.Text, ltk_kind )
IF le_err <> Success! THEN &
   of_errmsg(le_err, 'TraceOpen failed')
   RETURN
END IF

// Enable trace activities. Enabling ActLine!
// enables ActRoutine! implicitly
TraceEnableActivity(ActESQL!)
TraceEnableActivity(ActUser!)
TraceEnableActivity(ActError!)
TraceEnableActivity(ActLine!)
TraceEnableActivity(ActObjectCreate!)
TraceEnableActivity(ActObjectDestroy!)
TraceEnableActivity(ActGarbageCollect!)

TraceBegin("Trace_block_1")
// first block of code to be traced
// this block has the label Trace_block_1
…

TraceEnd()

// disable trace activities not needed for
// second block
TraceDisableActivity(ActLine! )
TraceDisableActivity(ActObjectCreate!)
TraceDisableActivity(ActObjectDestroy!)
TraceDisableActivity(ActGarbageCollect!)

TraceBegin("Trace_block_2")
// second block of code to be traced
…

TraceEnd()
TraceClose()

Analyzing trace information using profiling tools

Profiling Class View
Profiling Routine View
Profiling Trace View
Setting call aggregation preferences

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.

Analyzing trace information programmatically

Analyzing performance with a call graph model
Analyzing structure and flow using a trace tree model
Accessing trace data directly

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

Using the BuildModel function to build a call graph model
Extracting information from the 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

Using BuildModel to build a trace tree model
Extracting information from the 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

Using the TraceFile object

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

Generating a trace file without 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 Tools>System Options and check the Enable PBDebug Tracing check box.
Check the Prompt Before OverWriting PBDebug Output File box if you want to retain existing trace output when you run or debug the application.
(Optional) Specify a pathname for the PBDebug output file.
Run your application.

If you do not check the Prompt Before OverWriting PBDebug Output File box, PowerBuilder overwrites the existing trace file every time you run the application or click the Start button in the debugger. If you check the box, it displays a response window. You can choose to overwrite the file, append new trace output to the existing file, or cancel the run or debug session.

If you want to retain the trace file, save it with a different name before running the application, or specify a new file name in the System Options dialog box.

If you do not 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 do not have write permission to this directory, you must specify a value for the output file path.

Turning PBDebug off

Running your application with PBDebug on will slow down execution. Be sure to clear the Enable PBDebug Tracing check box on the System Options dialog box if you do not 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.

Prev	Up	Next
Debugging and Running Applications	Home	Creating Executables and Components

Users GuideRunning Your Application