How to accurately time code execution

[Witis]

Hi

At the moment I use gettickcount to time how long it takes for code to execute. Then I realised that this measure is only a guide rather than an accurate measure as it can be influenced by the total number of applications open at the same time. For example if I time my code execution while I do not have any other applications open it is much faster than if it is executed while I have 20 other applications open that are all simultaneously and actively using processor time.

Is there a way to determine the amount of processing time that was used to just execute my code (not other applications executing simultaneously)?

[lone_REBEL]

Isn't it the time difference you'd get with the tick count value when only your application is running on the system?

When there are no other applications, the processor would use all of its resources for your application and the time you'd get would be your code's "pure" processing time.

[Witis]

Thanks for the reply lone_REBEL. The only problem is that even when you have no applications running there are still background processes running and depending on the software, eg Java Virtual Machine and .Net framework, these might have a substantial impact on the tickcount numbers.

I guess what I am trying to find out is how many cpu cycles my app takes to execute (just my app not any other application) and the time per cycle on my machine. Although it might not just be the cpu cycles, as writing to and from files/devices might take additional time. Some way to measure thread or process execution in isolation from all other code...

[Cube8]

GetTickCount() is not accurate at all. Its resolution is about 16ms.

For a truly accurate code timing I have created a class, which makes use of QueryPerformanceCounter() and QueryPerformanceFrequency() functions.

The attached class contains 2 subs (StartTiming, StopTiming) and a property (Result).

Use it this way:
Before the code starts, make a call to StartTiming. After the code completes, call StopTiming. The result can be fetched using the property Result.

[lone_REBEL]

Cube, what you have made, is a precision to the Tick Count function. What he asks is, the time that only HIS application takes, while there are no other processes running in the bg.

Witis, while you want to exclude (or close) all other processes on your operating system, you ought to know that your application itself might depend on those processes and threads. For example, an application dependent on .net framework will not work if .net framework is not installed and acting on the system. Similarly, a VB6 application will not work if its underlying dependencies are not available on the system.

So when you want to calculate the time required by ONLY your app to execute, be aware that your application may depend on some OTHER threads and background processes/services which provide the grounds for your application to work. The time (and resources) exploited by those processes is also indirectly the time that your application takes. So you cannot exclude them as disjoint processes.

About the processes and services which actually are irrelevant to your application's working, you can stop them (Control Panel => Administrative Tools => Services) and then execute your application.

But as far as my personal point of view is concerned, I think as long as the CPU usage remains below 60-70%, the time your application takes to perform is the time it would take to perform if it were the only application running.

[Witis]

Hi lone_REBEL, yes you are correct, increasing the timer resolution won't solve my problem.

In relation to the direct dependency issue you raised, for example, if I had written a .net application which depends on the .net framework, the problem I have is this: Just say you run your application once just before the framework executes garbage collection (http://msdn.microsoft.com/en-us/library/0xy59wtx.aspx), and once while the .net framework is executing its garbage collection tasks, there will be a large difference in the tickcount for the time taken to execute your application even though my application's code is the same which I view as a distortion in the measure of my application's performance.

Furthermore, if I get two identical machines, and load different software, for example if I install sun office on one and not the other, then SUN virtual machine will be running in the background only on one machine not the other. Then when I time the performance of my application on the machine without SUN VM it will be faster than on the machine with SUN VM, which makes the reported performance number relevant only to the specific machine it is run on. I am hoping to get a measure that will give the same reported tick count as long as the hardware and the code are identical even if there is different software loaded on each machine, i.e. make the performance figures comparable when hardware is the same.

Overall, what would fix my problem, is some way to get the same reported tick count every time I run my application on any one given machine as long as the underlying code does not change, then I would be happy. The reason for this issue is that I have noticed up to and greater than 10% difference in recorded performance on the same machine with the same code, which makes me worry. However, if there is no way to get what I want then I will have to put up with slightly less accurate performance figures.

[Doogle]

Have you looked at the GetProcessTimes API? I'd guess that the 'user time' would be repeatable given the same data and program code. (At least you may get it repeatable to within 10% of 100 nano-seconds)

[lone_REBEL]

I agree to that, Witis, the disjoint background processes and services MAY add additional load to the CPU's workload and hence your application/code may take more time to execute. In case of disjoint software and services, which are completely irrelevant to your code, you can easily disable them without uninstalling them via Control Panel => Administrative Tools => Services.

But then again, even the installation of those services/softwares might add a slight workload on the CPU. So for the sake of "absolute precision", I'd suggest first compiling your code to EXE and then running that application (which has the code execution timer) on a machine with a freshly installed windows, on which not even antivirus is installed. If you want to go to extremes, don't even install the sound/video drivers and let windows have the least workload. I think this "natal environment" would provide you with the most precise time your code/application takes to run. Note that you should compile your code to an exe and then run it on the natal windows system without even installing VB suite on it.

But then again, whats all this effort worth, when your users would in the end use the software/script on machines where loads of softwares are running. If I were to determine the time taken by my code/application to function, I'd test it with a typical user-style system. A 3 GHz system with 1 GB RAM and with MS Office and with java and vb runtime files installed. Plus I'd test my app/code while there are 4 other softwares running simultaneously (an IM, a web browser, an office document and a windows image and fax viewer window)

[Cube8]

But then again, whats all this effort worth, when your users would in the end use the software/script on machines where loads of softwares are running. If I were to determine the time taken by my code/application to function, I'd test it with a typical user-style system. A 3 GHz system with 1 GB RAM and with MS Office and with java and vb runtime files installed. Plus I'd test my app/code while there are 4 other softwares running simultaneously (an IM, a web browser, an office document and a windows image and fax viewer window)

I was going to say exactly this.
What's the point in measuring an app performance in such a "sterilized" environment?

[Witis]

Hi Doogle, I played around with that function as it looked promising, and I eventually got it to work. The only thing that was a bit weird was that although it usually returns the exactly the same number of nanosecondsx100, sometimes it doesn't, perhaps one out of every 4-8 times it gives a different number, and this exception keeps repeating (i.e. the same two or three different results keep repeating). Is it my code, or something else?

Declarations:

Private Type FILETIME
dwLowDateTime As Long
dwHighDateTime As Long
End Type

Private Type SYSTEMTIME
wYear As Integer
wMonth As Integer
wDayOfWeek As Integer
wDay As Integer
wHour As Integer
wMinute As Integer
wSecond As Integer
wMilliseconds As Integer
End Type

Private Declare Function GetWindowThreadProcessId Lib "user32" (ByVal hwnd As Long, lpdwProcessId As Long) As Long
Private Declare Function OpenProcess Lib "kernel32" (ByVal dwDesiredAccess As Long, ByVal bInheritHandle As Long, ByVal dwProcessId As Long) As Long
Private Const PROCESS_ALL_ACCESS = &H1F0FFF
Private Declare Function GetCurrentProcess Lib "kernel32" () As Long
Private Declare Function CloseHandle Lib "kernel32" (ByVal hObject As Long) As Long

Private Declare Function GetProcessTimes Lib "kernel32" (ByVal hProcess As Long, lpCreationTime As FILETIME, lpExitTime As FILETIME, lpKernelTime As FILETIME, lpUserTime As FILETIME) As Long
Private Declare Function FileTimeToLocalFileTime Lib "kernel32" (lpFileTime As FILETIME, lpLocalFileTime As FILETIME) As Long
Private Declare Function FileTimeToSystemTime Lib "kernel32" (lpFileTime As FILETIME, lpSystemTime As SYSTEMTIME) As Long
Private Declare Function GetTickCount Lib "kernel32" () As Long

Function in a form(form1) with a single button (command1):

Function GetProcessTimesAPI(ByRef sStart$, ByRef lKT As Double, ByRef lUT As Double) As String
    ' Accepts variables by reference
    ' Determines Process Start Time, Kernel Mode Nanosecondsx100, User Mode Nanosecondsx100
    ' Returns a zero length string if successful, or an error description if not
    Dim ftCT As FILETIME, ftET As FILETIME, ftKT As FILETIME, ftUT As FILETIME, stCT As SYSTEMTIME
    Dim NanoCT As Double, NanoET As Double, NanoKT As Double, NanoUT As Double, s$, ret&
    Dim MyProcessThreadId&, MyAppProcessId&, MyAppProcessHandle&, r$

    MyProcessThreadId = GetWindowThreadProcessId(Form1.hwnd, MyAppProcessId)
    If MyAppProcessId = 0 Then GetProcessTimesAPI = "GetProcessTimesAPI - Error getting Application Process Id": Exit Function

    MyAppProcessHandle& = OpenProcess(PROCESS_ALL_ACCESS, 0&, MyAppProcessId)
    If MyAppProcessHandle = 0 Then GetProcessTimesAPI = "GetProcessTimesAPI - Error getting process handle": Exit Function
    
    ret = GetProcessTimes(MyAppProcessHandle, ftCT, ftET, ftKT, ftUT)
    If ret = 0 Then GetProcessTimesAPI = "GetProcessTimesAPI - Error getting Process Times": CloseHandle MyAppProcessHandle: Exit Function
    
    ' Filetime returns a 64-bit value representing the number of 100-nanosecond intervals since January 1, 1601 (UTC).
    ' 1 millisec (thousandth of a sec), 1 microsecond (1 millionth of a sec), 1 nanosecond (1 billionth of a second)
    ' To convert the 64 bit number stored in 2 words into a VB double multiply high word by 2^32 then add low word
    NanoCT = ftCT.dwHighDateTime * 2 ^ 32 + ftCT.dwLowDateTime
    NanoET = ftET.dwHighDateTime * 2 ^ 32 + ftET.dwLowDateTime
    NanoKT = ftKT.dwHighDateTime * 2 ^ 32 + ftKT.dwLowDateTime
    NanoUT = ftUT.dwHighDateTime * 2 ^ 32 + ftUT.dwLowDateTime
    
    ' converts the creation time to local time then to system time to make it easily readable
    FileTimeToLocalFileTime ftCT, ftCT
    FileTimeToSystemTime ftCT, stCT
    sStart = stCT.wHour & "h:" & stCT.wMinute & "m:" & stCT.wSecond & "s"
    lKT = NanoKT
    lUT = NanoUT
End Function

Called to test the code in nanosecondsx100 (output to debug windows ctril + g):

Private Sub Command1_Click()
Dim sStart$, KT1#, UT1#, KT2#, UT2#, ret$, s$, GTC1&, GTC2&
GTC1 = GetTickCount
ret = GetProcessTimesAPI(sStart, KT1, UT1)
If Len(ret) Then MsgBox ret: Exit Sub ' there was an error calling the function

'code to time
Dim i&, j&
For i = 0 To 800000
    j = i + 1
    If i Mod 1000 = 0 Then DoEvents
Next i

ret = GetProcessTimesAPI(sStart, KT2, UT2)
If Len(ret) Then MsgBox ret: Exit Sub ' there was an error calling the function
GTC2 = GetTickCount

' Note x nanoseconds by 0.0000001 to get seconds, milliseconds x 0.001 to get seconds
s = s & "Kernel Mode NanoSecs: " & KT2 - KT1 & vbCrLf
s = s & "User Mode NanoSecs: " & UT2 - UT1 & vbCrLf
s = s & "Gettickcount: " & GTC2 - GTC1
Debug.Print s
End Sub

Form attached (click the button, output is to the debug window crtl + g)

[Witis]

Hi lone_REBEL and Cube8, I think you both agree that the cpu is always running doing processing in the background and will always have an impact on the execution time of your application. It is good that the OS spreads out the load over time so that it doesn't overload the CPU at any one time, although when timing your application, even if you are running your code on the same machine with a fresh install, there can be quite a degree of difference in the reported tick count taken to run your code.

What I am trying to do is get a more accurate measure of code performance as it then makes performance comparisons more meaningful, rather than saying well this was the tick count for my code on this machine when I had this software loaded which is then only useful while the computer is set up that way and even then the BG processing distorts the measure somewhat. Although I accept that I might have to put up with less accurate numbers if there are no other alternatives.

[Cube8]

Even benchmarking applications don't have such "strict" requirements.

The only way to force the system to give all cpu resources to your app, is to set its priority to time critical.

[Doogle]

I think you should be using 'Currency' types rather than Double for the 64 bit values (Currency is a 64bit integer (scaled value) as opposed to a floating point representation)

[Witis]

Hi Doogle, I'll try it in a sec, although didn't you mention a 10% variation in 100 ns already, I think that might be it also?
Edit: I wasn't able to use currency - overflow error, doubles should be ok as only working with integers therefore no rounding errors as far as I am aware...

Hi Cube8, give Doogle's suggestion a go. The example in post 10 has been updated and is now in a workable form to test the execution time.

[Doogle]

@Cube: I don't think this is about raising the priority of the application, more one of obtaining repeatable measurements of resources directly attributable to the written code, as opposed to the written code and other resources used by the system, to support its execution.

Elapsed time is not a very good measure as there are so many extraneous factors that will affect the life of a program during execution. (eg I/O Wait time, Paging, thread quantum expiring, other applications executing 'alongside', liberal sprinkling of DoEvents in the code etc) Thus, from test to test the elapsed time could vary considerably.

A better method is to look at the actual CPU usage, which comes in 2 parts, the CPU time used by the application whilst in 'user mode' (ie the CPU time spent executing the actual instructions coded into the program) and the CPU time used in 'kernal Mode' (ie the CPU time spent by the system on behalf of the application). Since the code doesn't change and if you're running on the same CPU, the 'user mode' time should be just about, if not, identical from one execution to the next. The programmer has direct control over the user mode CPU time consumed, so the effects on CPU time attributable to changes in the code can be accurately measured. The kernal mode CPU time shouldn't be ignored though as it is a copmponent of the application's load on the CPU; a 'tweak' to the code may reduce user mode CPU time but increase kernal mode time. (eg doing something via an API rather than native code)

Simply put, if a loop of 100,000 iterations, involving reading / writing data to a file on Disk, takes 40 user mode CPU counts then a loop of 10,000 will take 4 user mode CPU counts. The elapsed times may differ significantly depending upon the performance of the I/O sub-system and other 'uncontrolable' factors at the time of the runs.

It's a reasonable start to understanding the performance of the code you write without the need / expense of a professional Profiler Tool.

(I used to have to do a lot of this sort of stuff in the olden days of Mainframes where CPU time was expensive, eg £3M for the power of one of today's iPods. We used to charge users by CPU seconds and therefore had to have a repeatable representation of it. Whilst the architecture has changed significantly the underlying theory remains valid.)

(all IMHO of course)

[Doogle]

I wasn't able to use currency - overflow error, doubles should be ok as only working with integers therefore no rounding errors as far as I am aware.

That's strange, I'll have a go myself later.

<rest of original post deleted as I got hold of the wrong end of the stick>

[Witis]

Hi Doogle, I think I have some more clues on this one, I have updated post 10 to do a side by side comparison with GettickCount, if you download the form, you can see the variation occurs at the same time time that GetTickCount varies (just keep pressing the button and notice when the results change in the debug window).

[Doogle]

I think you may have misunderstood the user and Kernal mode values returned. They are absolute values used to date.

Using

s = s & "Kernel Mode NanoSecs: " & KT2 & vbCrLf
s = s & "User Mode NanoSecs: " & UT2 & vbCrLf
s = s & "Gettickcount: " & GTC2 - GTC1
Debug.Print s

gives consistant values,for me, for user mode (+/-1 in the last digit with a loop of 10000000.)
Note the fairly large differences in kernal mode values from one execution to the next

EDIT: If you ever wanted to see the effect of DoEvens on a program, try running it with a long loop with and without DoEvents. You'll experience a significant elapsed time difference without a change to user mode CPU.

[Witis]

Doogle, I got some more results e.g.:

Kernel Mode NanoSecs: 0
User Mode NanoSecs: 312002
Gettickcount: 31

Kernel Mode NanoSecs: 0
User Mode NanoSecs: 312002
Gettickcount: 31

Kernel Mode NanoSecs: 156001
User Mode NanoSecs: 312002
Gettickcount: 47

The last result is really strange, my code didn't change, and now it is suddenly recording values for Kernel Mode (I had no previous kernel times at all). As a result these seem to be the absolute values used by the CPU while my process is executing - i.e. while my process was running for 47 milliseconds the CPU spent 312002 nano seconds in User Mode and 156001 nano seconds in Kernel Mode, although it does not seem to tell me anything regarding how much time my process was allocated on the CPU. Although I could be wrong, just suggesting a plausible explanation.

This is not what I expected from the function which was summarised as: "Retrieves timing information for the specified process." (http://msdn.microsoft.com/en-us/libr...(v=vs.85).aspx) which implies that the timings returned apply to one specific process, rather than specifying that the CPU times (user mode and kernel mode) returned are absolute and not process specific.

And it goes on:
"lpKernelTime [out]
A pointer to a FILETIME structure that receives the amount of time that the process has executed in kernel mode. The time that each of the threads of the process has executed in kernel mode is determined, and then all of those times are summed together to obtain this value.

lpUserTime [out]
A pointer to a FILETIME structure that receives the amount of time that the process has executed in user mode. The time that each of the threads of the process has executed in user mode is determined, and then all of those times are summed together to obtain this value."

Again clearly implying that the times returned are process specific not absolute, although my my example and checking seems to reveal that the opposite is actually occurring (the CPU times are absolute not process specific).