Profiling freebasic programs

[coderJeff]

In the last update 2024-05-17, the '-profgen fb' is mostly doing the kinds of things that I want it to do.
- can build the fbc test suite profiled and generate the report
- can build fbc itself and then compile fbc to generate a profiling report.
- Lots of information is collected and the report output is *fast*
- The implementation is mostly written in plain C, so should work on most platforms
- The basic port of the rtlib works also: https://github.com/ImortisInglorian/fbrtLib/pull/30

There is of course always areas to improve and bugs to find but I think could be used as-is in next release. I'm currently going through the various fbc targets and checking that the latest changes can compile and run on other platforms.

'-profgen cycles' is still a work in progress and will need more work. It can generate a basic report of cycle counts. It uses completely different methods to '-profgen fb'. '-profgen cycles' currently is only for `-gen gas64', stores data in specially named data sections, so will only work with linkers supporting arbitrarily named sections. '-profgen cycles' won't be supported on all platforms.

[fxm]

'-profgen cycles' is still a work in progress and will need more work.

When the work is well advanced, I plan to integrate this into the already existing page already prepared for this:
Profiling with fb's profiler (so: function call profiling + cycle count profiling)

[fxm]

@Jeff,

What is the precise meaning of the columns: 'total' and 'inside' in the report from cycle count profiler ?

[SARG]

What is the precise meaning of the columns: 'total' and 'inside' in the report from cycle count profiler ?

As author of the "engine" I can answer
Total: the number of cycles between the end of the procedure and its beginning
Inside : the number of cycles really "spent" inside the procedure.
In short if there is no call in the procedure the two numbers are equal.

This allows to know the real number of cycles in case of call to procedures not profiled (eg libraries)

[fxm]

Indeed this can be misleading:

Code: Select all

#cmdline "-profgen cycles"

Sub A()
End Sub

Sub B()
End Sub

A()
B()

• Compilation (-gen gas64) without other compile options:

  Code: Select all

  Total program execution time: 0.0004445 seconds
  module  function             total             inside         call count
  
  C:\...\FBIde0.4.6r4-FreeBASIC1.20.0.win64\FBIDETEMP.bas
  
          A
                                  21                 21                  1
          B
                                  21                 21                  1
          main
                                   0                105                  1
  

  Compilation (-gen gas64) with '-exx' compile option for example:

  Code: Select all

  Total program execution time: 0.0006235 seconds
  module  function             total             inside         call count
  
  C:\...\FBIde0.4.6r4-FreeBASIC1.20.0.win64\FBIDETEMP.bas
  
          A
                                 504                273                  1
          B
                                 336                210                  1
          main
                                   0                357                  1
  

[SARG]

Indeed this can be misleading:

Are the titles misleading?

[fxm]

Total: the number of cycles between the end of the procedure and its beginning
Inside : the number of cycles really "spent" inside the procedure.
In short if there is no call in the procedure the two numbers are equal.

This allows to know the real number of cycles in case of call to procedures not profiled (eg libraries)

What happens if the compiler adds simple code lines (no procedure calls) inside a user procedure?

[SARG]

What happens if the compiler adds simple code lines (no procedure calls) inside a user procedure?

Nothing is excluded, excepted not profiled procedures, so added code is also taken in account.
I hope that most of the profiled code is written by users.....

Code: Select all

For each proc  total cycles, internal cycles and number of calls

PROC A (main)
  ^-
  |-
  |- TA1
  |-
  |call--->PROC B
  |	 ^-
  |	 |- TB1
  |	 |-
  |	 |call--->PROC C
  |	 |	 ^-
  |	 | 	 |- TC1=TCT (if proc C is not profiled nothing will be stored when executed)
 TAT	TBT	 v-
  |	 |-
  |	 |- TB2
  |	 v-
  |-	 
  |- TA2	
  |-
  |call--->PROC D
  |	 ^-
  |	|- TD1=TDT
  |	 v-
  |-
  |- TA3
  v-

Final results :
TAT total cycles
TAI for A = TA1 + TA2 + TA3
TBI = TB1 + TB2
plus the number of times each procedure is called.

[fxm]

'-profgen cycles' is still a work in progress and will need more work.

When the work is well advanced, I plan to integrate this into the already existing page already prepared for this:
Profiling with fb's profiler (so: function call profiling + cycle count profiling)

For the moment, I have nevertheless documented a little of the existing capacity.

[adeyblue]

Can you make the reports show the unmangled function names before you kick it out the door as finished?

Code: Select all

{fbfp}FiR16ISHELLTREEWALKERjPKwS2_iP16TREEWALKCALLBACKE$1                                         1     0.01711     55.16%

        _ZN16TREEWALKCALLBACK9FOUNDFILEEPKwPK15TREEWALKERSTATSP17_WIN32_FIND_DATAW                1     0.00961     30.99%    56.18%
        _ZN16TREEWALKCALLBACK11ENTERFOLDEREPKwPK15TREEWALKERSTATSP17_WIN32_FIND_DATAW             1     0.00375     12.09%    21.92%
        _ZN16TREEWALKCALLBACK11LEAVEFOLDEREPKwPK15TREEWALKERSTATS                                 1     0.00280      9.04%    16.39%

This requires both an extra tool to demangle and is rather ungangly and unfriendly. I don't think users particularly care about the vagries of whatever internal recordkeeping format you've picked, but I do think they may rather care (I do, for one) that its output doesn't match the names that are in the source code and that it means extra work to figure it out.

[SARG]

@adeyblue
It's planned. I have provided a demangler (coded in FB) to Jeff.
With your examples what we get :

Code: Select all

{fbfp}FiR16ISHELLTREEWALKERjPKwS2_iP16TREEWALKCALLBACKE$1

TREEWALKCALLBACK.FOUNDFILE(* ,const.,wstring,* ,const.TREEWALKERSTATS,* ._WIN32_FIND_DATAW)
TREEWALKCALLBACK.ENTERFOLDER(* ,const.,wstring,* ,const.TREEWALKERSTATS,* ._WIN32_FIND_DATAW)
TREEWALKCALLBACK.LEAVEFOLDER(* ,const.,wstring,* ,const.TREEWALKERSTATS)

The first line is not demangled what are the initial name/parameters ?

I guess some cases still need a little work for more exact output.

Edit
For comparison, with GCC and MSVC C++ Demangler :

Code: Select all

TREEWALKCALLBACK::FOUNDFILE(wchar_t const*, TREEWALKERSTATS const*, _WIN32_FIND_DATAW*)
TREEWALKCALLBACK::ENTERFOLDER(wchar_t const*, TREEWALKERSTATS const*, _WIN32_FIND_DATAW*)
TREEWALKCALLBACK::LEAVEFOLDER(wchar_t const*, TREEWALKERSTATS const*)

Not so bad

Edit bis
After some adjustments

Code: Select all

TREEWALKCALLBACK.FOUNDFILE(* const wstring,* const TREEWALKERSTATS,*  _WIN32_FIND_DATAW)
TREEWALKCALLBACK.ENTERFOLDER(* const wstring,* const TREEWALKERSTATS,*  _WIN32_FIND_DATAW)
TREEWALKCALLBACK.LEAVEFOLDER(* const wstring,* const TREEWALKERSTATS)

[dodicat]

For adeyblue's 4 strings.

Code: Select all

#inclib "stdc++"
declare function demangle cdecl alias "__cxa_demangle"(as zstring ptr,as zstring ptr=0,as long=0,byref as long=0) as zstring ptr

function getdemangledname(mn as string,expand as boolean=false) as string
dim as long k
dim as string z=*demangle(mn,0,0,k) 
if expand then
print "Demangling: ";iif(len(z)=0,"Fail","OK")+"  ";
print mn
select case k
case  0:print "The demangling operation succeeded."
case -1:print "A memory allocation failiure occurred."
case -2:print "mangled_name is not a valid name under the C++ ABI mangling rules."
case -3:print "One of the arguments is invalid."
end select
end if
return z
end function

print getdemangledname("_ZN16TREEWALKCALLBACK9FOUNDFILEEPKwPK15TREEWALKERSTATSP17_WIN32_FIND_DATAW")
print
print getdemangledname("_ZN16TREEWALKCALLBACK11ENTERFOLDEREPKwPK15TREEWALKERSTATSP17_WIN32_FIND_DATAW")
print
print getdemangledname("_ZN16TREEWALKCALLBACK11LEAVEFOLDEREPKwPK15TREEWALKERSTATS",true)
print
print getdemangledname("{fbfp}FiR16ISHELLTREEWALKERjPKwS2_iP16TREEWALKCALLBACKE$1",true)
print
print mid(getdemangledname("_Z13Press Any Keyv"),1,13)
sleep
 

The first string doesn't demangle, I have put it in last (but one).