High resolution timer/code run time -> overhead?

Question

I'm trying to find my Code run time using a high resolution timer, I've noticed that the timer has inconsistent results and I would like to find out why this is.

I found this article How do you test running time of VBA code?
and have implemented the top answer, I tried using it to find the run time of several functions and noticed that the results changed fairly drastically.

To see if this was a fault of the timer, i made a function where I just started and stopped the timer.

Public Sub test_ctimer()
    Dim results(0 To 4) As Double
    Dim t As CTimer: Set t = New CTimer
    Dim i As Integer

    'Removes msg box overhead
    MsgBox "about to start"

    For i = 0 To 4
        t.StartCounter
        results(i) = t.TimeElapsed

    Next i

    For i = 0 To 4
        MsgBox results(i)
    Next i
End Sub

The first measurement takes significantly more time (~ 1 magnitude greater) than any of the following measurements. Does anyone know why this is?

Below is the ctimer code from How do you test running time of VBA code?

Option Explicit

Private Type LARGE_INTEGER
    lowpart As Long
    highpart As Long
End Type

Private Declare Function QueryPerformanceCounter Lib "kernel32" (lpPerformanceCount As LARGE_INTEGER) As Long
Private Declare Function QueryPerformanceFrequency Lib "kernel32" (lpFrequency As LARGE_INTEGER) As Long

Private m_CounterStart As LARGE_INTEGER
Private m_CounterEnd As LARGE_INTEGER
Private m_crFrequency As Double

Private Const TWO_32 = 4294967296# ' = 256# * 256# * 256# * 256#

Private Function LI2Double(LI As LARGE_INTEGER) As Double
Dim Low As Double
    Low = LI.lowpart
    If Low < 0 Then
        Low = Low + TWO_32
    End If
    LI2Double = LI.highpart * TWO_32 + Low
End Function

Private Sub Class_Initialize()
Dim PerfFrequency As LARGE_INTEGER
    QueryPerformanceFrequency PerfFrequency
    m_crFrequency = LI2Double(PerfFrequency)
End Sub

Public Sub StartCounter()
    QueryPerformanceCounter m_CounterStart
End Sub

Property Get TimeElapsed() As Double
Dim crStart As Double
Dim crStop As Double
    QueryPerformanceCounter m_CounterEnd
    crStart = LI2Double(m_CounterStart)
    crStop = LI2Double(m_CounterEnd)
    TimeElapsed = 1000# * (crStop - crStart) / m_crFrequency
End Property

Cor_Blimey · Accepted Answer · 2014-08-08T21:58:34.373

1

The linked class is not great. There is an overhead associated with calling QueryPerformanceCounter it and that overhead should be determined first then used to adjust the subsequent calls. This would explain all results being slightly slower than expected, however it does not explain the first one being substantially slower. Anyway, see http://support.microsoft.com/kb/172338 describes an approach to adjust for it. The class I have implemented I do not have access to at this time so I cannot post the relevant parts.

Also for a read unrelated to your specific issue, but related to Timings on Windows in general, http://msdn.microsoft.com/en-gb/library/windows/desktop/dn553408%28v=vs.85%29.aspx is interesting.

As a workaround in the meantime, add a call to start then stop in the Class_Initialize.

This is not really an answer at all - more of an extended comment - so I will edit it if I ever find a conclusive reason ;)

To reiterate to those upvoting: I cannot explain the reason for the results the OP is querying. I hypothesise it is to do with the VBA interpreter (i.e. close to a JIT'er) but I cannot evidence either way. My commentary above is related to the functions the OP is using but are probably non sequitur.

edited Aug 08 '14 at 21:58

answered May 29 '14 at 18:10

Cor_Blimey

3,260
1
14
20

1

I think the first one is actually substantially faster – Alter May 29 '14 at 18:28
@Alter oh whoops. I didnt notice the E-4 bit ;). Hmm, that is very interesting. That ruins my interpreter idea :D – Cor_Blimey May 29 '14 at 18:32
1

@Alter can you run it a few times and store the results then output them (e.g. into an `Dim results(0 to 4)...t.StartCounter:results(0) = t.TimeElapsed` kind of thing. Just trying to narrow down possible reasons. (random idea: On the first call it has been instantiated and has been 'accessed' recently through the initialisation. The msgbox, resulting in a lot of complex calls behind the scenes, could push it back to the heap). – Cor_Blimey May 29 '14 at 18:35
I just tried it as you suggested, running the msgbox in a separate loop in case it interfered. It looks like it did. the results are much closer but still significantly different. the first results is still ~8.4E-4, but now the following results are ~4.27E-3 and occasionally 0... – Alter May 29 '14 at 18:44
1

@Alter final idea: early bind (so `Dim t As CTimer: Set t = New CTimer` then do something else e.g. `MsgBox "about to start"`) then carry on with the rest in a seperate loop. Again, I am just approaching this from a practical perspective as this is beyond my basic understanding of how VBA is actually run, let alone how the kernel works. – Cor_Blimey May 29 '14 at 18:49
1

good idea, interesting results. The first result is now significantly greater (~an order of magnitude) than the following results. I guess this makes your interpreter idea valid again ;) – Alter May 29 '14 at 18:58
@Alter i think what it really means is it is as much a mystery to me as the virgin birth... – Cor_Blimey May 29 '14 at 20:02

High resolution timer/code run time -> overhead?

1 Answers1

Linked