Profiling freebasic programs

Forum for discussion about the documentation project.
coderJeff
Site Admin
Posts: 4358
Joined: Nov 04, 2005 14:23
Location: Ontario, Canada
Contact:

Re: Profiling freebasic programs

Post by 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
Moderator
Posts: 12222
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Profiling freebasic programs

Post by fxm »

coderJeff wrote: May 18, 2024 11:52 '-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
Moderator
Posts: 12222
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Profiling freebasic programs

Post by fxm »

@Jeff,

What is the precise meaning of the columns: 'total' and 'inside' in the report from cycle count profiler ?
SARG
Posts: 1792
Joined: May 27, 2005 7:15
Location: FRANCE

Re: Profiling freebasic programs

Post by SARG »

fxm wrote: May 28, 2024 11:21 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
Moderator
Posts: 12222
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Profiling freebasic programs

Post by 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
Posts: 1792
Joined: May 27, 2005 7:15
Location: FRANCE

Re: Profiling freebasic programs

Post by SARG »

fxm wrote: May 28, 2024 15:01 Indeed this can be misleading:
Are the titles misleading?
fxm
Moderator
Posts: 12222
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Profiling freebasic programs

Post by fxm »

SARG wrote: May 28, 2024 13:09 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
Posts: 1792
Joined: May 27, 2005 7:15
Location: FRANCE

Re: Profiling freebasic programs

Post by SARG »

fxm wrote: May 28, 2024 16:27 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
Moderator
Posts: 12222
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Profiling freebasic programs

Post by fxm »

fxm wrote: May 21, 2024 9:23
coderJeff wrote: May 18, 2024 11:52 '-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
Posts: 305
Joined: Nov 07, 2019 20:08

Re: Profiling freebasic programs

Post by 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
Posts: 1792
Joined: May 27, 2005 7:15
Location: FRANCE

Re: Profiling freebasic programs

Post by 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
Posts: 8014
Joined: Jan 10, 2006 20:30
Location: Scotland

Re: Profiling freebasic programs

Post by 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).
Post Reply