Profiling freebasic programs
Profiling freebasic programs
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.
'-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.
Re: Profiling freebasic programs
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
'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
Re: Profiling freebasic programs
Simple example, profiling a freebasic program and generating the default report:
A simple example:
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.
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
(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%
Last edited by coderJeff on Apr 28, 2024 23:21, edited 1 time in total.
Re: Profiling freebasic programs
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:
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" )
Re: Profiling freebasic programs
Generating a call tree
For example, with this source we tell the profiler to generate a call tree instead of timings and counts.
Which will produce the following output in the report file:
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
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
Re: Profiling freebasic programs
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%
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%
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.
Re: Profiling freebasic programs
thank you adeyblue for the tests
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.
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.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).
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.
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.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.
Ah, good idea, thank-you.I'd also suggest maybe changing the default file name to include the module name (ie myexe.exe or myapp.dll).
Re: Profiling freebasic programs
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) ?
- 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) ?
Re: Profiling freebasic programs
Thank-you, I agree with having separate pagesfxm wrote: ↑Apr 28, 2024 12:21 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) ?
Re: Profiling freebasic programs
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.
Re: Profiling freebasic programs
coderJeff wrote: ↑Apr 28, 2024 13:03Thank-you, I agree with having separate pagesfxm wrote: ↑Apr 28, 2024 12:21 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) ?
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()' ?
Re: Profiling freebasic programs
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
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
Re: Profiling freebasic programs
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.
Note:
I also updated after the 'inc' directory from:
freebasic_additional_headers.zip
but that should not be necessary for this.
Re: Profiling freebasic programs
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
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
Last edited by Dinosaur on Apr 29, 2024 8:46, edited 2 times in total.
Re: Profiling freebasic programs
Conditional compilation depending on profile code generation method
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
__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
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