Profiling with fb's profiler
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
`