Help Center
/
Help Center›FreeBASIC›Tutorials

Profiling with fb's profiler

Documentation

Profiling can be used to analyze the performance of an application.

Since fbc 1.20.0, FreeBASIC can use fb's profiler for analyzing the execution of an application. The profiler information is collected while the program is running.
This profiling feature may give an easy to use tool to help novice and experienced users analyze their programs.

Some of the capabilities of this profiler implemented through fb:
- easy to use,
- no extra tools needed,
- can profile (analyze) calls to external libraries.

This profiling feature may give an easy to use tool to help novice and experienced users analyze their programs.

The three basic steps to profiling a program are:
- Prepare the program for profiling by passing the the appropriate -profgen ... option to the FreeBASIC compiler or compile the source with appropriate '-profgen ...' #Cmdline option.
- Run the program to build the profiling report stored by default in <filename[.exe]>.prf (where <filename[.exe]> is the name of the executable).
- Analyze directly the profiling report (text file).

The fb's profiler offers two types of profiling:
1. Function call profiling
2. Cycle count profiling (currently a work in progress on -gen gas64 only)

1. Function Call Profiling (with fb's profiler)


The performance of an application might be measured by how many times functions are called, how much time is spent executing those functions, and which functions are calling other functions.
This can help to identify functions that might be taking too long to execute or executed too many times and that might be worth reviewing for optimization.

This feature is a reimplentation of Angelo Mottola's (lillo's) profiler from 2008, rewritten to fix some issues, and then some new features added on. This latest side quest started due to a desire to run some kind of profiling on the fbc compiler itself, and having no luck at all with gprof on windows. Years ago lillo's function call profiler was removed in favor of gmon/gprof.

This tool is not suitable for high resolution timing profiling. However, it helps identify potential problem areas in a program, or gives a better understanding of procedures called as starting point for investigations.

FreeBASIC supports function profiling; not basic-block or line-by-line profiling.

1.1 Preparing a Program for Profiling (with function call fb's profiler)
Only code that is compiled with the -profgen fb command line option can be so profiled.
Pass the -profgen fb option to the FreeBASIC compiler to prepare the program to be profiled or compile the source with '-profgen fb' #Cmdline option:
fbc program.bas -profgen fb
' or
#cmdline "-profgen fb"
This will tell the compiler to insert special startup code at the beginning of the application as well as at the beginning of each function.

1.2 Profiling (with function call fb's profiler) the Program
The information needed to analyze execution of the program is gathered while the program is running.
Run the program to begin collecting the function call information.
The profiling report is automatically stored in a file named by default <filename[.exe]>.prf in the same directory as the program.

1.3 Analyzing the Profiling Report (from function call fb's profiler)
After compiling and running the program, the user can open the default named profiling report <filename[.exe]>.prf (text file).

There are two sections:
- per function results - profile of individual procedures and the procedures called
- global results - profile of all procedures with respect to the whole program run time

Function: the parent function / child function profiled. Parents are on the left, children are indented
Count: number of times the procedure was called
Time: number of seconds executing the procedure
Total%: the percentage of execution time versus the whole run time
Proc%: the percentage of execution time versus the procedure run time

Times are based on fb's built-in TIMER function.

In case of multi-threading, each thread has a separate instance of the profiler storing its data in thread-local storage.
The final profiling report groups together one after the other the elementary profiling reports of each thread (including firstly that of the main thread). There is no inter-thread grouping.

    • Simple example:
#cmdline "-profgen fb"



Sub Pause_100

    Sleep 100, 1

End Sub



Sub Pause_200

    Sleep 200, 1

End Sub



Sub Pause_400

    Sleep 400, 1

End Sub



For i As Integer = 1 To 3

    Pause_100

Next i



Pause_200



Pause_400

Example of profiling report:
' .....

' 

' 

'   Per function results:

'   

'           Function:         Count:       Time:    Total%:    Proc%:

'   

'   (main)                         1     0.92307    100.00%

'   

'           PAUSE_400              1     0.40091     43.43%    43.43%

'           PAUSE_100              3     0.32153     34.83%    34.83%

'           PAUSE_200              1     0.20060     21.73%    21.73%

'           FB___MAIN              1     0.00000      0.00%     0.00%

'   

'   PAUSE_100                      3     0.32153     34.83%

'   

'           SLEEP                  3     0.32152     34.83%   100.00%

'   

'   PAUSE_200                      1     0.20060     21.73%

'   

'           SLEEP                  1     0.20059     21.73%   100.00%

'   

'   PAUSE_400                      1     0.40091     43.43%

'   

'           SLEEP                  1     0.40086     43.43%    99.99%

'   

'   

'   

'   Global results:

'   

'   (main)                         1     0.92307    100.00%

'   FB___MAIN                      1     0.00000      0.00%

'   PAUSE_100                      3     0.32153     34.83%

'   PAUSE_200                      1     0.20060     21.73%

'   PAUSE_400                      1     0.40091     43.43%

'   SLEEP                          5     0.92297     99.99%

1.4 Advanced Profiling Features (with function call fb's profiler)
The following features allow the user to control the information collected by the profiler as well as modify the profiling report, compared to the default operating.

1.4.1 Advanced procedures in the ./inc/fbc-int/profile.bi include file
The ./inc/fbc-int/profile.bi include file allows user to access some advanced procedures (declared inside Namespace: FBC) for working with the fb's profiler.
These procedures expose fb's profiler as an API that can then be called directly and used to generate a profiling report based on whatever structure of call recording is made by the user:
- To set the output report file name at run-time:
function ProfileSetFileName ( byval filename as const zstring ptr ) as long
- To set/get options for the profiler:
function ProfileSetOptions ( byval options as PROFILE_OPTIONS ) as PROFILE_OPTIONS
function ProfileGetOptions ( ) as PROFILE_OPTIONS
both associated with the PROFILE_OPTIONS Enum structure (see ./inc/fbc-int/profile.bi include file)
- To ignore a procedure when profiling:
sub ProfileIgnore ( byval procedurename as zstring ptr )
- To call fb's profiler directly to perform custom profiling and a report:
Examples of procedures:
sub ProfileInit () '' Initialize the profiler
function ProfileEnd ( byval errorcode as long ) as long '' Generate the profiling report and terminate the profiler
function ProfileBeginCall ( byval procedurename as const zstring ptr ) as any ptr '' Begin a call and return a caller_id pointer
sub ProfileEndCall ( byval procctx as any ptr ) '' End a call

      • Example for setting the profiling report file name at run-time:
#cmdline "-profgen fb"

#include Once "fbc-int/profile.bi"

Using FBC



'' automatically change the profile report name

Dim t As String = Time

Dim n As String = Left(t, 2) & Mid(t, 4, 2) & Right(t, 2)

ProfileSetFileName( "prof-" & n & ".txt" )

      • Example for telling the profiler to generate a call tree instead of timings and counts:
#cmdline "-profgen fb" 

#include Once "fbc-int/profile.bi"

Using FBC



ProfileSetOptions( PROFILE_OPTION_REPORT_CALLTREE ) 



Sub A

    Print "A"

End Sub



Sub B

    Print "B"

End Sub



Sub C

    Print "C"

End Sub



Sub D

    Print "D"

    A

    A

    B

    B

    C

    C

End Sub



D

Example of profiling report:
'	.....
'	
'	
'	Call Tree:
'	
'	\- (main)
'	   |- D
'	   |  |- A
'	   |  |  |- FB_PRINTSTRING
'	   |  |  \- FB_STRALLOCTEMPDESCZEX
'	   |  |- B
'	   |  |  |- FB_PRINTSTRING
'	   |  |  \- FB_STRALLOCTEMPDESCZEX
'	   |  |- C
'	   |  |  |- FB_PRINTSTRING
'	   |  |  \- FB_STRALLOCTEMPDESCZEX
'	   |  |- FB_PRINTSTRING
'	   |  \- FB_STRALLOCTEMPDESCZEX
'	   |- FB___MAIN
'	   \- PROFILESETOPTIONS
      • Example for calling fb's profiler directly to perform custom profiling and a report:
#include Once "fbc-int/profile.bi"

Using FBC



#if __FB_PROFILE__ = PROFILE_OPTION_REPORT_CALLS

#error Do Not compile With -profgen fb

#endif



ProfileInit()



Var ctx = ProfileBeginCall( @"Begin" )



Scope

    Var ctx = ProfileBeginCall( @"Step 1" )

        Sleep 100, 1

    ProfileEndCall( ctx )

End Scope



Scope

    Var ctx = ProfileBeginCall( @"Step 2" )

        Sleep 200, 1

    ProfileEndCall( ctx )

End Scope



ProfileEndCall( ctx )



ProfileEnd(0)

Example of profiling report:
' .....

' 

' 

' Per function results:

' 

'         Function:         Count:       Time:    Total%:    Proc%:

' 

' (main)                         1     0.30183    100.00%

' 

'         Begin                  1     0.30183    100.00%   100.00%

' 

' Begin                          1     0.30183    100.00%

' 

'         Step 2                 1     0.20057     66.45%    66.45%

'         Step 1                 1     0.10125     33.54%    33.54%

' 

' 

' 

' Global results:

' 

' (main)                         1     0.30183    100.00%

' Begin                          1     0.30183    100.00%

' Step 1                         1     0.10125     33.54%

' Step 2                         1     0.20057     66.45%

1.4.2 Conditional generation of profiling code
The user can also control a conditional generation of profiling code:
#Pragma Profile controls the generation of profiling code.
This allows optionally including or excluding sections of source code to be profiled.

User can optionally disable profiling code generation with #pragma profile = false or #pragma push( profile , false )
Profiling code generation can be reactivated with #pragma profile = true or #pragma pop( profile ) respectively

The __FB_OPTION_PROFILE__ intrinsic define allows to indicate that the profiling code is generated or not:
__FB_OPTION_PROFILE__ is set to non-zero when profiling code is generated
__FB_OPTION_PROFILE__ is set to zero when profiling code is not generated

      • Purely academic example:
#cmdline "-profgen fb"



Print "__FB_OPTION_PROFILE__ = " & __FB_OPTION_PROFILE__



#pragma push( profile , False )

Print "__FB_OPTION_PROFILE__ = " & __FB_OPTION_PROFILE__

Sleep 100, 1

#pragma pop( profile )



Print "__FB_OPTION_PROFILE__ = " & __FB_OPTION_PROFILE__

Example of profiling report:
' .....

' 

' 

' Per function results:

' 

'         Function:                     Count:       Time:    Total%:    Proc%:

' 

' (main)                                     1     0.11714    100.00%

' 

'         FB_PRINTSTRING                     2     0.00517      4.42%     4.42%

'         FB_STRALLOCTEMPDESCZEX             2     0.00001      0.01%     0.01%

'         FB___MAIN                          1     0.00000      0.00%     0.00%

' 

' 

' 

' Global results:

' 

' (main)                                     1     0.11714    100.00%

' FB_PRINTSTRING                             2     0.00517      4.42%

' FB_STRALLOCTEMPDESCZEX                     2     0.00001      0.01%

' FB___MAIN                                  1     0.00000      0.00%

The code profiler only takes into account 2 PRINTs (instead of 3) and not the SLEEP.

2. Cycle Count Profiling (with fb's profiler)


This is currently a work in progress on -gen gas64 only.

Cycle count fb's profiler enables cpu cycle count profiling on some targets.
It uses completely different methods than the function call fb's profiler. It stores data in specially named data sections, so will only work with linkers supporting arbitrarily named sections.
After running an executable compiled with this command, it can generate a basic report of cycle counts.

For each called user procedure body, there are two different counts:
- The profiler sums the CPU cycle counts for all internal code blocks that separate possible calls from any other user procedure or built-in procedure (all other called procedures are therefore excluded from this first count).
- The profiler also counts the total number of CPU cycles when executing the entire user procedure body.

2.1 Preparing a Program for Profiling (with cycle count fb's profiler)
Only code that is compiled with the -profgen cycles command line option can be so profiled.
Pass the -profgen cycles option to the FreeBASIC compiler to prepare the program to be profiled or compile the source with '-profgen cycles' #Cmdline option:
fbc program.bas -profgen cycles
' or
#cmdline "-profgen cycles"

2.2 Profiling (with cycle count fb's profiler) the Program
The information needed to analyze execution of the program is gathered while the program is running.
Run the program to begin collecting the function call information.
The profiling report is automatically stored in a file named by default <filename[.exe]>.prf in the same directory as the program.

2.3 Analyzing the Profiling Report (from cycle count fb's profiler)
After compiling and running the program, the user can open the default named profiling report <filename[.exe]>.prf (text file).

Profile of individual procedures per module:
total: the number of cycles between the end of the procedure and its beginning
inside: the number of cycles really "spent" inside the procedure (procedure calls inside the procedure body are not taken into account)
call count: number of times the procedure was called

    • Simple example:
#cmdline "-gen gas64"

#cmdline "-profgen cycles"



Sub A()

    Dim As Integer I

    For J As Integer = 1 To 1000

        I = I + 1

    Next J

End Sub



Sub B()

    A()

End Sub



Sub C()

    B()

    Print "End"

End Sub



C()

Example of profiling report:
' .....

' 

' 

'   module  function             total             inside         call count

'   

'   *.bas

'   

'           A

'                                 4242               4242                  1

'           B

'                                 4473                 42                  1

'           C

'                               858301                169                  1

'           main

'                                    0                 63                  1