Profiling freebasic programs

[coderJeff]

Conditional generation of profiling code

#pragma profile [=value]' or '#pragma push( profile [,value] )'

"#pragma profile" controls the generation of profiling code. This allows optionally including or excluding sections of source code to be profiled.
when #pragma profile = true, then profiling code is generated
when #pragma profile = false, then profiling code is not generated

__FB_OPTION_PROFILE__ is set to non-zero when #pragma profile = true
__FB_OPTION_PROFILE__ is set to zero when #pragma profile = false

I don't have an example for __FB_OPTION_PROFILE__, but it is used to detect at compile time if the current section of code is being compiled will have profiling code generated for it.

Consider this example and generating a call tree:

Code: Select all

#cmdline "-profgen fb" 

#if __FB_PROFILE__
	#include once "fbc-int/profile.bi"
	fbc.ProfileSetOptions( fbc.PROFILE_OPTION_REPORT_CALLTREE )
#endif

sub A( byval n as integer )
	sleep 100, 1
	if( n > 0 ) then
		A( n - 1 )
	end if
end sub

A( 5 )

Results in the following call-tree

Code: Select all

Call Tree:

\- (main)
   |- A
   |  |- A
   |  |  |- A
   |  |  |  |- A
   |  |  |  |  |- A
   |  |  |  |  |  |- A
   |  |  |  |  |  |  \- SLEEP
   |  |  |  |  |  \- SLEEP
   |  |  |  |  \- SLEEP
   |  |  |  \- SLEEP
   |  |  \- SLEEP
   |  \- SLEEP
   |- PROFILESETOPTIONS
   \- FB___MAIN
 

One option is to exclude a specific section of code from being profiled using "#pragma push(profile,false)":

Code: Select all

#cmdline "-profgen fb" 

#if __FB_PROFILE__
	#include once "fbc-int/profile.bi"
	fbc.ProfileSetOptions( fbc.PROFILE_OPTION_REPORT_CALLTREE )
#endif

sub A( byval n as integer )

	#pragma push(profile,false)
	sleep 100, 1
	#pragma pop(profile)

	if( n > 0 ) then
		A( n - 1 )
	end if
end sub

A( 5 )

Which then results in the following:

Code: Select all

Call Tree:

\- (main)
   |- A
   |  \- A
   |     \- A
   |        \- A
   |           \- A
   |              \- A
   |- PROFILESETOPTIONS
   \- FB___MAIN

[coderJeff]

Call fb's profiler directly to perform custom profiling and a report

Also, what is the feature of 'fbc.InitProfile()' ?

note: name changed in the last update

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.

fbc.ProfileInit() - Initialize the profiler
fbc.ProfileEnd(0) - Generate the profiling report and terminate the profiler
fbc.ProfileBeginCall( procedure_name ) - Begin a call and return a caller_id pointer
fbc.ProfileEndCall( caller_id ) - End a call

For example,

Code: Select all

#include "fbc-int/profile.bi"

#if __FB_PROFILE__ = fbc.PROFILE_OPTION_REPORT_CALLS
#error Do not compile with -profgen fb
#endif

using fbc

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)

Resulting in this report:

Code: Select all

Profiling results:
------------------

Executable name: E:\profile\manual.exe
Launched on: 04-28-2024, 20:23:01
Total program execution time: 0.304 seconds


Per function results:

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

(main)                         1     0.30396    100.00%

        Begin                  1     0.30396    100.00%   100.00%

Begin                          1     0.30396    100.00%

        Step 2                 1     0.20066     66.01%    66.01%
        Step 1                 1     0.10329     33.98%    33.98%



Global results:

(main)                         1     0.30396    100.00%
Begin                          1     0.30396    100.00%
Step 2                         1     0.20066     66.01%
Step 1                         1     0.10329     33.98%

[fxm]

@Jeff,

1)
Could you give a little information on these SUBs that can be used in the case of multi-threading ?

Code: Select all

#if __FB_MT__
extern "rtlib"
	declare sub fbProfileLock alias "fb_ProfileLock" ()
	declare sub fbProfileUnlock alias "fb_ProfileUnlock" ()
end extern
#endif

2)

Code: Select all

	declare sub ProfileIgnore alias "fb_ProfileIgnore" ( byval procedurename as zstring ptr ) 

The procedure names must absolutely be passed in upper case !

[srvaldez]

hello coderJeff
thank you for the profiling option, very interesting

[fxm]

New related pages in documentation:
- Compiler Option: -profgen
- __FB_PROFILE__
- __FB_OPTION_PROFILE__
- Profiling with fb's profiler (in Programmer's Guide)
+ Many slightly modified pages.

[coderJeff]

Could you give a little information on these SUBs that can be used in the case of multi-threading ?

Code: Select all

#if __FB_MT__
extern "rtlib"
	declare sub fbProfileLock alias "fb_ProfileLock" ()
	declare sub fbProfileUnlock alias "fb_ProfileUnlock" ()
end extern
#endif

'fbProfileLock' and 'fbProfileUnlock' is needed to serialize access to the profiler state data. It doesn't have and use yet for users. For me, it has been helpful to prototype some features in fb before writing the implementation in C in the fbrtlib. Once the internals of the profiler are stable, then we should be able to expose full access to the profiler object through an API.

Code: Select all

	declare sub ProfileIgnore alias "fb_ProfileIgnore" ( byval procedurename as zstring ptr ) 

The procedure names must absolutely be passed in upper case !

Oops, I didn't pay attention to that. The name of the procedure will depend on the name mangling of the procedure: this needs to be reviewed because currently the name generated internally is the debug name emitted for GDB as would be emitted by gas/gas64. Maybe this is ok, but for sure I didn't think about this before now.

Code: Select all

namespace ns
	sub proc alias "proc" ()
	end sub
end namespace

'' __ZN2NS4procEv@0
ns.proc ()

[fxm]

@Jeff,

Why the call tree representation depends on the procedure-name size (the only change) ?

Code: Select all

#cmdline "-profgen fb" 
#include once "fbc-int/profile.bi"
Using FBC
ProfileSetOptions( fbc.PROFILE_OPTION_REPORT_CALLTREE )

sub t( byval n as integer )
	sleep 100, 1
	if( n > 0 ) then
		t( n - 1 )
	end if
end sub

t( 5 )

Code: Select all

Call Tree:

\- (main)
   |- T
   |  |- T
   |  |  |- T
   |  |  |  |- T
   |  |  |  |  |- T
   |  |  |  |  |  |- T
   |  |  |  |  |  |  \- SLEEP
   |  |  |  |  |  \- SLEEP
   |  |  |  |  \- SLEEP
   |  |  |  \- SLEEP
   |  |  \- SLEEP
   |  \- SLEEP
   |- PROFILESETOPTIONS
   \- FB___MAIN

Code: Select all

#cmdline "-profgen fb" 
#include once "fbc-int/profile.bi"
Using FBC
ProfileSetOptions( fbc.PROFILE_OPTION_REPORT_CALLTREE )

sub test( byval n as integer )
	sleep 100, 1
	if( n > 0 ) then
		test( n - 1 )
	end if
end sub

test( 5 )

Code: Select all

Call Tree:

\- (main)
   |- PROFILESETOPTIONS
   |- FB___MAIN
   \- TEST
      |- SLEEP
      \- TEST
         |- SLEEP
         \- TEST
            |- SLEEP
            \- TEST
               |- SLEEP
               \- TEST
                  |- SLEEP
                  \- TEST
                     \- SLEEP

[fxm]

@Jeff,

Simple example, profiling a freebasic program and generating the default report:
A simple example:

Code: Select all

#cmdline "-profgen fb"

sub Pause100
	sleep 100, 1
end sub

sub Pause200
	sleep 200, 1
end sub

sub Pause400
	sleep 400, 1
end sub

for i as integer = 1 to 3
	Pause100
next

Pause200

Pause400

.....

Code: Select all

Profiling results:
------------------

Executable name: E:\profile\pauses.exe
Launched on: 04-27-2024, 16:48:14
Total program execution time: 0.907 seconds


Per function results:

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

(main)                         1     0.90704    100.00%

        PAUSE400               1     0.40100     44.21%    44.21%
        PAUSE100               3     0.30502     33.63%    33.63%
        PAUSE200               1     0.20100     22.16%    22.16%
        FB___MAIN              1     0.00000      0.00%     0.00%

PAUSE100                       3     0.30502     33.63%

        SLEEP                  3     0.30502     33.63%   100.00%

PAUSE200                       1     0.20100     22.16%

        SLEEP                  1     0.20100     22.16%   100.00%

PAUSE400                       1     0.40100     44.21%

        SLEEP                  1     0.40099     44.21%   100.00%



Global results:

(main)                         1     0.90704    100.00%
PAUSE400                       1     0.40100     44.21%
PAUSE100                       3     0.30502     33.63%
SLEEP                          3     0.30502     33.63%
PAUSE200                       1     0.20100     22.16%
FB___MAIN                      1     0.00000      0.00%

About the profiling report
In the 'Global results' section, all SLEEPs are not accumulated:

Code: Select all

SLEEP                          3     0.30502     33.63%
I was expecting something like
SLEEP                          5     0.90701    100.00%

Child procedures with the same name (regardless of their nesting orders) must be accumulated in the 'Global results' section

[coderJeff]

Why the call tree representation depends on the procedure-name size (the only change) ?

The procedure information is stored in a kind of hash table and the hash index is generated by a hashing function that operates on the procedure name. The order of procedures will follow the hashing index. So, not a useful ordering for the report.

I will fix this by sorting the procedures by name.

[coderJeff]

Child procedures with the same name (regardless of their nesting orders) must be accumulated in the 'Global results' section

Yes, agreed. I added the procedure count using same method as total time. I think the issue is a carry over from original implementation. In this example the total time for sleep should be approximately the full duration of the program run time.

[fxm]

Profiling reports in case of multi-threading

The report of a block per thread: (main), (thread)#1, (thread)#2, ..., suits me perfectly.

But accumulation of procedures (or builtin instructions) should only be carried out in the same thread, because it is illogical to add up the execution times of procedures (or builtin instructions) that execute in parallel (not serially).

Therefore, there must be as many blocks as threads: (main), (thread)#1, (thread)#2 , ..., both in the 'Per function results' section and in the 'Per function results' section (and in the same order).
Shared procedure (or built-in instruction) calls must only be accumulated within the same thread (so one result per calling thread).

Additionally, in the current profiling report, the time value on the '(thread)' line is wrong (the same as for '(main)' !).

Current profiling reports:

Code: Select all

#cmdline "-profgen fb"
'#include once "fbc-int/profile.bi"
'Using FBC

'ProfileSetOptions(PROFILE_OPTION_REPORT_CALLTREE)

Sub state(Byref s As String)
    Print s
    Sleep 100, 1
End Sub

Sub thread(Byval p As Any Ptr)
    state("thread running")
    Sleep 100, 1
    state("thread finishing")
End Sub

state("main running")
Sleep 100,1
state("create thread")
Dim As Any Ptr p = Threadcreate(@thread)
threadwait(p)
state("thread finished")
Sleep 100,1
state("main finishing")

Code: Select all

Per function results:

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

(main)                             1     0.98365    100.00%

        STATE                      4     0.45037     45.79%    45.79%
        THREADWAIT                 1     0.33247     33.80%    33.80%
        SLEEP                      2     0.20058     20.39%    20.39%
        THREADCREATE               1     0.00016      0.02%     0.02%
        FB_STRASSIGN               4     0.00002      0.00%     0.00%
        FB_STRDELETE               4     0.00001      0.00%     0.00%
        FB___MAIN                  1     0.00000      0.00%     0.00%

(thread)                           1     0.98365    100.00%

        STATE                      2     0.23152     23.54%    23.54%
        SLEEP                      1     0.10053     10.22%    10.22%
        FB_STRDELETE               2     0.00001      0.00%     0.00%
        FB_STRASSIGN               2     0.00001      0.00%     0.00%

STATE                              4     0.45037     45.79%

        SLEEP                      4     0.44829     45.57%    99.54%
        FB_PRINTSTRING             4     0.00207      0.21%     0.46%



Global results:

(thread)                           1     0.98365    100.00%
(main)                             1     0.98365    100.00%
STATE                              4     0.45037     45.79%
SLEEP                              4     0.44829     45.57%
THREADWAIT                         1     0.33247     33.80%
FB_PRINTSTRING                     4     0.00207      0.21%
THREADCREATE                       1     0.00016      0.02%
FB_STRASSIGN                       4     0.00002      0.00%
FB_STRDELETE                       4     0.00001      0.00%
FB___MAIN                          1     0.00000      0.00%

Code: Select all

Call Tree:

\- (main)
   |- SLEEP
   |- FB_STRASSIGN
   |- STATE
   |  |- SLEEP
   |  \- FB_PRINTSTRING
   |- FB_STRDELETE
   |- THREADWAIT
   |- PROFILESETOPTIONS
   |- FB___MAIN
   \- THREADCREATE



\- (thread)
   |- FB_STRASSIGN
   |- STATE
   |  |- SLEEP
   |  \- FB_PRINTSTRING
   |- FB_STRDELETE
   \- SLEEP

[fxm]

New related pages in documentation:
- Compiler Option: -profgen
- __FB_PROFILE__
- __FB_OPTION_PROFILE__
- Profiling with fb's profiler (in Programmer's Guide)
+ Many slightly modified pages.

In documentation, the update regarding profiling (with fb's profiler) is now pretty much finalized.

[coderJeff]

But accumulation of procedures (or builtin instructions) should only be carried out in the same thread, because it is illogical to add up the execution times of procedures (or builtin instructions) that execute in parallel (not serially).
...

Yes, have been working on all this. In the next update this should all be working. Each thread will have a separate instance of the profiler, stored in thread local storage thereby removing 99% of the previous mutex locking. Call counting problem is sovled, but now need to solve the time reporting problem for recursively called procedures. Once this is working, will push the next update.

[fxm]

@Jeff,

2)

Code: Select all

	declare sub ProfileIgnore alias "fb_ProfileIgnore" ( byval procedurename as zstring ptr ) 

The procedure names must absolutely be passed in upper case !

Not fixed yet (after last update) ?

[coderJeff]

Not fixed yet (after last update) ?

Correct, not fixed yet. I'm not sure what to do. Currently, the argument to ProfileIgnore() list must match the generated assembly name of the procedure which may vary between targets (windows / linux / etc ).

All procedures are identified by strings and need to be unique enough that they are seen as different procedures. Currently the naming as required in the string argument follows the same name mangling generated in the asm / C output. (And still to do is to differentiate same named PRIVATE procedures in different modules. They will have the same name between modules, they are private when linking the executable but global when tracked in the profiler, so some inclusion of the module name still needs to be added to the identifier.)

I thought maybe something like the following, but __FB_QUERY_SYMBOL__ needs to be fixed too, since it currently gives the return type of the procedure and not the mangled name of the procedure itself.

Code: Select all

#cmdline "-profgen fb"

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

namespace ns
	sub proc1 alias "some_other_name1"
		sleep 100, 1
	end sub
	sub proc2 alias "some_other_name2"
		sleep 100, 1
	end sub
end namespace

fbc.ProfileIgnore( __FB_QUOTE__( __FB_QUERY_SYMBOL__( fbc.FB_QUERY_SYMBOL.mangleid, ns.proc1 ) ) )

ns.proc1
ns.proc2