PROFILE statement

Purpose

Capture a profile report detailing total execution times of the Subs and Functions in a program and write it to a disk file.

Syntax

PROFILE diskfilename$

Remarks

At the time the PROFILE statement is executed, a standard sequential file of the specified file name diskfilename$ is created. For the best results in executable files, the PROFILE statement should be the last statement executed in the PBMAIN/WINMAIN function.

The profile report contains a list of every Sub/Function within the same module (EXE or DLL), the number of times it was called, and the total elapsed time (in milliseconds) spent executing all instances of the procedure. These statistics appear in the disk file in that specific order on each line:

The profile report only describes Subs/Functions that physically reside within the module (EXE or DLL) where the PROFILE statement is located. Subs/Functions in an external EXE or DLL are not profiled individually; however, the time taken to call other Subs/Functions and DLL/API functions is included in the accumulated execution time of the calling Sub/Function.

It is highly recommended that you close all other applications when profiling a PowerBASIC application. When an application is being profiled, PowerBASIC must generate a considerable amount of extra code to gather all of the needed information. This extra code is generated whenever a valid PROFILE statement appears in your program, regardless of whether it is actually executed.

For final production code, use the #TOOLS OFF metastatement is used to ensure the highest performance levels.

Interpreting a profile report

The execution time of nested Subs/Functions needs to be understood in order to obtain a clear "picture" of the execution times. For example, consider the following results:

Sub/Func	calls	time
MySubA,	1,	11016
MySubB,	100,	10014

At first glance, these results may suggest a "bottleneck" in MySubA since it took MySubA 11016 milliseconds to execute just one call, whereas the average time for MySubB was only about 100 milliseconds per call (10014 mSec / 100 calls = 100.14 mSec).

However, if MySubB is actually called by MySubA, the results need to be assessed differently. For example, we could say: "MySubB took 10014 milliseconds of the 11016 milliseconds of the time spent in MySubA". Or to put it another way: "Of the 11016 milliseconds MySubA took to execute, 10014 milliseconds of that time was spent executing MySubB".

Interpolating these results, it can be easily calculated that the code in MySubA only took 1002 milliseconds to run, yet this blossomed to 11016 milliseconds because of its dependence on MySubB.

Therefore, improving the performance of MySubB would clearly improve the overall speed of MySubA, and the profile results of both functions would be improved accordingly.

Restrictions

Profiling is "enabled" when the first Sub/Function that contains a PROFILE statement begins execution. All Subs/Functions subsequently executed from within that Sub/Function are profiled.

It is not possible to profile the actual PBMAIN or WINMAIN functions. If a PROFILE statement occurs within PBMAIN/WINMAIN, all Subs/Functions that are called from PBMAIN/LIBMAIN are profiled normally.

Therefore, if PBMAIN/WINMAIN contains code that requires profiling, simply rename the function and create a new PBMAIN/WINMAIN function that immediately calls the renamed function and then executes a PROFILE statement. See the example below.

For application code with nested and lengthy Sub/Function calls, adding up the total number of milliseconds in the last column of a PROFILE disk file will usually produce a number that is far larger than the actual time it took your program to execute.

The time resolution of the profile report is limited by the Quantum supported by the operating system (Win95/98 is 54 mSec, and WinNT/2000/XP is 10 mSec), and can be influenced by any other applications which run concurrently. Nonetheless, PROFILE can offer a great insight as to which code may be consuming the most CPU time, and where optimization efforts should be concentrated.