Introduction

BuildProfessional contains an upgraded Trace feature to that can be used to examine how logic statements are exercised in BuildProfessional.

Besides including details about the logic steps exercised, XTrace includes the the command name, processing time and logic line number. The XTrace output is marked up and can be read as XML.

Example XTrace Output:

<Function Name="myFunction" Command="ASSIGN" Line="20" Time="1">L-StartTime = *UTC</Function>
<Function Name="myFunction" Command="XML" Line="23" Time="22">XML *TRANSFRM *SUBSET= "data" "mystyle.xsl" "output.xml"</Function>
 

Note. This functionality is in Beta and is currently only available as an INTERNAL command. Please provide feedback. Requires latest xdev.

Starting and Stopping Xtrace
 

Syntax

NOTE Turn on XTrace
INTERNAL 250 outputfileref "False"

NOTE Turn off XTrace
INTERNAL 251

Where:

outputfileref is the file to write XTrace information.

"False" is a required argument.

Description

Logs commands executed to a log file including command name and processing time. Use XTrace log files for debugging and code review purposes.

Operation Summary

*ON. Turn on XTrace and starts logging XTrace information to the nominated file.

*OFF. Turn off XTrace and closes the log file.

Example:

IF 1 *OFF THEN
MESSAGE 0000 "XTrace is now on."
L-xmlFile = *ENV("LogPath") "/xtracelog_" *TRIM(*APPN) ".xml"
INTERNAL 250 L-xmlFile "False"
ON 1
ELSE
INTERNAL 251
MESSAGE 0000 "XTrace is now off."
OFF 1
ENDIF

Store the above example as "commonXTrace" to toggle XTrace on and off. Add a link to this function from your About pulldown menu (or other menu commonly used on all screens). Add an accelerator (Ctrl-T?) pointing to F-commonXTrace. Then simply press Ctrl-T to toggle XTrace on or off.

Viewing the Results

Viewing the Results in Internet Explorer

Change to valid XML format. By adding a <bpxml> the beginning of the file and </bpxml> at the end the XTrace file becomes valid XML.

Viewing Results in xdev

The Developer has a built-in XTrace file viewer (View / Debug, XTrace Tab) that produces some useful analysis information. This viewer produces the information by transforming a window of the XTrace file (for example lines 4,000 - 6,000 out of a 100,000 line file) into TreeViews and ListViews.

• Logic Used (Total). Lists the functions used in the XTrace file. For each function it displays the total processing time, number of VISIT's and number of steps executed. Note. A function with five lines visited 100 times will not always display as 500 steps. Conditional statements will affect the total step count.
   
• Logic Used (Function). Displays the function and notes the number of steps executed per line. This view shows how conditional arguments may have effected the processing of a function.
   
• Commands Used (Total). Displays all the commands used (i.e. IF, FILE, XML etc), their total processing time and number of executions. Expanding the view will show the functions where the command was used.
   
• Logic Sequence. Displays the sequence in which functions were executed.

Note. In all the above, the data only represents the window (lines) that were selected. Expand the number of lines to get an overall view. Expanding the window will increase the processing time per view. 2,000 - 5,000 lines provides reasonable performance.

Build Your Own

If you truly want to dig into how logic is executed in your application, you will need to use your favorite text editor or commands to post process the XTrace file. As each application is unique, you will know what you want to examine and how to find it. You can for example extract irrelevant lines (by function name or command name) to decrease the XTrace file size.

Evaluating the Results

What do the results mean? While the processing time is the first to review, the flow of the code is one of the most important results of XTrace. It is easy to find the individual statements that take the longest time, but frequently used statements of complete functions might be easier and more important to address.

The Developer XTrace Debug View provides the following values:

• Time. This is the total time in a function including time it took to visit sub functions. A simple function at the top of the stack will be displayed using most time.
   
• Local Time. This is the time to process statements in the local function not including visits. This is important to find the functions that use the most processing time.
   
• Visits. Number of visits is important to determine commonly used functions. While a function might be simple, if it gets visited frequently, it is worth reviewing.
   
• Steps. Besides the functions with the highest local time, functions with the most steps are important to review.

Finally, XTrace can help determine functionality that should be centralised or packaged in a generic function.

Problems and Issues

XTrace files can be VERY big. It is important to turn XTrace on just prior to the code that needs to be analysed. Strip out lines that from the XTrace file that are not relevant.

The processing time reported is in milliseconds. Since most systems cannot easily calculate times less than 10-20 milliseconds, most logic lines report zero processing time. While an individual step might be take "zero" time, that same step run 10,000 times will take more than "zero". Consider these options:

• Evaluate number of steps executed as well as processing time.
   
• It is also possible to replace all Time="0" with Time="1" (each step takes at least one millisecond) and reopen the XTrace file. This will however distort the total values.
   
• Running XTrace on a slower system will provide better emphasis on slow areas of code. Or load your system with a CPU intensive task while running XTrace.