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).

[coderJeff]

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

This has been and is now both an interesting and annoying challenge.

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

I also thought would be easy-ish, just following the mangling grammar. But it's not a case of just replacing one string for another and sorting the order for freebasic.

I've made quite a bit of progress fumbling around with this on and off for a while now. So I went ahead and published what I have; something that kind of does something but is far from complete. I thought someone might find it interesting.

SOURCE FILE: CDemangler.bas

So for example:

Code: Select all

#include once "CDemangler.bas"

dim as CDemangler demangler
dim as string src =  "_ZN1A1BEPKaPK1CP1DS6_"
dim as string ret = demangler.demangle( src )

#if __FB_DEBUG__
demangler.dump()
#endif

'' show results
print "'" & src & "'"
print "'" & ret & "'"
print

print "press any key"
sleep

This gives a result, but should notice right away has a problem of showing things in the same order as would be in C++ declaration:

Code: Select all

'_ZN1A1BEPKaPK1CP1DS6_'
'A.B( as ptr const byte , as ptr const C, as ptr D, as ptr D )'

The hardest bit is the substitutions, a kind of compression in the mangled name where an "S[number]_" mangled identifier can refer to an earlier declaration. But it's not just a string lookup and replacement, it's symbolic. So in this case, this short mangled name actually has many substitutions available based on the order of parsing the mangled name string:

Code: Select all

SUBSTITUTIONS(8):
  0: 'A'
  4   4         TT_SOURCE_NAME          + 1A

  1: 'const byte '
  4   8      10 TT_CV_QUALIFIER_CONST   \ K
  5   9         TT_BUILTIN_TYPE            + a

  2: 'ptr const byte '
  4   7       9 TT_TYPE_POINTER         \ P
  5   8      10 TT_CV_QUALIFIER_CONST      \ K
  6   9         TT_BUILTIN_TYPE               + a

  3: 'C'
  4  13         TT_SOURCE_NAME          + 1C

  4: 'const C'
  4  12      19 TT_CV_QUALIFIER_CONST   \ K
  5  13         TT_SOURCE_NAME             + 1C

  5: 'ptr const C'
  4  11      18 TT_TYPE_POINTER         \ P
  5  12      19 TT_CV_QUALIFIER_CONST      \ K
  6  13         TT_SOURCE_NAME                + 1C

  6: 'D'
  4  16         TT_SOURCE_NAME          + 1D

  7: 'ptr D'
  4  15      28 TT_TYPE_POINTER         \ P
  5  16         TT_SOURCE_NAME             + 1D

So what we end up with is a tree representation of the mangled name that symbolically represents the declaration (yes an abstract syntax tree):

Code: Select all

NODES(33):
  N   I   L   R TOKEN TYPE               Text
--- --- --- --- ------------------------ ----------
  0   0   1     NT_ENCODING_PREFIX      + NT_ENCODING_PREFIX
  1   1       2 NT_ENCODING             \ NT_ENCODING
  2   2   7   3 NT_TOP_NAME                + NT_TOP_NAME
  3   3       4 TT_NESTED_BEGIN            |  \ N
  4   4   6     TT_SOURCE_NAME             |     + 1A
  5   5         TT_SOURCE_NAME             |     + 1B
  6   6      16 NT_PARAMETER_LIST          \ NT_PARAMETER_LIST
  7  10  26   8 NT_PARAMETER                  + NT_PARAMETER
  8   7       9 TT_TYPE_POINTER               |  \ P
  9   8      10 TT_CV_QUALIFIER_CONST         |     \ K
 10   9         TT_BUILTIN_TYPE               |        + a
 11  14  32  17 NT_PARAMETER                  + NT_PARAMETER
 12  11      18 TT_TYPE_POINTER               |  \ P
 13  12      19 TT_CV_QUALIFIER_CONST         |     \ K
 14  13         TT_SOURCE_NAME                |        + 1C
 15  17      27 NT_PARAMETER                  \ NT_PARAMETER
 16  15      28 TT_TYPE_POINTER                  \ P
 17  16         TT_SOURCE_NAME                      + 1D

Then finally, need to emit this tree, taking in to account the order needed for freebasic declarations (which I have not done).