I recently had an article published that shows how to build a Windows Forms application using an accelerometer to measure the performance of a vehicle. By using basic physics equations, a vehicle’s current speed, distance traveled, horsepower, and other performance metrics can be derived from the acceleration values provided by the accelerometer. It's pretty cool, check it out.
http://blogs.msdn.com/coding4fun/archive/2007/02/18/1709215.aspx
http://channel9.msdn.com/ShowPost.aspx?PostID=283953
I was recently at work, and was doing some performance testing on a web service that we created. The web service request message basically consisted of an array of inventory items (mostly books in our case) and the response message returned gave the status of all the items passed to it (such as quantity available, quantity on order, etc.). Anywho, I was getting some really odd times, and I couldn't let it go. Let me explain...
This is how I was doing my timing:
Dim startTime As DateTime = DateTime.MinValue
Dim endTime As DateTime = DateTime.MinValue
Dim elapsedTime As TimeSpan
startTime = DateTime.Now()
'call the web service
inventoryAvailability = invTestObj.RequestInventoryStatus(inventoryItems)
endTime = DateTime.Now()
'get the difference
elapsedTime = endTime.Subtract(startTime)
'this outputs the elapsed time in milliseconds to the console in a nice format
Console.WriteLine(elapsedTime.TotalMilliseconds.ToString("00.000" & Environment.NewLine))
Here is some sample output:
62.5
15.625
15.625
15.625
15.625
31.25
31.25
15.625
(measured in ms)
Notice that every single number is evenly divisible by 15.625? Yeah me too. I was very curious to see why this was the case, since I "knew" that DateTime values represent the number of ticks (each tick being 100-nanoseconds) since 01/01/0001. Since each tick has a granularity of 100ns, I saw no problem with using the DateTime structure for the precision that we needed, as we were more concerned with seconds than with nanoseconds. Regardless, it was frustrating me that every call took either the exact same time, or was divisible by 15.625. I began my mission to solve this issue, and learned a lot doing so... I share with you why this happened, and what to do about it.
Okay, while the DateTime structure can return ticks with a precision of 100ns each, it is only updated 64 times a second, or every 15.625 milliseconds (our magic number). So, although the precision is there, the resolution of the timer is not. So, we now know we cannot use the DateTime structure to get accurate timings when the granularity of the time is small.
Now what?
I wrote a class in VB.NET that you can compile into a library and use whenever you need to do your timing. It has 3 exposed methods, StartTimer, ReturnElapsedTime, and ReturnFomattedElapsedTime.
StartTimer takes in a "identifier" Int32 parameter, so you can have multiple timings per instance of my class. For instance the identifier could be the caller's thread ID (Thread.CurrentThread.ManagedThreadID) so you can keep track of multiple threads.
ReturnElapsedTime takes in an identifier that was previousley used as a parameter for StartTimer, and will return the number of seconds in the form of a Double.
ReturnFomattedElapsedTime takes in an identifier that was previously used as a parameter for StartTimer, and will return the number of seconds in the form of a formatted Double. You can pass in a string format, or just use the default: "00.0000"s.
To use it...
Dim timer As New HighResTimer()
Dim elapsedTime As Double
timer.StartTimer(Thread.CurrentThread.ManagedThreadId)
inventoryAvailability = invTestObj.RequestInventoryStatus(inventoryItems)
elapsedTime = timer.ReturnFormattedElapsedTime(Thread.CurrentThread.ManagedThreadId, "00.0000")
Console.WriteLine(elapsedTime & Environment.NewLine)
You can take a look at the results for yourself, it is very simple to use. I will include my source at the bottom of the screen.
What ended up being used for the timing were 2 API calls from Kernel32.dll, QueryPerformanceFrequency and QueryPerformanceCounter. They are both unmanaged calls that use a pointer to an Int64 to return their values. The first one returns (by reference) the amount of ticks the current computer can do per second (I have read that this will work with multiprocessor or dual core computers). The second function QueryPerformanceCounter, returns the current processor's amount of ticks. (Minimum resolution: 1/1193182 sec (according to Microsoft)).
Here is my code:
After I learned all about timing, I made this class really quick and did not implement the cost of calling the unmanaged code, so if you decide to throw that logic in there, or there is anything you want to know regarding the explanation above, just let me know. Thanks!
Public
Class PerformanceTimer
Private timeTracker As Hashtable
Public Sub New()
timeTracker =
New Hashtable(100) 'I know this isn't the best choice...
End Sub
<System.Runtime.InteropServices.DllImport(
"Kernel32.dll")> _
Private Shared Function QueryPerformanceFrequency(ByRef countsPerSecondForThisMachine As Int64) As Boolean
End Function
<System.Runtime.InteropServices.DllImport(
"Kernel32.dll")> _
Private Shared Function QueryPerformanceCounter(ByRef counts As Int64) As Boolean
End Function
Private Shared Function QueryPerformanceCounter() As Int64
Dim counts As Int64
QueryPerformanceCounter(counts)
Return counts
End Function
Private Shared Function QueryPerformanceFrequency() As Int64
Dim countsPerSecondForThisMachine As Int64
QueryPerformanceFrequency(countsPerSecondForThisMachine)
Return countsPerSecondForThisMachine
End Function
Public Sub StartTimer(ByVal identifier As Integer)
Try
If timeTracker.ContainsKey(identifier) Then Throw New Exception(String.Format("There already is a timer running with identifier '{0}'", identifier))
timeTracker.Add(identifier, QueryPerformanceCounter())
Catch ex As Exception
Console.WriteLine(ex.Message)
End Try
End Sub
Public Function ReturnElapsedTime(ByVal identifier As Integer) As Double
Dim curTime As Int64 = QueryPerformanceCounter()
Dim startTime As Int64
Try
If timeTracker.ContainsKey(identifier) Then
startTime = timeTracker.Item(identifier)
timeTracker.Remove(identifier)
Return CDbl((curTime - startTime) / QueryPerformanceFrequency())
Else
Throw New Exception(String.Format("There is no timer running with identifier '{0}'", identifier))
End If
Catch ex As Exception
Console.WriteLine(ex.Message)
Return Double.NaN
End Try
End Function
Public Function ReturnFormattedElapsedTime(ByVal identifier As Integer, Optional ByVal strFormat As String = "0.0000") As Double
Dim retDbl As Double = ReturnElapsedTime(identifier)
If Not retDbl = Double.NaN Then
Return CDbl(retDbl.ToString(strFormat))
Else
Return Double.NaN
End If
End Function
End
Class