How To Time Managed Code Using QueryPerformanceCounter and QueryPerformanceFrequency
- J.D. Meier, Srinath Vasireddy, Ashish Babbar, and Alex Mackman
Summary
This How To shows you how to create a managed wrapper class to encapsulate the Microsoft® Win32® functions QueryPerformanceCounter and QueryPerformanceFrequency. You can use this class to time the execution of managed code. This How To also provides examples that show you how to use the class to measure the overhead associated with boxing and string concatenation.
Applies To
Microsoft .NET Framework version 1.1
Overview
You can use the Win32 functions QueryPerformanceCounter and QueryPerformanceFrequency to measure the performance of your code to nanosecond accuracy. For comparison, a nanosecond (ns or nsec) is one billionth (10-9) of a second. A millisecond (ms or msec) is one thousandth of a second.
Note At the time of this writing, the .NET Framework 2.0 (code-named "Whidbey") provides a wrapper to simplify using QueryPerformanceCounter and QueryPerformanceFrequency.
Creating a QueryPerfCounter Wrapper Class
In this step, you will create a wrapper class to encapsulate the Win32 function calls used to obtain performance information.
To create the wrapper class
Use Microsoft Visual Studio® .NET or any text editor to create a new C# file named QueryPerfCounter.cs. Add an empty class named QueryPerfCounter as shown.
public class QueryPerfCounter
{
}
Add a using statement to reference System.Runtime.InteropServices so that you can make calls to native Win32 functions.
using System.Runtime.InteropServices;
Create the declarations to call the QueryPerformanceCounter and QueryPerformanceFrequency Win32 APIs as shown.
[DllImport("KERNEL32")]
private static extern bool QueryPerformanceCounter(out long lpPerformanceCount);
[DllImport("Kernel32.dll")]
private static extern bool QueryPerformanceFrequency(out long lpFrequency);
Add a constructor. In the constructor, call QueryPerformanceFrequency, passing a global variable to hold a value that will be used to calculate a duration in nanoseconds.
private long frequency;
public QueryPerfCounter()
{
if (QueryPerformanceFrequency(out frequency) == false)
{
// Frequency not supported
throw new Win32Exception();
}
}
Create a Start method that gets the current value from QueryPerformanceCounter. Use a global variable to store the retrieved value.
public void Start()
{
QueryPerformanceCounter(out start);
}
Create a Stop method that gets the current value from QueryPerformanceCounter. Use another global variable to store the retrieved value.
public void Stop()
{
QueryPerformanceCounter(out stop);
}
Create a Duration method that accepts the number of iterations as an argument and returns a duration value. Use this method to calculate the number of ticks between the start and stop values. Next, multiply the result by the frequency multiplier to calculate the duration of all the operations, and then divide by the number of iterations to arrive at the duration per operation value.
public double Duration(int iterations)
{
return ((((double)(stop - start)*
(double) multiplier) /
(double) frequency)/iterations);
}
Your code in QueryPerfCounter.cs should resemble the following.
QueryPerfCounter.cs
// QueryPerfCounter.cs using System; using System.ComponentModel; using System.Runtime.InteropServices;
public class QueryPerfCounter
{
[DllImport("KERNEL32")]
private static extern bool QueryPerformanceCounter(
out long lpPerformanceCount);
[DllImport("Kernel32.dll")]
private static extern bool QueryPerformanceFrequency(out long lpFrequency);
private long start;
private long stop;
private long frequency;
Decimal multiplier = new Decimal(1.0e9);
public QueryPerfCounter()
{
if (QueryPerformanceFrequency(out frequency) == false)
{
// Frequency not supported
throw new Win32Exception();
}
}
public void Start()
{
QueryPerformanceCounter(out start);
}
public void Stop()
{
QueryPerformanceCounter(out stop);
}
public double Duration(int iterations)
{
return ((((double)(stop - start)* (double) multiplier) / (double) frequency)/iterations);
}
}To compile the code, use the following command line.
csc.exe /out:QueryPerfCounter.dll /t:library /r:System.dll QueryPerfCounter.cs
Using the Wrapper Class
To use the QueryPerfCounter wrapper class in your code, you need to reference QueryPerfCounter.dll and then instantiate the QueryPerfCounter class. Your client code should resemble the following.
QueryPerfCounter myTimer = new QueryPerfCounter();
// Measure without boxing
myTimer.Start();
for(int i = 0; i < iterations; i++)
{
// do some work to time
}
myTimer.Stop();
// Calculate time per iteration in nanoseconds
double result = myTimer.Duration(iterations);
The following sections show examples of how to use the wrapper to time the execution of managed code.
Validating Your QueryPerfCounter Class
In the following example, you will validate your QueryPerfCounter class by creating a simple console application. The application puts a thread to sleep for a specified time so that you can compare the results against your own timing results.
The following example code puts a thread to sleep for one second and loops five times. As a result, each iteration should take one second, and the total duration should be five seconds.
ValidateQueryPerfCounter.cs
// ValidateQueryPerfCounter.cs using System;
public class ValidateQueryPerfCounter
{
public static void Main()
{
RunTest();
}
public static void RunTest()
{
int iterations=5;
// Call the object and methods to JIT before the test run
QueryPerfCounter myTimer = new QueryPerfCounter();
myTimer.Start();
myTimer.Stop();
// Time the overall test duration
DateTime dtStartTime = DateTime.Now;
// Use QueryPerfCounters to get the average time per iteration
myTimer.Start();
for(int i = 0; i < iterations; i++)
{
// Method to time
System.Threading.Thread.Sleep(1000);
}
myTimer.Stop();
// Calculate time per iteration in nanoseconds
double result = myTimer.Duration(iterations);
// Show the average time per iteration results
Console.WriteLine("Iterations: {0}", iterations);
Console.WriteLine("Average time per iteration: ");
Console.WriteLine(result/1000000000 + " seconds");
Console.WriteLine(result/1000000 + " milliseconds");
Console.WriteLine(result + " nanoseconds");
// Show the overall test duration results
DateTime dtEndTime = DateTime.Now;
Double duration = ((TimeSpan)(dtEndTime-dtStartTime)).TotalMilliseconds;
Console.WriteLine();
Console.WriteLine("Duration of test run: ");
Console.WriteLine(duration/1000 + " seconds");
Console.WriteLine(duration + " milliseconds");
Console.ReadLine();
}
}
To compile the code above, use the following command line.
csc.exe /out:ValidateQueryPerfCounter.exe /r:System.dll,QueryPerfCounter.dll /t:exe ValidateQueryPerfCounter.cs
Note the reference to the QueryPerfCounter.dll assembly that you built earlier.
Results
When you run ValidateQueryPerfCounter.exe, the output will resemble the following.
Iterations: 5 Average time per iteration: 0.999648279320416 seconds 999.648279320416 milliseconds 999648279.320416 nanoseconds
Duration of test run: 5.137792 seconds 5137.792 milliseconds
Example A: Boxing Overhead
In the following console application example, you will use your wrapper class, QueryPerfCounter, from your QueryPerfCounter.dll to measure the performance cost of boxing an integer.
BoxingTest.cs
// BoxingTest.cs using System;
public class BoxingTest
{
public static void Main()
{
RunTest();
}
public static void RunTest()
{
int iterations=10000;
// Call the object and methods to JIT before the test run
QueryPerfCounter myTimer = new QueryPerfCounter();
myTimer.Start();
myTimer.Stop();
// variables used for boxing/unboxing
object obj = null;
int value1 = 12;
int value2 = 0;
// Measure without boxing
myTimer.Start();
for(int i = 0; i < iterations; i++)
{
// a simple value copy of an integer to another integer
value2 = value1;
}
myTimer.Stop();
// Calculate time per iteration in nanoseconds
double result = myTimer.Duration(iterations);
Console.WriteLine("int to int (no boxing): " + result + " nanoseconds");
// Measure boxing
myTimer.Start();
for(int i = 0; i < iterations; i++)
{
// point the object to a copy of the integer
obj = value1;
}
myTimer.Stop();
// Calculate time per iteration in nanoseconds
result = myTimer.Duration(iterations);
Console.WriteLine("int to object (boxing): " + result + " nanoseconds");
// Measure unboxing
myTimer.Start();
for(int i = 0; i < iterations; i++)
{
// copy the integer value from the object to a second integer
value2 = (int)obj;
}
myTimer.Stop();
// Calculate time per iteration in nanoseconds
result = myTimer.Duration(iterations);
Console.WriteLine("object to int (unboxing): " + result + " nanoseconds");
Console.ReadLine();
}
}
Compiling the Sample
To compile the code, use the following command line.
csc.exe /out:BoxingTest.exe /r:System.dll,QueryPerfCounter.dll /t:exe BoxingTest.cs
Results
Run BoxingTest.exe. The results show you the overhead when boxing occurs.
int to int (no boxing): 1.22920650529606 nanoseconds int to object (boxing): 77.132708207328 nanoseconds object to int (unboxing): 2.87746068285215 nanoseconds
In the scenario above, an additional object is created when the boxing occurs.
Example B: String Concatenation
In this example, you will use the QueryPerfCounter class to measure the performance impact of concatenating strings. This example allows you to increase iterations so that you can observe the impact as the number of iterations grows.
StringConcatTest.cs
// StringConcatTest.cs using System; using System.Text;
public class StringConcatTest
{
public static void Main()
{
RunTest(10);
RunTest(100);
}
public static void RunTest(int iterations)
{
// Call the object and methods to JIT before the test run
QueryPerfCounter myTimer = new QueryPerfCounter();
myTimer.Start();
myTimer.Stop();
Console.WriteLine("");
Console.WriteLine("Iterations = " + iterations.ToString());
Console.WriteLine("(Time shown is in nanoseconds)");
// Measure StringBuilder performance
StringBuilder sb = new StringBuilder("");
myTimer.Start();
for (int i=0; i<iterations; i++)
{
sb.Append(i.ToString());
}
myTimer.Stop();
// Pass in 1 for iterations to calculate overall duration
double result = myTimer.Duration(1);
Console.WriteLine(result + " StringBuilder version");
// Measure string concatenation
string s = string.Empty;
myTimer.Start();
for (int i=0; i<iterations; i++)
{
s += i.ToString();
}
myTimer.Stop();
// Pass in 1 for iterations to calculate overall duration
result = myTimer.Duration(1);
Console.WriteLine(result + " string concatenation version");
Console.ReadLine();
}
}
Compiling the Sample
To compile the code, use the following command line.
csc.exe /out:StringConcat.exe /r:System.dll,QueryPerfCounter.dll /t:exe StringConcat.cs
Results
With a small number of concatenations, the benefits of using StringBuilder are less obvious. However, with a hundred concatenations, the difference is more apparent. For example:
10 Iterations
Iterations = 10 12292.0650529606 StringBuilder version 20393.6533833211 string concatenation version 100 Iterations
Iterations = 100 62019.0554944832 StringBuilder version 112304.776165686 string concatenation version
