Using the DataBasic Profiler

The DataBasic Profiler is a host utility that allows you to:

• Capture and display the DataBasic call stack for any process.

• List changes to the DataBasic call stack, with details of the time taken to make each subroutine call.

• Capture a profile of a DataBasic application running on any Reality process, with timings of how long each cataloged subroutine is taking and caller information. If required, profiles can be captured in a graphical format that can be viewed with a third party graphics tool.

This makes it possible to find out where most time and system resources are spent within a DataBasic application, so that you can target your efforts to improve efficiency. You can also diagnose problems with particular ports.

Syntax

realprof -g {-s} {-C} processId

realprof -t {[ -a || -r ]} {-n} {-s} {-C} processId

realprof -e{i} {-s} {-C} processId

realprof -c {-G graphicsFile} processId > captureFile

realprof -p captureFile -G graphicsFile

realprof -o processId

Parameters

processId The host process id of the reality process to be profiled. This can be obtained by running the WHERE command from TCL.

captureFile The name of a host file in which to capture a profile in text format. The output is a tab-separated list that can be displayed in a spreadsheet such as Microsoft Excel.

graphicsFile The name of a host file in which to capture a profile in graphical format. The output is in GDL (graphical description language) format and can be displayed in any suitable tool, such as VCG (available from http://rw4.cs.uni-sb.de/~sander/html/gsvcg1.html).

Options

-a Specifies that times in seconds from the start of the realprof process should be included in the output.

-C Prefixes each subroutine name with its nesting level (see Nested Programs for an explanation of nesting).

-c Specifies that captured statistics should be copied to stdout. The reality process will no longer be captured.

-e{i} Specifies that the reality process processId should start capturing profile data. This data can subsequently be viewed or saved by calling realprof with the -c option.

The i option specifies that invocation (caller) information should be included in the captured data.

To stop the background process, run realprof with the -o option.

-G Specifies that the next parameter is the name of an output file (see graphicsFile).

-g Specifies that the current state of the DataBasic stack should be displayed. realprof then exits.

-n Indents the output to show the nesting structure of the subroutine calls.

-o Aborts a capture operation started with the -e option.

-p Specifies that a graphics file in GDL format should be generated from the specified capture file. Use the -G option to specify the name of the graphics file.

-r Specifies that the time in seconds between changes to the DataBasic stack should be included in the output.

-s Specifies that calls to Reality service routines should be included in the output.

-t Specifies that changes to the DataBasic stack should be listed. The result is a history of changes to the stack since realprof was started.

Operation

To use realprof, you must run it at the same time as the DataBasic program that you want to profile.

The examples which follow use the process id 2124. To find the id of your reality process, use the WHERE command from TCL, or a host utility such as ps on UNIX or the Task Manager on Windows.

Displaying the Current State of the DataBasic Stack

The simplest way to use realprof is to display the current state of the DataBasic stack. For example, if you are running a program called PTEST on Reality and enter the host command

realprof -g 2124

the following would be a typical result:

PTEST
DIAGONAL
USERINPUT

You can refine this output with the options -s, to include calls to Reality service routines, and -C, prefix each subroutine name with its nesting level. For example:

realprof -g -s -C 2124

produces

000_PTEST
000_DIAGONAL
000_USERINPUT
Port Read

Stack History Display

Knowing the current state of the DataBasic stack is of only limited use. You can learn much more by finding out how the stack is changing with time. To do this, use the -t option. For example, enter

realprof -t 2124

and then run your Reality program. The following is a typical result:

+PTEST
+USERINPUT
-USERINPUT
+LINE
-LINE
+DIAGONAL
+USERINPUT
-USERINPUT
+DISTANCE
-DISTANCE
+LINE
-LINE
-DIAGONAL
+LINE
-LINE
+TL-STATUS
+TL-STATUS
+TL.READERR
-TL.READERR
+TL.READERR
-TL.READERR
+TL.READERR
-TL.READERR
+TL.READERR
-TL.READERR
+TL.READERR
-TL.READERR
+TL.READERR
-TL.READERR
+TL.CHK
-TL.CHK
+TL.CHK
-TL.CHK
+TL.CHK
-TL.CHK
+TL.CHK
-TL.CHK
+TL.PRINTERR
-TL.PRINTERR
-TL-STATUS
-TL-STATUS
+LINE
-LINE
-PTEST

The plus (+) signs show a subroutine call, and the minus (-) signs the return from a subroutine.

To stop displaying the stack, interrupt realprof (with ctrl+c or, on Windows, ctrl+break).

There are various options you can use with -t (see Syntax). For example, the following command indents the output to show the way in which the subroutines are nested and includes the time taken for each step:

$realprof -t -r -n 1236
 2.5136144 +PTEST
 0.0000000  +USERINPUT
 1.6623904  -USERINPUT
 0.0000000  +LINE
10.0043856  -LINE
 0.0000000  +DIAGONAL
 0.0000000    +USERINPUT
 2.0829952    -USERINPUT
 5.0072000    +DISTANCE
 0.0000000    -DISTANCE
10.0144000    +LINE
10.0043856    -LINE
 0.0000000  -DIAGONAL
 0.0000000  +LINE
10.0043856  -LINE
 0.0000000  +TL-STATUS
 0.0000000    +TL-STATUS
 0.0000000      +TL.READERR
 0.0000000      -TL.READERR
 0.0000000      +TL.READERR
 0.0000000      -TL.READERR
 0.0000000      +TL.READERR
 0.0000000      -TL.READERR
 0.0000000      +TL.READERR
 0.0000000      -TL.READERR
 0.0000000      +TL.READERR
 0.0000000      -TL.READERR
 0.0000000      +TL.READERR
 0.0000000      -TL.READERR
 0.0100144      +TL.CHK
 0.0000000      -TL.CHK
 0.0000000      +TL.CHK
 0.0000000      -TL.CHK
 0.0000000      +TL.CHK
 0.0000000      -TL.CHK
 0.0000000      +TL.CHK
 0.0000000      -TL.CHK
 0.0000000      +TL.PRINTERR
 0.0100144      -TL.PRINTERR
 0.0000000    -TL-STATUS
 0.0000000  -TL-STATUS
 0.0100144  +LINE
10.0043856  -LINE
 0.0000000 -PTEST

This can be useful if you have a slow application and want to identify which parts of the program are taking the longest.

In practice, the Stack History Display will produce too much information to display on the screen - you would need to redirect the output to a file. For example:

realprof -t -r -n 2124 > /users/user1/capture.txt

Capturing a Profile of a DataBasic Program

The -e option instructs the reality process you specify to start capturing profile data. When you have the information you require, you can use the -c option to end the capture operation and save the results to a file. For example, enter:

realprof -e 2124

Then run your Reality program, followed by

realprof -c 2124 > /users/user1/capture.txt

at the host prompt.

realprof -o 2124

The result is a text file containing tab-separated data that can be imported into a spreadsheet or any other program that can display tabular data. The following is a typical result:

The different columns contain the following:

Type/Operation The name of the subroutine, program or Reality service routine call, prefixed by a letter that indicates the type of operation, as follows:

C Subroutine call.

E DataBasic ENTER statement.

H DataBasic CHAIN statement

R Run program.

P PERFORM.

S Reality service routine call (these are only included if the -s option was used).

Count The number of times the operation was invoked.

Time In The total time spent on this operation, including time spent in operations invoked from this operation.

Time Elapsed The total time spent on this operation, excluding time spent in operations invoked from this operation. If this operation did not invoke any other operations, this will be the same as Time In.

Called By The name of the operation that invoked this operation. This column is blank unless the i option was specified. With the i option, there will be one column for each operation that invoked this operation.

Unlike the Stack History Display, this produces a profile, that is, a summary the information, rather than details of all the individual subroutine calls. For example, the table above shows that PTEST called a number of subroutines: LINE four times, DISTANCE once, USERINPUT once, etc. It also ran the program TL-STATUS. The command took 57.853189 seconds to run and the most time (40.017542 seconds) was spent in LINE.

The i option specifies that subroutine invocation (caller) information should be included in the captured data. Repeating the previous command but with both the e and the i options produces:

Notice that the timings are different to those in the previous example. The time spent in subroutines and between subroutine calls will depend on the host workload at the time the profile was captured. In general, you should disregard times less than 0.01s.

Displaying a Profile in Graphical Format

The tabular format shown in the previous section can provide useful information if looking for specific problems. However, for complex programs, this can be difficult to interpret. The data can be much easier to understand if presented in graphical form.

The -G option allows you to save the captured data in GDL (graphical description language) format. This can be done in two ways:

• When you save your captured profile, use the -G option to specify a graphics file. For example:

realprof -c -G capture.gdl 2124 > capture.txt

• Convert a saved profile to graphical format. To do this, use the -p option to specify the file containing your save profile and -G to specify a graphics file. For example:

realprof -p capture.txt -G capture.gdl

Once saved in graphical format, the profile can be displayed in any tool that recognises GDL (graphical description language). The example below was created from the profile generated in the previous example and displayed in the VCG utility (available from http://rw4.cs.uni-sb.de/~sander/html/gsvcg1.html).