It is currently Fri Jul 19, 2019 5:10 am

All times are UTC + 1 hour




Post new topic Reply to topic  [ 12 posts ] 
Author Message
 Post subject: Poor (wo)man's time profiling
PostPosted: Mon Dec 31, 2018 1:26 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
Hi,

since we don't have many options for doing time profiling with our PB code, here is another one, which has already proved useful to me.

  • Main advantages: Flexible and simple (this also means e.g. that it is cross-platform, and compatible with ASCII as well as Unicode compilation).
  • Main disadvantage: You'll have to manually insert commands before and after each code block in your program of which you want to measure the execution time.

Code:
; Poor (wo)man's time profiling for PB, version 1.41
; Cross-platform (tested with PB 5.62 and PB 5.70 LTS on Windows 10 and Linux Mint 19.1 Cinnamon)
; <https://www.purebasic.fr/english/viewtopic.php?f=12&t=72017>

; INCLUDE THIS FILE in your program.
; At the beginning of your program and/or module, write '#TimeProfile = #True'.
; Note that this line written inside of a module does not take effect outside
; of the module, and vice versa (it's the same as with 'EnableExplicit').
; The code in this module only takes effect if the DEBUGGER is OFF, because
; measuring execution time otherwise doesn't make sense.

DeclareModule TimeProfile
   EnableExplicit
   
   ; Call the following two macros pairwise with the same name before and
   ; after each code block in your program of which you want to measure
   ; the execution time.
   ;
   ; When there are *sequential* calls with the same name, e.g.
   ;    Start("This")
   ;    <code>
   ;    Stop("This")
   ;    <code>
   ;    Start("This")
   ;    <code>
   ;    Stop("This")
   ; then all measured times for "This" will be added.
   ;
   ; When there are *nested* calls with the same name, e.g.
   ;    Start("That")
   ;    <code>
   ;    Start("That")
   ;    <code>
   ;    Stop("That")
   ;    <code>
   ;    Stop("That")
   ; then only the outer calls of Start() and Stop() are
   ; taken into account for the time measurement.
   
   Macro Start (_name_)
      CompilerIf Defined(TimeProfile, #PB_Constant)
         CompilerIf #TimeProfile = #True And #PB_Compiler_Debugger = #False
            TimeProfile::_Start(#PB_Compiler_Module, _name_)
         CompilerEndIf
      CompilerEndIf
   EndMacro
   
   Macro Stop (_name_)
      CompilerIf Defined(TimeProfile, #PB_Constant)
         CompilerIf #TimeProfile = #True And #PB_Compiler_Debugger = #False
            TimeProfile::_Stop(#PB_Compiler_Module, _name_)
         CompilerEndIf
      CompilerEndIf
   EndMacro
   
   
   ; Show the results of the time measurements, and reset the state of the module.
   
   Macro Results (_title_="")
      CompilerIf Defined(TimeProfile, #PB_Constant)
         CompilerIf #TimeProfile = #True And #PB_Compiler_Debugger = #False
            TimeProfile::_Results(_title_)
         CompilerEndIf
      CompilerEndIf
   EndMacro
   
   
   ; Reset the state of the module, without showing the results
   ; (only needed in special cases).
   
   Macro Clear ()
      CompilerIf Defined(TimeProfile, #PB_Constant)
         CompilerIf #TimeProfile = #True And #PB_Compiler_Debugger = #False
            TimeProfile::_Clear()
         CompilerEndIf
      CompilerEndIf
   EndMacro
   
   
   ; Do not call the following procedures directly.
   Declare _Start(modul$, name$)
   Declare _Stop (modul$, name$)
   Declare _Results(title$)
   Declare _Clear()
EndDeclareModule


Module TimeProfile
   #Title$ = "Time profile"
   
   Structure MeasureTime
      CurStart.q
      CurStop.q
      Called.i
      Level.i
      Error.i
   EndStructure
   
   Structure DisplayTime
      Name$
      DurationAbs.q
      DurationRel.d
      Called.i
   EndStructure
   
   Global NewMap gTimeProfile.MeasureTime()
   Global.i gProfilingIsActive = #False
   Global.q gTotalStart, gTotalStop
   
   
   Procedure _Start (modul$, name$)
      If Asc(modul$) <> ''
         name$ = modul$ + "::" + name$
      EndIf   
     
      If gTimeProfile(name$)\Level = 0
         gTimeProfile()\CurStart = ElapsedMilliseconds()
         If gProfilingIsActive = #False
            gProfilingIsActive = #True
            gTotalStart = gTimeProfile()\CurStart
         EndIf   
      EndIf
      gTimeProfile()\Called + 1
      gTimeProfile()\Level + 1
   EndProcedure
   
   
   Procedure _Stop (modul$, name$)
      If Asc(modul$) <> ''
         name$ = modul$ + "::" + name$
      EndIf   
     
      gTimeProfile(name$)\Level - 1
      If gTimeProfile()\Level = 0
         gTotalStop = ElapsedMilliseconds()
         gTimeProfile()\CurStop = gTotalStop
      ElseIf gTimeProfile()\Level < 0
         gTotalStop = ElapsedMilliseconds()
         gTimeProfile()\Error = #True
      EndIf
   EndProcedure
   
   
   Procedure _Clear()
      ClearMap(gTimeProfile())
      gProfilingIsActive = #False
   EndProcedure
   
   ; ---------------------------------------------------------------------------
   
   Procedure.s _RAlign (s$, width.i)
      If Len(s$) >= width
         ProcedureReturn s$
      Else
         ProcedureReturn RSet(s$, width)
      EndIf
   EndProcedure
   
   Procedure.s _FormatTime (ms.i)
      ; in : duration expressed in milliseconds
      ; out: duration expressed in milliseconds, seconds, minutes or hours as appropriate
      Protected ret$
     
      If ms < 1000
         ret$ = ReplaceString(RSet(Str(ms), 3), " ", "  ") + " ms"
      ElseIf ms < 60000
         ret$ = StrD(ms/1000, 1) + " Sec."
      ElseIf ms < 3600000
         ret$ = StrD(ms/60000, 1) + " Min."
      Else
         ret$ = StrD(ms/3600000, 1) + " Hrs."
      EndIf
     
      ProcedureReturn ret$
   EndProcedure
   
   
   #WinMain = 0
   
   Enumeration      ; Gadgets
      #ListIcon
      #Text
      #Editor
   EndEnumeration
   
   #ListIcon_Width  = 60 + 3*80 + 250 + 10
   #ListIcon_Height = 250
   #Editor_Height   = 80
   #WinMain_Width   = #ListIcon_Width  + 20
   #WinMain_Height  = #ListIcon_Height + 50 + #Editor_Height + 10
   
   Procedure _Results (title$)
      Protected msg$, item$, totalDuration.q, error.i=#False
      Protected NewList profile.DisplayTime()
     
      If title$ = ""
         title$ = #Title$
      EndIf
     
      If OpenWindow(#WinMain, 0, 0, #WinMain_Width, #WinMain_Height, title$,
                    #PB_Window_MinimizeGadget|#PB_Window_ScreenCentered|#PB_Window_Invisible) = 0
         msg$ = "Couldn't open main window." + #LF$ +
                #LF$ +
                "Program terminated."
         MessageRequester(#Title$, msg$, #PB_MessageRequester_Error)
         End
      EndIf
     
      ListIconGadget (#ListIcon, 10, 10, #ListIcon_Width, #ListIcon_Height, " % Time", 60,
                      #PB_ListIcon_GridLines|#PB_ListIcon_FullRowSelect|#PB_ListIcon_MultiSelect)
      AddGadgetColumn(#ListIcon, 1, " Time", 80)
      AddGadgetColumn(#ListIcon, 2, "  Called", 80)
      AddGadgetColumn(#ListIcon, 3, " Time/Call", 80)
      AddGadgetColumn(#ListIcon, 4, " Name", 250)
      TextGadget     (#Text,   10, #ListIcon_Height+30, #WinMain_Width-20, 20, "Error - unbalanced calls of Start() and Stop():")
      EditorGadget   (#Editor, 10, #ListIcon_Height+50, #WinMain_Width-20, #Editor_Height, #PB_Editor_ReadOnly)
     
      totalDuration = gTotalStop - gTotalStart
     
      ForEach gTimeProfile()
         If gTimeProfile()\Error = #True Or gTimeProfile()\Level <> 0
            error = #True
            AddGadgetItem(#Editor, -1, MapKey(gTimeProfile()))
         Else
            AddElement(profile())
            profile()\Name$ = MapKey(gTimeProfile())
            profile()\DurationAbs = gTimeProfile()\CurStop - gTimeProfile()\CurStart
            If totalDuration > 0
               profile()\DurationRel = profile()\DurationAbs / totalDuration
            Else
               profile()\DurationRel = 1.0
            EndIf
            profile()\Called = gTimeProfile()\Called
         EndIf
      Next
     
      ClearMap(gTimeProfile())
      gProfilingIsActive = #False
     
      SortStructuredList(profile(), #PB_Sort_Descending, OffsetOf(DisplayTime\DurationRel), TypeOf(DisplayTime\DurationRel))
     
      ; Add the 'Total' line to the ListIconGadget
      item$ = "100.0" + #LF$ + _FormatTime(totalDuration) + #LF$ + Space(11) + "---" + #LF$ +
              "---" + #LF$ + "From first call of Start() to last call of Stop()"
      AddGadgetItem(#ListIcon, -1, item$)
     
      ; Add the results of all time measurements to the ListIconGadget
      ForEach profile()
         item$ = ReplaceString(RSet(StrD(100 * profile()\DurationRel, 1), 5), " ", "  ") + #LF$ +
                 _FormatTime(profile()\DurationAbs) + #LF$ +
                 ReplaceString(_RAlign(Str(profile()\Called), 8), " ", "  ") + #LF$ +
                 _FormatTime(profile()\DurationAbs / profile()\Called) + #LF$ +
                 " " + profile()\Name$
         
         AddGadgetItem(#ListIcon, -1, item$)
      Next
     
      If error = #False
         HideGadget(#Text, #True)
         HideGadget(#Editor, #True)
         ResizeGadget(#ListIcon, #PB_Ignore, #PB_Ignore, #PB_Ignore, #WinMain_Height-20)
      EndIf
     
      SetGadgetState(#ListIcon, 0)
      SetActiveGadget(#ListIcon)
      HideWindow(#WinMain, #False)
     
      Repeat
      Until WaitWindowEvent() = #PB_Event_CloseWindow
     
      CloseWindow(#WinMain)
   EndProcedure
EndModule


CompilerIf #PB_Compiler_IsMainFile
   ; -- Demo
   
   DeclareModule MyModule
      EnableExplicit
      #TimeProfile = #True
     
      Declare MyProc (n.i)
   EndDeclareModule
   
   Module MyModule
      Procedure MyProc (n.i)
         Protected i.i
         
         TimeProfile::Start("MyProc")
         
         If n <= 0
            Delay(10)
            TimeProfile::Stop("MyProc")
            ProcedureReturn
         EndIf
         
         For i = 1 To n
            Delay(2)
         Next
         
         TimeProfile::Stop("MyProc")
         ProcedureReturn
      EndProcedure
   EndModule
   
   
   EnableExplicit
   #TimeProfile = #True
   
   ; First time profiling section
   TimeProfile::Start("Foo")
   Delay(500)
   TimeProfile::Stop("Foo")
   
   MyModule::MyProc(100)
   
   TimeProfile::Results()
   
   ; Another time profiling section, independent from the first one
   TimeProfile::Start("Bar")
   Delay(300)
   TimeProfile::Stop("Bar")
   
   TimeProfile::Results("My title")
CompilerEndIf

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Last edited by Little John on Tue Mar 05, 2019 9:33 pm, edited 7 times in total.

Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Tue Jan 01, 2019 2:41 pm 
Offline
Addict
Addict

Joined: Thu Aug 30, 2007 11:54 pm
Posts: 1007
Location: right here
Very nice, Thanks!
I hope you don't mind if I share a similar module here. It doesn't have the nice results window, but it can stop/resume timers and can give you an info string about timers for easy debugging. The example code uses the debugger for simple output, so enable it to see something.
Happy new year :D
Code:
DeclareModule stopwatch
  EnableExplicit
 
  Declare   reset(name.s)
  Declare.q elapsed(name.s)
  Declare.q resume(name.s)
  Declare   restart(name.s)
  Declare.q stop(name.s)
  Declare.s info(name.s)
  Declare.q stopDebugInfo(name.s)
  Declare.s stopGetInfo(name.s)
  Declare   remove(name.s)
 
EndDeclareModule

Module stopwatch
  EnableExplicit
 
  Structure sStopwatch
    running.i
    timeStarted.q
    timeStopped.q
    timeElapsed.q
    timeElapsedTotal.q
  EndStructure
 
  Global NewMap stopwatch.sStopwatch()
 
  ; reset and stop
  Procedure reset(name.s)
    stopwatch(name)\running = #False
    stopwatch(name)\timeStarted = 0
    stopwatch(name)\timeStopped = 0
    stopwatch(name)\timeElapsed = 0
    stopwatch(name)\timeElapsedTotal = 0
  EndProcedure
 
  ; return elapsed
  Procedure.q elapsed(name.s)
    If stopwatch(name)\running
      ProcedureReturn stopwatch(name)\timeElapsedTotal + (ElapsedMilliseconds() - stopwatch(name)\timeStarted)
    Else
      ProcedureReturn stopwatch(name)\timeElapsedTotal
    EndIf
  EndProcedure
 
  ; start or resume
  Procedure.q resume(name.s)
    If Not stopwatch(name)\running
      stopwatch(name)\running = #True
      stopwatch(name)\timeStarted = ElapsedMilliseconds()
      stopwatch(name)\timeStopped = 0
      stopwatch(name)\timeElapsed = 0
      ;stopwatch(name)\timeElapsedTotal = 0  ; (keep total)
    EndIf
    ProcedureReturn elapsed(name)
  EndProcedure
 
  ; reset and start
  Procedure restart(name.s)
    reset(name)
    resume(name)
  EndProcedure
 
  ; stop and return elapsed
  Procedure.q stop(name.s)
    If stopwatch(name)\running
      stopwatch(name)\timeStopped = ElapsedMilliseconds()
      stopwatch(name)\timeElapsed = stopwatch(name)\timeStopped - stopwatch(name)\timeStarted
      stopwatch(name)\timeElapsedTotal + stopwatch(name)\timeElapsed
      stopwatch(name)\running = #False
    EndIf
    ProcedureReturn elapsed(name)
  EndProcedure
 
  ; return info string
  Procedure.s info(name.s)
    If stopwatch(name)\running
      ProcedureReturn "stopwatch '" + name + "' running. elapsed: " + elapsed(name)
    Else
      ProcedureReturn "stopwatch '" + name + "' stopped. elapsed: " + elapsed(name)
    EndIf
  EndProcedure
 
  ; stop, debug info string and return elapsed (debugger required)
  Procedure.q stopDebugInfo(name.s)
    stop(name)
    Debug info(name)
    ProcedureReturn elapsed(name)
  EndProcedure
 
  ; stop and return info string (i.e. for console print without debugger)
  Procedure.s stopGetInfo(name.s)
    stop(name)
    ProcedureReturn info(name)
  EndProcedure
 
  ; remove map element
  Procedure remove(name.s)
    DeleteMapElement(stopwatch(), name)
  EndProcedure
 
EndModule

CompilerIf #PB_Compiler_IsMainFile
  Debug "[" + #PB_Compiler_Filename + "]"
  EnableExplicit
 
  ;XIncludeFile "stopwatch.pb"
 
  ; test functions
  stopwatch::restart("sw 1")
  Delay(100)
  Debug stopwatch::elapsed("sw 1")                     ; 100
  Delay(100)
  Debug stopwatch::info("sw 1")                        ; stopwatch 'sw 1' running. elapsed: 200
  Delay(100)
  stopwatch::stopDebugInfo("sw 1")                     ; stopwatch 'sw 1' stopped. elapsed: 300
  Delay(100)
  Debug stopwatch::elapsed("sw 1")                     ; 300
  Debug stopwatch::resume("sw 1")                      ; 300
  Delay(100)
  Debug stopwatch::info("sw 1")                        ; stopwatch 'sw 1' running. elapsed: 400
  Delay(100)
  Debug stopwatch::stopGetInfo("sw 1")                 ; stopwatch 'sw 1' stopped. elapsed: 500
  Delay(100)
  stopwatch::reset("sw 1")
  Debug stopwatch::info("sw 1")                        ; stopwatch 'sw 1' stopped. elapsed: 0
  stopwatch::remove("sw 1")
  Debug "----------"                                   ; ----------
  ; test overlapping
  stopwatch::restart("sw 2")
  Delay(100)
  stopwatch::restart("sw 3")
  Delay(100)
  stopwatch::stop("sw 2")
  Delay(100)
  stopwatch::stop("sw 3")
  Delay(100)
  Debug stopwatch::info("sw 2")                        ; stopwatch 'sw 2' stopped. elapsed: 200
  Debug stopwatch::info("sw 3")                        ; stopwatch 'sw 3' stopped. elapsed: 200
  Delay(100)
  Debug stopwatch::info("sw 2")                        ; stopwatch 'sw 2' stopped. elapsed: 200
  Debug stopwatch::info("sw 3")                        ; stopwatch 'sw 3' stopped. elapsed: 200
  stopwatch::remove("sw 2")
  stopwatch::remove("sw 3")
  Debug "----------"                                   ; ----------
  ; test without restart/reset
  Debug stopwatch::info("sw a")                        ; stopwatch 'sw a' stopped. elapsed: 0
  Debug stopwatch::stopGetInfo("sw b")                 ; stopwatch 'sw b' stopped. elapsed: 0
  stopwatch::stopDebugInfo("sw c")                     ; stopwatch 'sw c' stopped. elapsed: 0
  Debug stopwatch::elapsed("sw d")                     ; 0
  Debug stopwatch::resume("sw e")                      ; 0
  Delay(100)
  Debug stopwatch::resume("sw e")                      ; 100
  Delay(100)
  Debug stopwatch::stop("sw e")                        ; 200
  Delay(100)
  Debug stopwatch::resume("sw e")                      ; 200
  Delay(100)
  Debug stopwatch::stopGetInfo("sw e")                 ; stopwatch 'sw e' stopped. elapsed: 300
 
  Debug stopwatch::stop("sw f")                        ; 0
  Delay(100)
  Debug stopwatch::resume("sw f")                      ; 0
  Delay(100)
  Debug stopwatch::stop("sw f")                        ; 100
 
  stopwatch::remove("sw xyz")
CompilerEndIf



Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Tue Jan 01, 2019 7:29 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
Nice, thank you.
Happy new year to you, too!

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sun Jan 27, 2019 1:59 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
New version 1.10, 2019-01-27

Changes
  • Renamed Update() to Stop() and _Update() to _Stop().

New
  • In the output window, added columns "Called" and "Time/Call".

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sun Jan 27, 2019 5:08 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Feb 09, 2006 11:27 pm
Posts: 2430
Like it :lol:

I would hide the error part in the result dialog when no error exists...

Code:
   Procedure _Results ()
      
      Protected total.q, msg$, item$
      Protected NewList profile.TimeProfileStruc()
      Protected Errors.i

      If TimeProfile("Total")\Error = #True Or TimeProfile()\Level <> 0
         msg$ = ~"Both Start(\"Total\") and Stop(\"Total\") must be called exactly once." + #LF$ +
         #LF$ +
         "Program terminated."
         MessageRequester(#Title$, msg$, #PB_MessageRequester_Error)
         End
      EndIf

      If OpenWindow(#WinMain, 0, 0, #WinMain_Width, #WinMain_Height, #Title$, #PB_Window_MinimizeGadget|#PB_Window_ScreenCentered|#PB_Window_Invisible) = 0
         msg$ = "Couldn't open main window." + #LF$ +
         #LF$ +
         "Program terminated."
         MessageRequester(#Title$, msg$, #PB_MessageRequester_Error)
         End
      EndIf

      ListIconGadget (#ListIcon, 10, 10, #ListIcon_Width, #ListIcon_Height, " % Time", 60, #PB_ListIcon_GridLines|#PB_ListIcon_FullRowSelect|#PB_ListIcon_MultiSelect)
      AddGadgetColumn(#ListIcon, 1, " Time", 70)
      AddGadgetColumn(#ListIcon, 2, "  Called", 70)
      AddGadgetColumn(#ListIcon, 3, " Time/Call", 70)
      AddGadgetColumn(#ListIcon, 4, " Name", 200)
      TextGadget     (#Text,   10, #ListIcon_Height+30, #WinMain_Width-20, 20, "No error.")
      EditorGadget   (#Editor, 10, #ListIcon_Height+50, #WinMain_Width-20, #Editor_Height, #PB_Editor_ReadOnly)

      total = TimeProfile("Total")\DurationAbs

      ForEach TimeProfile()
         If TimeProfile()\Error = #True Or TimeProfile()\Level <> 0
            Errors+1
            SetGadgetText(#Text, "Error - unbalanced calls of Start() and Stop():")
            AddGadgetItem(#Editor, -1, MapKey(TimeProfile()))
         Else
            AddElement(profile())
            profile()\Name$ = MapKey(TimeProfile())
            profile()\DurationAbs = TimeProfile()\DurationAbs
            If total > 0
               profile()\DurationRel = profile()\DurationAbs / total
            Else
               profile()\DurationRel = 1.0
            EndIf
            profile()\Called = TimeProfile()\Called
         EndIf
      Next

      SortStructuredList(profile(), #PB_Sort_Descending, OffsetOf(TimeProfileStruc\DurationRel), TypeOf(TimeProfileStruc\DurationRel))

      ForEach profile()
         item$ = ReplaceString(RSet(StrD(100 * profile()\DurationRel, 1), 5), " ", "  ") + #LF$
         item$ + _FormatTime(profile()\DurationAbs) + #LF$
         item$ + ReplaceString(_RAlign(Str(profile()\Called), 8), " ", "  ") + #LF$
         item$ + _FormatTime(profile()\DurationAbs / profile()\Called) + #LF$
         item$ + " " + profile()\Name$

         AddGadgetItem(#ListIcon, -1, item$)
      Next
      
      If Errors=#Null
         HideGadget(#Text,1)
         HideGadget(#Editor,1)
         ResizeGadget(#ListIcon,#PB_Ignore,#PB_Ignore,#PB_Ignore,#WinMain_Height-20)
      EndIf
      
      SetGadgetState(#ListIcon, 0)
      SetActiveGadget(#ListIcon)
      HideWindow(#WinMain,0)
      
      Repeat
      Until WaitWindowEvent() = #PB_Event_CloseWindow
   EndProcedure


Another simple extension would be to include procedure names automatically...

Code:
Macro Start (_name_)
   :
   TimeProfile::_Start(_name_,#PB_Compiler_Procedure)
   :
EndMacro

Structure TimeProfileStruc
   :
   Modul.s
   :
EndStructure

Procedure _Start (name$,modul.s)
   If TimeProfile(name$)\Level = 0
      TimeProfile()\CurStart = ElapsedMilliseconds()
   EndIf
   TimeProfile()\Modul=modul
   :
EndProcedure

Procedure _Results ()
   :
   AddGadgetColumn(#ListIcon, 4, " Name", 120)
   AddGadgetColumn(#ListIcon, 5, " Modul", 120)
   :
   profile()\Name$ = MapKey(TimeProfile())
   profile()\Modul = TimeProfile()\Modul
   :
   item$ + " " + profile()\Name$+#LF$
   item$ + " " + profile()\Modul
   :
EndProcedure


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sun Jan 27, 2019 8:00 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
Hi Michael,

thank you for your good suggestions! I just posted a new version. :-)

Module names are included automatically now, but not as a separate structure field. They are now prepended to the name that is chosen for the time measurement block, similar to the way PB does do it itself with module names. So if someone (by accident) writes e.g. TimeProfile::Start("Foo") not only in one module, but also in another module, there still will be no naming conflict for my little tool. :-)

New version 1.20, 2019-01-27

Changes
  • In the results window, the panel for error messages is now only shown if there are actually errors.

New
  • If a block for time measurement is inside of a module, then the self-chosen name for that block is automatically prepended with "<modulename>::".

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sat Feb 09, 2019 10:35 pm 
Offline
Addict
Addict

Joined: Fri Nov 09, 2012 11:04 pm
Posts: 1660
Location: Uttoxeter, UK
Hi Little John,
Earlier tonight I tested the timing module: It is very good. Thank you.

However, when I tested this on my MacBook the program crashed.
I noticed that this was due to me missing both 'Totals'.
This is not an oblique complaint with your instructions; they are clear.
I didn't read them. :oops:

_________________
DE AA EB


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sun Feb 10, 2019 3:30 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
Hello davido,

thank you for your kind words, and for reporting that issue.
I just posted a new version, which has extended error checking. :-)
Since to err is human, I think software should assist us in this regard whenever possible.
And since you drew my attention to Start("Total") and Stop("Total"), I found a related bug. Thank you!


New version 1.30, 2019-02-10

Fixed
  • Due to changes made in the previous version, time profiling did not work anymore if Start("Total") and Stop("Total") were called inside of a module.

Changed
  • Extended error checking.
  • Extended demo code, that also demonstrates how to use this module with other modules.
  • Improved documentation, especially in regard to usage of this modiule with other modules.

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sun Feb 10, 2019 5:22 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Feb 09, 2006 11:27 pm
Posts: 2430
Wouldn't a total result of the time between the first starttimer and last stoptimer event easier for to handle?

For me I did something like this, but this is also too complicate...
Code:
   Global TotalFlag
   #TotalName="Total"

   Macro Start (_name_)
      CompilerIf Defined(TimeProfile,#PB_Constant)
         CompilerIf #TimeProfile = #True And #PB_Compiler_Debugger = #False
            If TimeProfile::TotalFlag=0
               If _name_<>TimeProfile::#TotalName
                  TimeProfile::_Start("",TimeProfile::#TotalName)
               Else
                  TimeProfile::TotalFlag=#True
               EndIf
            EndIf
            TimeProfile::_Start(#PB_Compiler_Module, _name_)
         CompilerEndIf
      CompilerEndIf
   EndMacro


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Sun Feb 10, 2019 7:22 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
Michael Vogel wrote:
Wouldn't a total result of the time between the first starttimer and last stoptimer event easier for to handle?

Great idea! :idea: I didn't think of that. :oops:
That will make things simpler! I'll implement it in the next version.
Thank you!

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Mon Feb 11, 2019 7:41 am 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
New version 1.40, 2019-02-11

Changed
  • Removed the need to call Start("Total") and Stop("Total")
    and all related error checks that I introduced in the previous version. :-)
  • Slightly increased the column widths of the output window.
  • Simplified the demo code a bit.

Thanks again to davido and Michael for the idea of doing without Start("Total") and Stop("Total").
That makes it considerably simpler and clearer!
It seems that I couldn't see the wood for the trees. :D

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
 Post subject: Re: Poor (wo)man's time profiling
PostPosted: Tue Mar 05, 2019 9:39 pm 
Offline
Addict
Addict
User avatar

Joined: Thu Jun 07, 2007 3:25 pm
Posts: 3598
Location: Berlin, Germany
New version 1.41, 2019-03-05

Often, I'm using this module once for a whole program, i.e. I'm calling TimeProfile::Results() only at the end of the program. However, sometimes I find it useful to do time profiling in several sections of a program independently from each other, i.e. calling TimeProfile::Results() multiple times in the program. This is now better supported in the current version.

Fixed
  • Added missing CloseWindow(#WinMain) after the event loop.

Changed
  • You can now optionally pass your own title for the output window to the public Macro Results().
  • Demo code a bit extended.
  • Comments slightly improved.

New
  • Public Macro Clear() for resetting the state of the module, without showing the results.

_________________
Please excuse my flawed English. My native language is PureBasic.
Search
RSBasic's backups


Top
 Profile  
Reply with quote  
Display posts from previous:  Sort by  
Post new topic Reply to topic  [ 12 posts ] 

All times are UTC + 1 hour


Who is online

Users browsing this forum: Majestic-12 [Bot] and 5 guests


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
Jump to:  

 


Powered by phpBB © 2008 phpBB Group
subSilver+ theme by Canver Software, sponsor Sanal Modifiye