Profiling freebasic programs

[coderJeff]

New profiling feature in freebasic
'-profgen fb' command line option generates a profiling report "<filename[.exe]>.prf" where <filename[.exe]> is the name of the executable.

To try it out:
- obtain latest fbc development binaries (or build your own)
- add '#cmdline "-profgen fb"' to your source and compile your program
- Or compile your program with '-profgen fb' command line option
- Run your compiled program
- When the program exits, it will write a profiling report to "<filename[.exe]>.prf"
- Marvel at the results!

actually ... please check the math. The calculations and tallies are based on the original implementation and this feature newly re-added, so could be bugs to squash

----

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 favour of gmon/gprof.

Personally, I liked some of the capabilities of lillo's 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.

I was able to successfully run the profiler on the full test suite, and on fbc when using fbc to compile itself.

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

[coderJeff]

New command line option -profgen:
'fbc -profgen gmon' : enable profiling code generation for gmon/gprof
'fbc -profgen fb' : enable function call profiling using fb's profiler
'fbc -profgen cycles' : coming soon, for cpu cycle counting on some targets (currently a wip on -gen gas64 only)

FYI on command line option -profile
'-profile' is a pre-existing command line option that enabled profiling code generation for gmon/gprof
In future, this will probably change to indicate "enable default profiler". Note that not every kind of profile code generation will be supported on every target, so this option will be used to choose something automatically that makes sense for the target platform.

Added: ./inc/fbc-int/profile.bi which allows user to access some more advanced features of the profiling report. Examples to follow in later posts.

Examples:
1) Simple example, generating the default report
2) Setting the output report file name at runtime
3) Generating a call tree
4) Conditional compilation depending on profile code generation method
5) Conditional generation of profiling code
6) Call fb's profiler directly to perform custom profiling and a report



TODO stuff, for future:

Still things to do on this feature:
- more testing, especially recursion and threading
- optionally merge main and thread data
- test the start-up and exit code more
- demangle procedure names
- refactor the code (again), to share code with cycle count profiler (coming soon)
- 32-bit gas backend: thiscall and fastcall calling conventions don't work with this profiler

[coderJeff]

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

After compiling and running the program, the default named report "<filename[.exe]>.prf" is generated.

(EDIT: previously default report filename was named "profile.txt". The default report filename is now the executable name with an added ".prf" extension)

There are two sections:
1) per function results - profile of individual procedures and the procedures called
2) 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.

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%

[coderJeff]

Setting the output report file name at run-time

New include file 'fbc-int/profile.bi' adds some API for working with profiling

For example, this has the effect of setting the output filename for the profile report to "prof-hhmmss.txt" where 'hhmmss' is replaced with the current time:

Code: Select all

#include once "fbc-int/profile.bi"
'' 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)
fbc.ProfileSetFileName( "prof-" + n + ".txt" )

[coderJeff]

Generating a call tree

For example, with this source we tell the profiler to generate a call tree instead of timings and counts.

Code: Select all

#cmdline "-profgen fb" 

#include once "fbc-int/profile.bi"
fbc.ProfileSetOptions( fbc.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

Which will produce the following output in the report file:

Code: Select all

Call Tree:

\- (main)
   |- PROFILESETOPTIONS
   |- D
   |  |- C
   |  |  |- FB_STRALLOCTEMPDESCZEX
   |  |  \- FB_PRINTSTRING
   |  |- FB_STRALLOCTEMPDESCZEX
   |  |- B
   |  |  |- FB_STRALLOCTEMPDESCZEX
   |  |  \- FB_PRINTSTRING
   |  |- A
   |  |  |- FB_STRALLOCTEMPDESCZEX
   |  |  \- FB_PRINTSTRING
   |  \- FB_PRINTSTRING
   \- FB___MAIN

[adeyblue]

- more testing, especially recursion and threading

Indirect calls aren't faring too well.

Code: Select all

Function FirstFunc(Byval a as Long) As Long

  Sleep 500
  Return a* 2

End Function

Function SecondFunc(ByVal b as Long) As Long

  Sleep 600
  Return b * 2

End Function

Dim fnPtr as Function(ByVal b as Long) As Long

For i As Long = 0 To 9

If Rnd * 2 > 1 Then
   fnPtr = @FirstFunc
Else
   fnPtr = @SecondFunc
End If

fnPtr(i)

Next

Code: Select all

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

Executable name: T:\test.exe
Launched on: 04-28-2024, 02:34:33
Total program execution time: 5.342 seconds


Per function results:

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

(main)                           1     5.34163    100.00%

        {fbfp}FiiE$1            10     5.34151    100.00%   100.00%
        RND                     10     0.00003      0.00%     0.00%

{fbfp}FiiE$1                    10     5.34151    100.00%

        SLEEP                   10     5.34149    100.00%   100.00%



Global results:

(main)                           1     5.34163    100.00%
{fbfp}FiiE$1                    10     5.34151    100.00%
SLEEP                           10     5.34149    100.00%
RND                             10     0.00003      0.00%

See also external callbacks like this viewtopic.php?t=32483 where the called-back function is missed out since it's never directly called (ie ProcessEvents won't ever show up, all its data gets attributed to ProcessTrace). An example run is below. This is fine here, but when the dispatcher can call multiple callbacks, all their leaf functions will be glommed into the dispatcher with no way to tell them apart

Code: Select all

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

Executable name: H:\FB\FreeBASIC-1.10.0-winlibs-gcc-9.3.0\etw.exe
Launched on: 04-28-2024, 02:20:47
Total program execution time: 79.21 seconds


Per function results:

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

(main)                                     1    79.20576    100.00%

        SLEEP                           9387    74.00511     93.43%    93.43%
        THREADWAIT                         1     3.76325      4.75%     4.75%
        INKEY                           9387     1.35830      1.71%     1.71%
        FB_STRCOMPARE                   9387     0.01287      0.02%     0.02%
        FB_PRINTSTRING                     1     0.00079      0.00%     0.00%
        THREADCREATE                       1     0.00011      0.00%     0.00%
        FB_STRALLOCTEMPDESCZEX             1     0.00000      0.00%     0.00%

(thread)                                   1    79.20576    100.00%

        PROCESSTRACE                       1    79.19084     99.98%    99.98%
        STARTTRACEW                        1     0.00717      0.01%     0.01%
        WPRINTF                            1     0.00487      0.01%     0.01%
        PUTS                               1     0.00179      0.00%     0.00%
        ENABLETRACEEX2                     2     0.00040      0.00%     0.00%
        OPENTRACEW                         1     0.00022      0.00%     0.00%
        STOPTRACEW                         2     0.00009      0.00%     0.00%
        CLOSETRACE                         1     0.00002      0.00%     0.00%
        FB_WSTRASSIGN                      1     0.00000      0.00%     0.00%

PROCESSTRACE                               1    79.19084     99.98%

        WPRINTF                          303     0.78668      0.99%     0.99%
        PUTWCHAR                          23     0.00411      0.01%     0.01%
        SHUTDOWNTRACING                    1     0.00379      0.00%     0.00%

SHUTDOWNTRACING                            1     0.00379      0.00%

        PUTS                               1     0.00295      0.00%    77.80%
        STOPTRACEW                         1     0.00068      0.00%    17.93%
        ENABLETRACEEX2                     1     0.00015      0.00%     3.92%



Global results:

(thread)                                   1    79.20576    100.00%
(main)                                     1    79.20576    100.00%
PROCESSTRACE                               1    79.19084     99.98%
SLEEP                                   9387    74.00511     93.43%
THREADWAIT                                 1     3.76325      4.75%
INKEY                                   9387     1.35830      1.71%
WPRINTF                                  303     0.78668      0.99%
FB_STRCOMPARE                           9387     0.01287      0.02%
STARTTRACEW                                1     0.00717      0.01%
PUTWCHAR                                  23     0.00411      0.01%
SHUTDOWNTRACING                            1     0.00379      0.00%
PUTS                                       1     0.00295      0.00%
FB_PRINTSTRING                             1     0.00079      0.00%
STOPTRACEW                                 1     0.00068      0.00%
OPENTRACEW                                 1     0.00022      0.00%
ENABLETRACEEX2                             1     0.00015      0.00%
THREADCREATE                               1     0.00011      0.00%
CLOSETRACE                                 1     0.00002      0.00%
FB_WSTRASSIGN                              1     0.00000      0.00%
FB_STRALLOCTEMPDESCZEX                     1     0.00000      0.00%

Also, you could keep the call database per thread and then merge it to a global one while under the main lock when the thread dies. No extra locks or locking during the profiling calls would be required. The contention for this profile lock will be massive in any sort of active multithread program and on Windows, critical sections aren't FIFO in terms of waiting and acquiring nor fair so threads could end up waiting and skewing/heisenberging the results.

I'd also suggest maybe changing the default file name to include the module name (ie myexe.exe or myapp.dll). Black-holing some results because you didn't actively set a file name and your multi-module profiles overwrote each-other is perhaps a little unfriendly as a default.

[coderJeff]

thank you adeyblue for the tests

Indirect calls aren't faring too well.

See also external callbacks like this viewtopic.php?t=32483 where the called-back function is missed out since it's never directly called (ie ProcessEvents won't ever show up, all its data gets attributed to ProcessTrace).

You are quite correct. The original strategy of this profiler measures each callee through the caller only which is nice for seeing what's being called even if the callee wasn't built with profiling in mind. But does not measure procedures called through a callback, so we don't see the whole picture with this strategy alone.

SARG was working on changes (currently gas64 only) that inject measuring code at the beginning and end of each procedure, and would allow measuring each callee independently of who the caller was. Not sure atm if this will stay as 2 different kinds of profiling or if the 2 strategies can optionally be combined to give a fuller picture of the execution.

Also, you could keep the call database per thread and then merge it to a global one while under the main lock when the thread dies. No extra locks or locking during the profiling calls would be required.

I had this idea also; and the profiler supporting code should allow capability to instance a profiler on each thread. To be honest, I haven't thought about how to merge multiple call trees so just getting this thing working well enough for basic use the call database is managed under one profiler instance with a mutex.

I'd also suggest maybe changing the default file name to include the module name (ie myexe.exe or myapp.dll).

Ah, good idea, thank-you.

[fxm]

About documentation update:
- Added 'Compiler Option: -profgen' page.
- Waiting for new update to add '__FB_PROFILE__' and '__FB_OPTION_PROFILE__'.
- @Jeff : For the Programmer's Guide, a single page containing profiling for both gmon/gprof and fb's profiler, or 2 separate pages (the simpler in my opinion) ?

[coderJeff]

About documentation update:
- Added 'Compiler Option: -profgen' page.
- Waiting for new update to add '__FB_PROFILE__' and '__FB_OPTION_PROFILE__'.
- @Jeff : For the Programmer's Guide, a single page containing profiling for both gmon/gprof and fb's profiler, or 2 separate pages (the simpler in my opinion) ?

Thank-you, I agree with having separate pages

[coderJeff]

while under the main lock.
...
this profile lock

Just to clarify, what is your opinion / which do you suggest the "main lock" should be? Because I am uncertain and thought about this a bit before doing what I did.

The original implementation of the profiler (what I started off with) used the main rtlib mutex (FB_LOCK/FB_UNLOCK).

But because the profiler does not share any data (and very little code for that matter) with the rest of the rtlib I added a profiler mutex just for the profiler data since the profiler data should be completely distinct from the rest of the rtlib.

[fxm]

About documentation update:
- Added 'Compiler Option: -profgen' page.
- Waiting for new update to add '__FB_PROFILE__' and '__FB_OPTION_PROFILE__'.
- @Jeff : For the Programmer's Guide, a single page containing profiling for both gmon/gprof and fb's profiler, or 2 separate pages (the simpler in my opinion) ?

Thank-you, I agree with having separate pages

As for '#pragma profile [=value]' or '#pragma push( profile [,value] )', I do not know how it works or how to integrate it into the documentation (in existing page or to new page) ?

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

[Dinosaur]

Hi All

Missing something in this implementation of profiling.
Downloaded the .zip file fbc_linux64_0813_2024-04-27.zip 2024-04-28 02:03 1.7M
from https://users.freebasic-portal.de/stw/builds/
Deleted my old usr/local/bin/fbc and proved it was the only one on my system.
Extracted and ran sudo ./install.sh -i

After that tried in various places to use -profgen fb
In Geany Set Build commands fbc -v -profgen fb -s gui -l cgui -w all "%f"
At the command line: fbc myprog.bas -profgen fb
In the source code Project.bi which is the first statement in the source code:

All of them come back with a variation of:
Invalid command-line option, "-profgen"

Can SKS please direct me in the direction to make this work

Regards

[fxm]

No problem for me with Windows 10.

Note:
I also updated after the 'inc' directory from:
freebasic_additional_headers.zip
but that should not be necessary for this.

[Dinosaur]

Hi All

fxm , thanks for your reply.

The download from https://users.freebasic-portal.de/stw/builds/
results in a folder structure:
fbc_linux64/include/freebasic/fbc-int

The additional headers extract into an inc folder.
Taking the contents of the inc folder and pasting it into fbc_linux64/include
does not solve the problem.

When downloading daily builds like this (my first time) what is the correct folder structure for the includes.?

EDIT: Changing the Folder structure to:
FreeBASIC/include/freebasic/..... all the included folders like Al Allegro etc from the Additional Headers.
Then running ./install.sh -i

Edit: Include folders also installed in /usr/local/include/freebasic/...

Still creates the same error with the sample code from the first post above.

After confirming all I could I have concluded that the fbc version included with fbc_linux64_0813_2024-04-27.zip 2024-04-27
simply does not recognise the "-profgen" command from within the source code or as command line fbc Test.bas -profgen fb
So I guess I will wait until further development.

Regards

[coderJeff]

Conditional compilation depending on profile code generation method

- add '__FB_PROFILE__'

__FB_PROFILE__ is an intrinsic define set to an integer to indicate the profiling method.

Code: Select all

namespace FBC
enum PROFGEN_ID
	PROFGEN_ID_NONE                  = 0
	PROFGEN_ID_GMON                  = 1
	PROFGEN_ID_CALLS                 = 2
	PROFGEN_ID_CYCLES                = 3
end enum

Please do use the named constants in "fbc-int/profile.bi"

built-in instrinsic define '__FB_PROFILE__' will be 0 if profiling is not enabled

'__FB_PROFILE__' will be set to a non-zero integer if '-profgen' or '-profile' command line option was given on the command line of in #cmdline

PROFGEN_ID_GMON: code is being generated for gmon/gprof
PROFGEN_ID_CALLS: code is being generated for fb's function call profiler
PROFGEN_ID_CYCLES: code is being generated for fb's cycle count call profiler (wip: gas64 only as of APR 2024)

Example to set the profiling filename:
1) Only include "fbc-int/profile.bi" if profiling enabled
2) Only set the filename if '-profgen fb' was given

Code: Select all

#if __FB_PROFILE__
	#include once "fbc-int/profile.bi"

	#if __FB_PROFILE__ = fbc.PROFGEN_ID_CALLS
		'' automatically change the profile report name
		scope
			dim t as string = TIME
			dim n as string = left(t,2)+mid(t,4,2)+right(t,2)
			fbc.ProfileSetFileName( "prof-" + n + ".txt" )
		end scope
	#endif
#endif