Timer Macros

[David Roberts]

I've been using QueryPerformanceCounter a bit lately and I've noticed some posts using it of late.

Some of you may find the following handy.

#COMPILE  EXE
#Register None
#Dim      All
#TOOLS    OFF

%NOMMIDS = 1
%NOGDI = 1

#Include "WIN32API.INC"

'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Macro InitializeTimer
  Local qFreq, qOverhead, qStart, qStop As Quad
  Local f As String
  f = "#####.##"
  QueryPerformanceFrequency qFreq 
  QueryPerformanceCounter qStart ' Intel suggestion. First use may be suspect 
  QueryPerformanceCounter qStart ' So, wack it twice <smile>
  QueryPerformanceCounter qStop
  qOverhead = qStop - qStart     ' Relatively small 
End Macro

Macro StartTimer = QueryPerformanceCounter qStart
Macro StopTimer = QueryPerformanceCounter qStop

Macro TimeTaken = Using$(f,(qStop - qStart - qOverhead)*1000/qFreq) + "ms"
'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Function PBMain( ) As Long

  Local i, n As Long
  
  InitializeTimer
  
  StartTimer
  ' Example
  For i = 1 To 1000000
    n = Rnd(0,255)
  Next
  StopTimer
  
  MsgBox TimeTaken

END FUNCTION

[Gary Barnes]

Wonderful work David

I made a couple of mods to the code and now it tells you how long SLEEP takes to execute.

I wanted to know because I read somewhere that the sleep command can get a little inaccurate below 10ms.

On my machine SLEEP 0 takes a couple of microseconds to execute.

#COMPILE  EXE
#REGISTER NONE
#DIM      ALL
#TOOLS    OFF

%NOMMIDS = 1
%NOGDI = 1

#INCLUDE "WIN32API.INC"

'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
MACRO InitializeTimer
  LOCAL qFreq, qOverhead, qStart, qStop AS QUAD
  LOCAL f AS STRING
  f = "#####.##"
  QueryPerformanceFrequency qFreq
  QueryPerformanceCounter qStart ' Intel suggestion. First use may be suspect
  QueryPerformanceCounter qStart ' So, wack it twice <smile>
  QueryPerformanceCounter qStop
  qOverhead = qStop - qStart     ' Relatively small
END MACRO

MACRO StartTimer = QueryPerformanceCounter qStart
MACRO StopTimer = QueryPerformanceCounter qStop

MACRO TimeTaken = USING$(f,(qStop - qStart - qOverhead)*1000000/qFreq) + " micro seconds"
'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

FUNCTION PBMAIN( ) AS LONG

  LOCAL i, n AS LONG

  InitializeTimer

  ' Example
  StartTimer
  SLEEP 10
  StopTimer

  ? "Sleep 10 takes " + TimeTaken

END FUNCTION

Thanks and Regards

[Petr Schreiber jr]

-- Deleted, I did not noticed i am in Source Code forum

[David Roberts]

No discussions allowed in Source Code forum, Peter. I've replied in the Cafe.

[David Roberts]

PBWin9 & PBCC5 version (Revised 29 Aug)

#Compile  Exe
#Register None
#Dim      All
#Tools    Off

%NOMMIDS = 1
%NOGDI = 1

#Include "WIN32API.INC"

'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Global qFreq, qOverhead As Quad
Global f As String

Macro InitializeTixTimer
  f = "#####.##"
  QueryPerformanceFrequency qFreq
Tix qOverhead ' Just a precaution and in-line with post #1 
Tix qOverhead
  Tix End qOverhead 
End Macro

Macro sTimeTaken(x) = Using$(f,(x - qOverhead)*1000/qFreq) + "ms"
'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Function PBMain() As Long

  Local i As Long, t As Single, qTimer As Quad
    
  InitializeTixTimer
  
  Tix qTimer
    For i = 1 To 10000000
      t = Rnd
    Next
  Tix End qTimer
  MsgBox sTimeTaken(qTimer)

End Function

[Paul Dixon]

David,
that won't work. TIX is counting CPU clock cycles, QueryPerformanceFrequency is getting the frequency of the high speed timer which is a different timer running a lot slower than the CPU.

Paul

EDIT: noticed this is Source Code forum so I'd better add some code..
The following isn't in the form of a macro but it shows ways to calibrate the time stamp counter (as used by TIX)

#COMPILE  EXE
#REGISTER NONE
#DIM      ALL
#TOOLS    OFF

%NOMMIDS = 1
%NOGDI = 1

#INCLUDE "WIN32API.INC"

'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
GLOBAL qFreq AS QUAD
GLOBAL f AS STRING

MACRO GetTimerFrequency
  f = "#####.##"
  QueryPerformanceFrequency qFreq
END MACRO

MACRO sTimeTaken(x) = USING$(f,x*1000/qFreq) + "ms"
'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

FUNCTION PBMAIN() AS LONG

LOCAL i AS LONG, t AS SINGLE, qTimer AS QUAD
'### 1st way calculate the CPU frequency for the Time Stamp Couinter by comparing with the performance counter for a short time
LOCAL freq,cnt1,cnt2,TSC, CPUfreq AS QUAD
'calibrate Time Stamp Counter
QueryPerformanceFrequency Freq
QueryPerformanceCounter cnt1
TIX TSC
SLEEP 1000
QueryPerformanceCounter cnt2
TIX END TSC

CPUfreq = TSC/((cnt2-cnt1)/freq)
MSGBOX "CPU Freq from Performance Counter = "+FORMAT$(CPUfreq,"###,###,###,###")+"MHz"

'### 2nd way Look up the CPU speed in the registry
LOCAL hKey,CPUspeedReg AS DWORD

        IF RegOpenKeyEx(%HKEY_LOCAL_MACHINE, "Hardware\Description\System\CentralProcessor\0", 0,%KEY_READ ,hKey) = %ERROR_SUCCESS  THEN
            
            IF RegQueryValueEx(hKey, "~MHz",0,0,CPUspeedReg,SIZEOF(CPUspeedReg)) = %ERROR_SUCCESS THEN
               MSGBOX "Registry says"+FORMAT$(CPUspeedReg,"###,###")+"MHz"
               
            ELSE
               MSGBOX "Couldn't get value from registry"
            END IF

            IF RegCloseKey(hKey) <> %ERROR_SUCCESS THEN
                MSGBOX "Couldn't close registry key"
            END IF


        ELSE
            MSGBOX "Couldn't open registry key"
        END IF


          

  TIX qTimer
    FOR i = 1 TO 10000000
      t = RND
    NEXT

  TIX END qTimer
  MSGBOX "Time Taken="+STR$(qTimer/CPUfreq)

END FUNCTION

[Michael Mattias]

I wanted to know because I read somewhere that the sleep command can get a little inaccurate below 10ms.

That's because SLEEP is not a timer.

[David Roberts]

May I invite you to tea and crumpets here.

[David Roberts]

Post #5 has been revised to take account of overhead as post #1 does.

The macro 'Macro sTimeTaken(x) = Using$(f,(x - qOverhead)*1000/qFreq) + "ms"' assumes that the frequency of the of the Performance Counter is the same as the frequency of the Time Stamp Counter which Tix uses. If this is not the case then the macro will be unsafe as a Tix to time conversion.

The following code will output a very good estimate of the Time Stamp Counter frequency, the Performance Counter frequency and the difference.

One run on my 2.66GHz Intel E6700 gave this result:

Time Stamp Counters per second 2666879836
Performance Counters per second 2666880000
Difference 164

In my case, and I suspect most people's, the macro is safe.

It is worth noting that when comparing two pieces of code if their timings are subtracted then the overhead is eliminated from the calculation. If their timings are divided then any time conversion is eliminated.

Given two timings Time1 and Time2, say, then the comparison method

Abs(Time1 - Time2)/Min(Time1, Time2)

will eliminate both the overhead and any time conversion.

Added: BTW, I should have mentioned that the code will take between 4 and 5 minutes to complete.

' PBCC 5
#Compile  Exe
#Optimize speed
#Register None
#Dim      All
#Tools    Off

%NOMMIDS = 1
%NOGDI = 1

#Include "WIN32API.INC"

Function PBMain() As Long
Local qPerfFreq, qTSFreq, qTargetPerfCtr, qCurrentPerfCtr, qTSCbegin, qTSCend, Tot As Quad
Local i As Long
Dim x(1 To 24) As Quad

' If you have a single core remove the next three lines
Local hProcess As Dword
  hProcess = GetCurrentProcess()
  SetProcessAffinityMask( hProcess, 1) ' ie CPU 0
  
  QueryPerformanceFrequency qPerfFreq
  
  If qPerfFreq = 0 Then
    Print "Sorry, but a high-resolution performance counter is not available"
    Waitkey$
    Exit Function
  End If
   
  For i = 1 To 24 ' We will only use 20
  
    QueryPerformanceCounter qTargetPerfCtr
    ' Determine Performance Counter in 10 seconds time
    qTargetPerfCtr = qTargetPerfCtr + qPerfFreq*10
    
    ' Take a snapshot of Time Stamp Counter
    !RDTSC
    !lea esi, qTSCbegin
    !mov [esi], eax
    !mov [esi+4], edx
    
    Do
      QueryPerformanceCounter qCurrentPerfCtr
    Loop While qCurrentPerfCtr < qTargetPerfCtr ' We pull out then when qCurrentPerfCtr >= qTargetPerfCtr
      
    ' Take another snapshot at, or earliest after, qTargetPerfCtr
    !RDTSC
    !lea esi, qTSCend
    !mov [esi], eax
    !mov [esi+4], edx
    
    x(i) = (qTSCend - qTSCbegin)\10 ' Our 10 seconds again
    
    Sleep Rnd(1000,2000) ' Avoid looping 'back to back'
        
  Next
  
  Array Sort x()
  
  For i = 3 To 22 ' Throw out the two largest and the two smallest
    Tot = Tot + x(i)
  Next
  
  qTSFreq = Tot/20
  
  Print "Time Stamp Counters per second ";qTSFreq
  Print "Performance Counters per second";qPerfFreq
  Print "Difference"; Abs(qTSFreq - qPerfFreq)
  
  Waitkey$

End Function

[David Roberts]

I needed to extend the original concept to multiple timers and have them with varying display accuracies.

PBMain shows a job being timed and individual functions - selective Profiling if you like. This example sets up 16 timers, must be done in PBMain, but you decide what you want. As for the accuracies - well, play around with that as well.

#COMPILE  EXE
#Register None
#Dim      All
#TOOLS    OFF

%NOMMIDS = 1
%NOGDI = 1

#Include "WIN32API.INC"

' Timer macros ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Global qFreq, qStart(), qStop(), qOverhead As Quad
Global f() As String

Macro InitializeTimer
  QueryPerformanceFrequency qFreq 
  QueryPerformanceCounter qStart(0) ' Intel suggestion. First use may be suspect 
  QueryPerformanceCounter qStart(0) ' So, wack it twice <smile>
  QueryPerformanceCounter qStop(0)
  qOverhead = qStop(0) - qStart(0)  ' Relatively small 
End Macro

Macro StartTimer(i) = QueryPerformanceCounter qStart(i)
Macro StopTimer(i) = QueryPerformanceCounter qStop(i)

' In the following i is the ith timer and 0 <= j <= 3 For 0 To 3 decimal places
Macro sTimeTaken( i, j ) = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), (qStop(i) - qStart(i) - qOverhead)*1000/qFreq) + "ms"
Macro nTimeTaken(i) = (qStop(i) - qStart(i) - qOverhead)*1000/qFreq
' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Function PBMain

' For timers ----------------------
Dim qStart( 0 To 15) As Global Quad
Dim qStop( 0 To 15 ) As Global Quad
Dim f( 0 To 3 ) As Global String   
' ---------------------------------

Local i, n As Long, Message As String
InitializeTimer

StartTimer(0)
  MainFunction
StopTimer(0)

Message =  "MainFunction:" + sTimetaken(0,0) + $CrLf + "Function One:" + _
           sTimeTaken(1,2) + $CrLf + "Function Two:" + sTimeTaken(2,2)
MsgBox Message 

End Function

Function MainFunction As Long

  One
  Two
  
End Function

Function One As Long
  Local i, n As Long
  
  StartTimer(1)
    For i = 1 To 123456
      n = Rnd(0,255)
    Next
  StopTimer(1)
End Function

Function Two As Long
  Local i, n As Long
  
  StartTimer(2)
    For i = 1 To 1000000
      n = Rnd(0,255)
    Next
  StopTimer(2)
  
End Function

[David Roberts]

We can remove the f() - got left in from another idea. CCleaner won't do that for me, yet.

[David Roberts]

I am sorry. I am being extremely dim.

Those two Dims are better placed in the InitializeTimer macro.

We have then:

Macro InitializeTimer
  Dim qStart( 0 To 15) As Global Quad
  Dim qStop( 0 To 15 ) As Global Quad
  QueryPerformanceFrequency qFreq 
  QueryPerformanceCounter qStart(0) ' Intel suggestion. First use may be suspect 
  QueryPerformanceCounter qStart(0) ' So, wack it twice <smile>
  QueryPerformanceCounter qStop(0)
  qOverhead = qStop(0) - qStart(0)  ' Relatively small
End Macro

All we put in PBMain is InitializeTimer, as we did with the singleton macro. Dear, oh dear.

[Jeff Blakeney]

You'll want to change those DIM statements to REDIM or add ERASE statements before the DIMs or use ARRAYATTR and other code to check to see if the arrays are already dimensioned and skip the DIMs just in case someone uses InitializeTimer more than once.

[David Roberts]

Thanks Jeff, but I think I'll leave that to others to sort out if they want.

I have added a few more macros.

The main addition is the facility to total a section of a function called more than once which may vary in time consumed and which we feel is critical, benefiting perhaps from some tweaking or replacing with assembler. This could have been done previously but the addition is in keeping with the style developed thus far.

In use we simply bracket as we have been doing like this:-

StartTimer(n)
Do some work
StopTimer(n)

where n is the timer number used and add:-

qTotalTime(n) = qTotalTime(n) + qTicks(n)

We are totalling ticks so that the division by qFreq is left as the last job.

The total for printing is got from sTotalTime( i, j ) in the same vein as sTimeTaken( i, j ).

Here are some examples of the macros and the new ToTalTime.

The use of timer 3 and function three is coincidental. I could have used timers 1 or 2 as they have ceased to be used but I am 'playing it safe'; we have 16 after all - or have you upped the anti to more?

#COMPILE  EXE
#Register None
#Dim      All
#TOOLS    OFF

%NOMMIDS = 1
%NOGDI = 1

#Include "WIN32API.INC"

' Multiple Timer macros (0 to 15) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Global qFreq, qStart(), qStop(), qOverhead, qTotalTime() As Quad

Macro InitializeTimer
  Dim qStart( 0 To 15) As Global Quad
  Dim qStop( 0 To 15 ) As Global Quad 
  Dim qTotalTime( 0 To 15 ) As Global Quad
  QueryPerformanceFrequency qFreq 
  QueryPerformanceCounter qStart(0) ' Intel suggestion. First use may be suspect 
  QueryPerformanceCounter qStart(0) ' So, wack it twice <smile>
  QueryPerformanceCounter qStop(0)
  qOverhead = qStop(0) - qStart(0)  ' Relatively small
End Macro

Macro StartTimer(i) = QueryPerformanceCounter qStart(i)
Macro StopTimer(i) = QueryPerformanceCounter qStop(i)

' In the following i is the ith timer and 0 <= j <= 3 For 0 To 3 decimal places
Macro  sTimeTaken( i, j ) = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), (qStop(i) - qStart(i) - qOverhead)*1000/qFreq) + "ms"
Macro nTimeTaken(i) = (qStop(i) - qStart(i) - qOverhead)*1000/qFreq
Macro sTicks(i) =  Format$(qStop(i) - qStart(i) - qOverhead, "###,###,###,###")
Macro qTicks(i) =  qStop(i) - qStart(i) - qOverhead
Macro sTotalTime( i, j ) = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTotalTime(i)*1000/qFreq) + "ms"
Macro sCPUfreq = Format$(qFreq, "###,###,###,###")
' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Function PBMain

  Local i, n As Long, Message As String
  
  InitializeTimer
  
  ' Main Block
  StartTimer(0)
    MainFunction
    For i = 1 To 214000
      n = Rnd(0,255)
    Next
  StopTimer(0)
  
  ' 5 x Section of Three
  Three( 98765 )
  Three( 1234567 )
  Three( 99999 )
  Three( 111111 )
  Three( 658457 )
  
  Message =  "Main Block:" + sTimetaken(0,2) + $CrLf + _
             "Function One:" + sTimeTaken(1,2) + $CrLf + _
             "Function Two:" + sTimeTaken(2,2) + $CrLf + _
             "5 x Section of Three:" + sTotalTime(3,2)
             
  MsgBox Message

End Function

Function MainFunction As Long

  One
  Two
  
End Function

Function One As Long
  Local i, n As Long
  
  StartTimer(1)
    For i = 1 To 1234567
      n = Rnd(0,255)
    Next
  StopTimer(1)
  
End Function

Function Two As Long
  Local i, n As Long
  
  StartTimer(2)
    For i = 1 To 1000000
      n = Rnd(0,255)
    Next
  StopTimer(2)
  
End Function

Function Three( i As Long ) As Long

  Local j, n As Long
  
  StartTimer(3)
    For j = 1 To i
      n = Rnd(0,255)
    Next
  StopTimer(3)
  
  qTotalTime(3) = qTotalTime(3) + qTicks(3)

End Function

[David Roberts]

Another macro added.

Macro StopTimer_UpdateTotalTime(i)
StopTimer(i)
qTotalTime(i) = qTotalTime(i) + qTicks(i)
End Macro

This saves us having to remember the update construct and is used like this:

StartTimer(n)
Do some work
StopTimer_UpdateTotalTime(n)

where n is the timer number used.

[David Roberts]

qTotalTime() has been sitting uneasily with me since I introduced it.

Most, if not all of us, have come foul with using the construct 'Tot = Tot + something' more than once in a Function and forgotten to re-initialize Tot to zero on a second or subsequent instance. Of course, using Tot0, Tot1, Tot2 and so on avoids that but using Tot all the time probably stems from not having much memory in the 'old days'. I often use 'dummy' and when I see that it reminds me that I've probably used it more than once and needs to be re-initialized before another use.

So it is with qTotalTime(n). If we want to use the nth timer in a totalling fashion again then we must re-initialize qTotalTime(n). As it stands we could total different sections of code in different Functions. That amount of scope was never intended; one section of code in one function called many times was the intention. To do no more than intended then we could re-initialize after reading the appropriate values which is done via the code associated with the sTotalTime() macro. Having 'read' then we can print straight away in a console window or build a string for a message box, the point being the timer can now be used again.

So, I propose re-writing the sTotalTime() to the following:-

Macro Function sTotalTime( i, j )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTotalTime(i)*1000/qFreq) + "ms"
  Reset qTotalTime(i)
End Macro = str

The code in the preceding post will work just the same but now we can test qTotalTime(n) on its 'first' use, but only if there is a need.

Something like this will do:

Static BeenHere As Long
If IsFalse(BeenHere) Then ' 1st call to function
  If qTotalTime(3) <> 0 then ' we need zero
    ' Handle it
  End If
  BeenHere = %True
End If

By 'Handle it' will depend on how you handle an error in that Function and the type of Function ie Long, String or whatever.

We could incorporate a test in a macro but too many assumptions will be needed.

While we are at it a similar test could be made to avoid using a straight forward timer when it is still 'active' or has not been 'read' yet. By 'straight forward' I mean not of the StopTimer_UpdateTotalTime() variety.

Here, I propose replacing sTimeTaken() with:-

Macro Function sTimeTaken( i, j )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), (qStop(i) - qStart(i) - qOverhead)*1000/qFreq) + "ms"
  Reset qStart(i)
End Macro = str

and to introduce the assignment Macro mTimer(i) = qStart(i).

We can test if a timer cannot be used by, for example:-

If mTimer(2) <> 0 then 'Handle it

In the preceding post's code it is clear what is going on and we are unlikely to make a mistake so a test is not really necessary. However, if a lot of timers are being used and scattered across a large application then a test may very well be in order.

Right, this is what I now have. I should have done the above at the outset but pennies do not drop as fast as they used to - at least they are still dropping.

Added: I should have mentioned that whilst qOverhead is relatively small and will only be significant when a very small time is involved with sTimeTaken() when we use sTotalTime() a Function may be called thousands, if not more, times and the overhead could get 'noisy' but this is taken care of by qTicks() which removes the overhead on each use.

' Multiple Timer macros (0 to 15) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Global qFreq, qStart(), qStop(), qOverhead, qTotalTime() As Quad

Macro InitializeTimer
  Dim qStart( 0 To 15) As Global Quad
  Dim qStop( 0 To 15 ) As Global Quad 
  Dim qTotalTime( 0 To 15 ) As Global Quad
  QueryPerformanceFrequency qFreq 
  QueryPerformanceCounter qStart(0) ' Intel suggestion. First use may be suspect 
  QueryPerformanceCounter qStart(0) ' So, wack it twice <smile>
  QueryPerformanceCounter qStop(0)
  qOverhead = qStop(0) - qStart(0)  ' Relatively small
End Macro

Macro StartTimer(i) = QueryPerformanceCounter qStart(i)
Macro StopTimer(i) = QueryPerformanceCounter qStop(i)

Macro mTimer(i) = qStart(i)

Macro StopTimer_UpdateTotalTime(i)
  StopTimer(i)
  qTotalTime(i) = qTotalTime(i) + qTicks(i)
End Macro

' In the following i is the ith timer and 0 <= j <= 3 For 0 To 3 decimal places

Macro Function sTimeTaken( i, j )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), (qStop(i) - qStart(i) - qOverhead)*1000/qFreq) + "ms"
  Reset qStart(i)
End Macro = str

Macro nTimeTaken(i) = (qStop(i) - qStart(i) - qOverhead)*1000/qFreq
Macro sTicks(i) =  Format$(qStop(i) - qStart(i) - qOverhead, "###,###,###,###")
Macro qTicks(i) =  qStop(i) - qStart(i) - qOverhead

Macro Function sTotalTime( i, j )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTotalTime(i)*1000/qFreq) + "ms"
  Reset qTotalTime(i)
End Macro = str

Macro sCPUfreq = Format$(qFreq, "###,###,###,###")
' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

More added: It would be better if qTotalTime was described as qTotalTicks and StopTimer_UpdateTotalTime was described as StopTimer_UpdateTotalTicks.

[David Roberts]

Here is another one.

I'm now using 'TotalTicks' as opposed to 'TotalTime' descriptions [ see 'More added' note above ]

Macro Function sAverageTime( i, j, n )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTotalTicks(i)*1000/(qFreq*n)) + "ms"
  Reset qTotalTicks(i)
End Macro = str

In use:

n = 10 ' or whatever 
For i = 1 To n
  Four
Next
 
MsgBox "Average:" + sAverageTime(7,2,n)
 
...
...
...
 
Function Four As Long
  Local i, n As Long
 
  ' Some code here
 
  ' Section of interest
  StartTimer(7)
    For i = 1 To 1234567
      n = Rnd(0,255)
    Next
  StopTimer_UpdateTotalTicks(7)
 
  ' More code here
 
End Function

[David Roberts]

I have mentioned a few times the insignificance of qOverhead unless we are looking at small timings.

With my system, qOverhead is about 550 ticks and with my qFreq that gives qOverhead at 0.0002ms which is below the microsecond radar and the cut-off if 3 decimal places are displayed

With qTotalTicks() and a section of code executed 10^6 times then qOverhead comes to bear arms.

In this case a perturbation of qOverhead may come into play but, of course, nothing like qOverhead itself.

A more accurate estimate of qOverhead is required.

This is easily achieved by computing many qOverheads and averaging. A revised InitializeTimer is suggested.

Macro InitializeTimer
  Dim qStart( 0 To 15) As Global Quad
  Dim qStop( 0 To 15 ) As Global Quad
  Dim qTotalTicks( 0 To 15 ) As Global Quad
  QueryPerformanceFrequency qFreq
  QueryPerformanceCounter qStart(0) ' Intel suggestion. First use may be suspect
  Do
    QueryPerformanceCounter qStart(0)
    QueryPerformanceCounter qStop(0)
    qTotalTicks(1) = qTotalTicks(1) + qStop(0) - qStart(0)
    Incr qTotalTicks(0)
  Loop Until qTotalTicks(0) = 100000
  qOverhead = qTotalTicks(1)\100000 ' Relatively small
  Reset qTotalTicks(0)
  Reset qTotalTicks(1)
End Macro

This will also 'iron out' any rogue qOverheads. The very first QPC is still ignored - Intel did not indicate a level of suspicion.

Another macro has been added. If you have more than one core then the respective QPCs are not guaranteed to be in sync; although I have not seen any 'oddities' - but you may.

Macro SingleCore
  Local hProcess As Dword
  hProcess = GetCurrentProcess()
  SetProcessAffinityMask( hProcess, 1) ' ie CPU 0
End Macro

In another thread I wrote "I still haven't bought into TIX yet". Well, I have now and the next post has a TIX version.

[David Roberts]

I looked at a TIX version in earlier posts but stayed with the QPC.

The issue is whether TIX = QPC.

I have recently read that Windows will choose from one of the following for the QPC:-

• New north-bridge hardware performance timers
• Time stamp counter (RDTSC) On P4 level hardware
• PCI bridge timers

On my machine it is clear that the TSC is used so TIX = QPC since TIX uses the TSC.

qOverhead for TIX on my machine is about 70 ticks. It is still worthwhile to average qOverhead, but the 'pressure' is well down. InitializeTimer for the QPC version takes about 400ms on my machine. With the TIX version this reduces to about 7ms.

'************
' Tix version
'***********

' Multiple Timer macros (0 to 15) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Global qFreq, qTicks(), qOverhead, qTotalTicks() As Quad

Macro InitializeTimer
  Dim qTicks( 0 To 15) As Global Quad
  Dim qTotalTicks( 0 To 15 ) As Global Quad
  QueryPerformanceFrequency qFreq 
  Tix qTicks(0) ' Intel suggestion. First use may be suspect 
  Do
    Tix qTicks(0)
    Tix End qTicks(0)
    qTotalTicks(1) = qTotalTicks(1) + qTickS(0)
    Incr qTotalTicks(0)
  Loop Until qTotalTicks(0) = 100000
  qOverhead = qTotalTicks(1)\100000 ' Relatively small
  Reset qTotalTicks(0)
  Reset qTotalTicks(1)
End Macro

Macro StartTimer(i) = Tix qTicks(i)
Macro StopTimer(i)
  Tix End qTicks(i)
  qTicks(i) = qTicks(i) - qOverhead
End Macro

Macro mTimer(i) = qTicks(i)

Macro StopTimer_UpdateTotalTicks(i)
StopTimer(i)
qTotalTicks(i) = qTotalTicks(i) + qTicks(i)
End Macro

' In the following i is the ith timer and 0 <= j <= 3 For 0 To 3 decimal places

Macro Function sTimeTaken( i, j )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTicks(i)*1000/qFreq) + "ms"
  Reset qTicks(i)
End Macro = str

Macro nTimeTaken(i) = qTicks(i)*1000/qFreq
Macro sTicks(i) =  Format$(qTicks(i), "###,###,###,###")

Macro Function sTotalTime( i, j )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTotalTicks(i)*1000/qFreq) + "ms"
  Reset qTotalTicks(i)
End Macro = str

Macro Function sAverageTime( i, j, n )
  MacroTemp str
  Dim str As String
  str = Using$(Choose$(j+1,"####","####.#", "####.##","####.###"), qTotalTicks(i)*1000/(qFreq*n)) + "ms"
  Reset qTotalTicks(i)
End Macro = str

Macro sCPUfreq = Format$(qFreq, "###,###,###,###")

Macro SingleCore
  Local hProcess As Dword
  hProcess = GetCurrentProcess()
  SetProcessAffinityMask( hProcess, 1) ' ie CPU 0
End Macro
' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

[David Roberts]

A few additions.

Further development will be on the Tix version only. I am mindful that this will exclude older versions of the compilers but it is not difficult to convert to a QPC version.

Instead of 100,000 'Tix/Tix End' pairings to determine qOverhead I have allocated 10ms. The greater qFreq the more pairings will be considered in determining a smaller qOverhead. On my machine 10 X InitializeTimer runs gave qOverhead as 66, 69, 67, 66, 67, 69, 66, 66, 66, 66. The differences are way below any 'radar' we use in the macros.

sTimeTaken, sTotalTime and sAverageTime now have either a simple output, the same output as previously, or a verbose output.

The verbose output includes the Function name where StartIimer() is placed, the timer index and whether Single, Total or Average. With sTotalTime and sAverageTime the number of times the timer was invoked is also mentioned and we no longer have to pass that as a parameter - this is taken care of in StopTimer_UpdateTotalTicks().

I haven't mentioned that I often use Patrice Terrier's zTrace 1.52 in conjunction with the Timer macros. I personally find this little library awesome especially with the features in the right-click context menu.

The test program, for PBWin or PBCC, following the latest Tix version of Multiple Timer Macros, now as an include file, with '%PatriceTrace = 1' gives the attached output.

With %PatriceTrace = 0 the test program uses '?' for outputting.

Added: CAVEAT

Treat sTotalTime and sAverageTime for the same timer as mutually exclusive. qTotalTicks() is reset on 'printing' for good reason - learnt the 'hard' way.

' MultipleTimersTix.inc

' Multiple Timer Macros (0 to 15) ~~~~~~~~~~~~~~~~~~~~~~

Global qFreq, qTicks(), qOverhead, qTotalTicks() As Quad
Global sFuncName() As String
Global TimerCallCount() As Long

Macro InitializeTimer
  Dim qTicks( 0 To 15) As Global Quad
  Dim qTotalTicks( 0 To 15 ) As Global Quad
  Dim sFuncName( 0 To 15 ) As String
  Dim TimerCallCount( 0 To 15 ) As Long
  QueryPerformanceFrequency qFreq 
  Tix qTicks(0) ' Intel suggestion. First use may be suspect 
  Tix qTicks(1) ' Start of averaging interval
  Do
    Tix qTicks(0)
    Tix End qTicks(0)
    qTotalTicks(0) = qTotalTicks(0) + qTickS(0)
    Incr qTotalTicks(1) ' divisor
    Tix qTicks(2) ' End of averaging interval
  Loop Until qTicks(2) - qTicks(1) > qFreq\100 ' 10ms averaging interval
  qOverhead = qTotalTicks(0)\qTotalTicks(1) ' Relatively small
  Reset qTicks(0) : Reset qTicks(1) : Reset qTicks(2)
  Reset qTotalTicks(0) : Reset qTotalTicks(1)
End Macro

Macro mTimer(i) = qTicks(i)

Macro StartTimer(i)
  sFuncName(i) = FuncName$
  Tix qTicks(i)
End Macro

Macro StopTimer(i)
  Tix End qTicks(i)
  qTicks(i) = qTicks(i) - qOverhead
End Macro

Macro StopTimer_UpdateTotalTicks(i)
  StopTimer(i)
  qTotalTicks(i) = qTotalTicks(i) + qTicks(i)
  Incr TimerCallCount(i)
End Macro

Macro nTimeTaken(i) = qTicks(i)*1000/qFreq

Macro sTicks(i) =  Format$(qTicks(i), "###,###,###,###")

Macro sCPUfreq = Format$(qFreq, "###,###,###,###")

' In the following
' i is the ith Timer
' 0 <= j <= 3 For 0 To 3 decimal places
' flag = 0 => time in ms only
' flag = 1 => verbose output including Function name, timer index
'   and whether Single, Total or Average, if applicable

Macro Function sTimeTaken( i, j, flag )
  MacroTemp strM
  Dim strM As String
  strM = Using$(Choose$(j+1,"####","####.#","####.##","####.###"), qTicks(i)*1000/qFreq) + "ms"
  If IsTrue( flag ) Then
    strM = sFuncName(i) + " [" + Trim$(Str$(i)) + "] Single:" + " " + Trim$(strM)
  End If
  Reset qTicks(i)
End Macro = strM

Macro Function sTotalTime( i, j, flag )
  MacroTemp strM
  Dim strM As String
  strM = Using$(Choose$(j+1,"####","####.#","####.##","####.###"), qTotalTicks(i)*1000/qFreq) + "ms"
  If IsTrue( flag ) Then
    strM = sFuncName(i) + " [" + Trim$(Str$(i)) + "] Total(" + Trim$(Str$(TimerCallCount(i))) + "):" + " " + Trim$(strM)
  End If
  Reset qTotalTicks(i)
  Reset TimerCallCount(i)
End Macro = strM

Macro Function sAverageTime( i, j, flag )
  MacroTemp strM
  Dim strM As String
  strM = Using$(Choose$(j+1,"####","####.#","####.##","####.###"), qTotalTicks(i)*1000/(qFreq*TimerCallCount(i))) + "ms"
  If IsTrue( flag ) Then
    strM = sFuncName(i) + " [" + Trim$(Str$(i)) + "] Average(" + Trim$(Str$(TimerCallCount(i))) + "):" + " " + Trim$(strM)
  End If
  Reset qTotalTicks(i)
  Reset TimerCallCount(i)
End Macro = strM

Macro SingleCore
  Local hProcess As Dword
  hProcess = GetCurrentProcess()
  SetProcessAffinityMask( hProcess, 1) ' ie CPU 0
End Macro

' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

New features test program:

#Compile  Exe
#Dim      All
#Tools    Off

%NOMMIDS = 1
%NOGDI = 1

%PatriceTrace = 1

#Include "WIN32API.INC"
#Include "MultipleTimersTix.inc"

#If %PatriceTrace = 1
  Declare Function zTrace Lib "zTrace.DLL" Alias "zTrace" (zMessage As Asciiz) As Long
#EndIf

Function PBMain
Local i, n, r, t, w As Long, Wait As String

  InitializeTimer
  
  StartTimer(0)
    For r = 1 To 10000
      For t = 1 To 1000
        w= r*t
      Next
    Next
  StopTimer(0)
  #If %PatriceTrace = 1
    zTrace( sTimeTaken(0,3,1) + $Nul )
  #Else
    ? sTimeTaken(0,2,1)
  #EndIf
    
  n = 8
  For i = 1 To n
    Test
  Next
  #If %PatriceTrace = 1
    zTrace( sTotalTime(1,1,1) + $Nul )
    zTrace( sAverageTime(2,1,1) + $Nul )
  #Else
    ? sTotalTime(1,1,1) + " " + sAverageTime(2,1,1)
  #EndIf
  
  #If %Def(%Pb_Win32) And %PatriceTrace = 1
    Wait = InputBox$("Click Cancel")
  #ElseIf %Def(%Pb_Cc32)  
    Waitkey$
  #EndIf
  
End Function

Function Test As Long
Local i, n As Long

  ' Some code
  
  StartTimer(1)
  For i =1 To 1234567
    n = Rnd(0,255)
  Next
  StopTimer_UpdateTotalTicks(1)
  
  ' more code
  
  StartTimer(2)
  For i =1 To Rnd(100000, 500000)
    n = Rnd(0,255)
  Next
  StopTimer_UpdateTotalTicks(2)
  
  ' more code

End Function