Page 1 of 1

time profiler

Posted: Wed Mar 15, 2023 1:22 am
by idle
A simple tool to facilitate time profiling via macros supports x86/x64 c and asm backends note times and cycle counts are approximate, though they will be fairly accurate for purpose of profiling code.

compile your exe as console

example results for the procedures foo bar and main
CPU Frequency 2.75 ghz
foo sum time 685 ms avg cycles 18,614,901 0
main sum time 685 ms avg cycles 1,861,570,995 0
bar sum time 677 ms avg cycles 18,396 0
main elapsed ms check 686
press any key to end
To use just add BeginProfile and EndProfile blocks, they will only compile in if #ENABLE_PROFILE=1
see example
Procedure bar()
Protected b

BeginProfile("bar") ;add this and the procedure name it will only compile if #ENABLE_PROFILE=1
For a = 1 To 10000
b*a
Next
Endprofile("bar")

EndProcedure

Code: Select all


;Time profiler   
;Author Idle 
;PB LTS 6.01 x86,x64 asm and c backend 
;v1.01b
;Notes Cycle counts are indicative of relative performance and times are approximate  
;If the time cpu time stamp rolls over it subtracts from the count and adds to the err  
;compile As console

#ENABLE_PROFILE=1   ;Enables profiler or to disable ENABLE_PROFILE=0   

CompilerIf #ENABLE_PROFILE=1
  
  CompilerIf Defined(PB_Compiler_Backend,#PB_Constant) 
    CompilerIf #PB_Compiler_Backend=#PB_Backend_C
      Procedure GetRDTSC()
        Protected t.q
        !unsigned hi, lo;
        !__asm__ __volatile__ ("lfence\n rdtsc\n lfence" : "=a"(lo), "=d"(hi));
        !v_t =((unsigned long long)lo)|(((unsigned long long)hi)<<32 );
        ProcedureReturn t
      EndProcedure
    CompilerElse
      Procedure.q GetRDTSC()
        Protected hi.q,lo.q,res.q 
        DisableDebugger
        !lfence 
        !rdtsc
        !lfence
        !mov [p.v_hi], edx
        !mov [p.v_lo], eax 
        res = hi
        res << 32
        res | lo
        ProcedureReturn res
        EnableDebugger 
      EndProcedure
    CompilerEndIf
  CompilerElse
    Procedure.q GetRDTSC()
      Protected hi.q,lo.q,res.q 
      DisableDebugger
      !lfence 
      !rdtsc
      !lfence
      !mov [p.v_hi], edx
      !mov [p.v_lo], eax 
      res = hi
      res << 32
      res | lo
      EnableDebugger 
    EndProcedure
  CompilerEndIf  
  
  Procedure.q GetFrequency() 
    Protected t1.q,t2.q,result 
    Repeat     
      t1 = GetRDTSC()
      Delay(128) 
      t2 = GetRDTSC()
      If t2 - t1 > 0 
        result = ((t2-t1) / (128)) 
        Break  
      EndIf    
    ForEver 
    ProcedureReturn result 
  EndProcedure   
  
  Structure profile 
    count.i
    err.i
    sumtime.q 
    st.q
    et.q 
  EndStructure 
  
  Global NewMap prof.profile() 
  Global prof_msfreq.i = GetFrequency() 
  
  Macro BeginProfile(name) 
    
    prof(name)\count + 1 
    prof(name)\st = GetRDTSC() 
    
  EndMacro 
  
  Macro EndProfile(name) 
    
    prof(name)\et = GetRDTSC() 
    If prof(name)\et > prof(name)\st 
      prof()\sumtime + prof(name)\et - prof(name)\st
    Else  
      prof()\count - 1    ;ignore rollover if st > et    
      prof()\err + 1      ;indicates a timeing error     
    EndIf   
    
  EndMacro   
  
  Macro PrintProfile() 
    
    PrintN("CPU Frequency " + FormatNumber(prof_msfreq/1000000.0,2,".",",") + " ghz") 
    ForEach prof()  
      If prof()\count 
        PrintN(MapKey(prof())  + " sum time " + FormatNumber(prof()\sumtime / prof_msfreq ,0,".",",") + " ms avg cycles " + FormatNumber(prof()\sumtime / prof()\count,0,".",",") + " " + Str(prof()\err )) 
      EndIf   
    Next 
    
  EndMacro    
  
CompilerElse 
  
  Macro BeginProfile(name) : EndMacro 
  Macro EndProfile(name) : EndMacro 
  Macro PrintProfile() : EndMacro 
  
CompilerEndIf   

CompilerIf #PB_Compiler_IsMainFile 
  ;example 
  
  Procedure bar() 
    Protected b 
    BeginProfile(#PB_Compiler_Procedure)  ;Add BeginProfile / EndProfile blocks to code you want to time it will only compile if #ENABLE_PROFILE=1 is declared  
    For a = 1 To 10000 
      b*a  
    Next   
    EndProfile(#PB_Compiler_Procedure)     
  EndProcedure   
  
  Procedure foo() 
    Protected b 
    BeginProfile(#PB_Compiler_Procedure) 
    For a = 1 To 1000 
      b * 2 
      bar()
     Next 
    EndProfile(#PB_Compiler_Procedure) 
  EndProcedure   
  
  OpenConsole()
  
  BeginProfile(#PB_Compiler_Procedure) 
  st = ElapsedMilliseconds() 
  For a = 1 To 100 
    foo() 
  Next 
  et = ElapsedMilliseconds() 
  EndProfile(#PB_Compiler_Procedure) 
  
  PrintProfile() ; dump profile results           
  
  PrintN("main elapsed ms check " + Str(et-st)) 
  PrintN("press enter key to end") 
  Input() 
  
CompilerEndIf 



Re: time profiler

Posted: Wed Mar 15, 2023 4:03 pm
by Fred
Looks nice ! You can use #PB_Compiler_Procedure to get the current procedure name:

Code: Select all

BeginProfile(#PB_Compiler_Procedure)

Re: time profiler

Posted: Wed Mar 15, 2023 9:45 pm
by idle
Fred wrote: Wed Mar 15, 2023 4:03 pm Looks nice ! You can use #PB_Compiler_Procedure to get the current procedure name:

Code: Select all

BeginProfile(#PB_Compiler_Procedure)
Thanks that will make it simpler to automate. I found code to get cycle count on arm so will try it on a PI

can someone test this on a PI4 and M1
I tried on Pi3 but it appears I need to compile a kernel module to make the counters available.
info for pi 3
https://forums.raspberrypi.com/viewtopic.php?p=267700
https://matthewarcus.wordpress.com/2018 ... erry-pi-3/

Code: Select all


;Time profiler   
;Author Idle 
;PB LTS 6.01 x86,x64 asm and c backend 
;v1.02a
;Notes Cycle counts are indicative of relative performance and times are approximate  
;If the time cpu time stamp rolls over it subtracts from the count and adds to the err  
;compile As console

#ENABLE_PROFILE=1   ;Enables profiler or to disable ENABLE_PROFILE=0   

CompilerIf #ENABLE_PROFILE=1
  
  CompilerIf Defined(PB_Compiler_Backend,#PB_Constant) 
    CompilerIf #PB_Compiler_Backend=#PB_Backend_C
      CompilerIf #PB_Compiler_Processor = #PB_Processor_x64 Or #PB_Compiler_Processor = #PB_Processor_x86 
        Procedure.q GetRDTSC()
          Protected t.q
          !unsigned hi, lo;
          !__asm__ __volatile__ ("lfence\n rdtsc\n lfence" : "=a"(lo), "=d"(hi));
          !v_t =((unsigned long long)lo)|(((unsigned long long)hi)<<32 );
          ProcedureReturn t
        EndProcedure
      CompilerElseIf #PB_Compiler_Processor = #PB_Processor_Arm64 Or #PB_Compiler_Processor = #PB_Processor_Arm32 
        Procedure.q GetRDTSC()
        Protected pmuseren.l,pmcntenset.l,pmccntr.l;
        !asm volatile("mrc p15, 0, %0, c9, c14, 0" : "=r"(v_pmuseren));
        If pmuseren & 1 
          !asm volatile("mrc p15, 0, %0, c9, c12, 1" : "=r"(v_pmcntenset));
          If pmcntenset & $80000000 
            !asm volatile("mrc p15, 0, %0, c9, c13, 0" : "=r"(v_pmccntr));
            t = pmccntr
            ProcedureReturn t << 6 
          EndIf 
        EndIf 
        EndProcedure 
     CompilerEndIf 
    CompilerElse
      Procedure.q GetRDTSC()
        Protected hi.q,lo.q,res.q 
        DisableDebugger
        !lfence 
        !rdtsc
        !lfence
        !mov [p.v_hi], edx
        !mov [p.v_lo], eax 
        res = hi
        res << 32
        res | lo
        ProcedureReturn res
        EnableDebugger 
      EndProcedure
    CompilerEndIf
  CompilerElse
    Procedure.q GetRDTSC()
      Protected hi.q,lo.q,res.q 
      DisableDebugger
      !lfence 
      !rdtsc
      !lfence
      !mov [p.v_hi], edx
      !mov [p.v_lo], eax 
      res = hi
      res << 32
      res | lo
      EnableDebugger 
    EndProcedure
  CompilerEndIf  
  
  Procedure.q GetFrequency() 
    Protected t1.q,t2.q,result 
    Repeat     
      t1 = GetRDTSC()
      Delay(128) 
      t2 = GetRDTSC()
      If t2 - t1 > 0 
        result = ((t2-t1) / (128)) 
        Break  
      EndIf    
    ForEver 
    ProcedureReturn result 
  EndProcedure   
  
  Structure profile 
    count.i
    err.i
    sumtime.q 
    st.q
    et.q 
  EndStructure 
  
  Global NewMap prof.profile() 
  Global prof_msfreq.i = GetFrequency() 
  
  Macro BeginProfile(name) 
    
    prof(name)\count + 1 
    prof(name)\st = GetRDTSC() 
    
  EndMacro 
  
  Macro EndProfile(name) 
    
    prof(name)\et = GetRDTSC() 
    If prof(name)\et > prof(name)\st 
      prof()\sumtime + prof(name)\et - prof(name)\st
    Else  
      prof()\count - 1    ;ignore rollover if st > et    
      prof()\err + 1      ;indicates a timeing error     
    EndIf   
    
  EndMacro   
  
  Macro PrintProfile() 
    
    PrintN("CPU Frequency " + FormatNumber(prof_msfreq/1000000.0,2,".",",") + " ghz") 
    ForEach prof()  
      If prof()\count 
        PrintN(MapKey(prof())  + " sum time " + FormatNumber(prof()\sumtime / prof_msfreq ,0,".",",") + " ms avg cycles " + FormatNumber(prof()\sumtime / prof()\count,0,".",",") + " " + Str(prof()\err )) 
      EndIf   
    Next 
    
  EndMacro    
  
CompilerElse 
  
  Macro BeginProfile(name) : EndMacro 
  Macro EndProfile(name) : EndMacro 
  Macro PrintProfile() : EndMacro 
  
CompilerEndIf   

CompilerIf #PB_Compiler_IsMainFile 
  ;example 
  
  Procedure bar() 
    Protected b 
    BeginProfile(#PB_Compiler_Procedure)  ;Add BeginProfile / EndProfile blocks to code you want to time it will only compile if #ENABLE_PROFILE=1 is declared  
    For a = 1 To 10000 
      b*a  
    Next   
    EndProfile(#PB_Compiler_Procedure)     
  EndProcedure   
  
  Procedure foo() 
    Protected b 
    BeginProfile(#PB_Compiler_Procedure) 
    For a = 1 To 1000 
      b * 2 
      bar()
     Next 
    EndProfile(#PB_Compiler_Procedure) 
  EndProcedure   
  
  OpenConsole()
  
  BeginProfile(#PB_Compiler_Procedure) 
  st = ElapsedMilliseconds() 
  For a = 1 To 100 
    foo() 
  Next 
  et = ElapsedMilliseconds() 
  EndProfile(#PB_Compiler_Procedure) 
  
  PrintProfile() ; dump profile results           
  
  PrintN("main elapsed ms check " + Str(et-st)) 
  PrintN("press enter key to end") 
  Input() 
  
CompilerEndIf