High-Precision Code Timing in .NET
By Peter A. Bromberg, Ph.D.
Printer - Friendly Version
Peter Bromberg

We get a lot of questions here at eggheadcafe.com about how to time code execution and how to create timers. I even wrote a code execution timer / logger component some months ago in VB.NET and posted it as an article here. We've even gotten "come on" posts from people who have written timing components and post seemingly "innocent" questions, when their real intention is just to sell their component!



 

One of the interesting things I found out is that even though the resolution of the Ticks property of the System.DateTime structure is stated as 100 nanoseconds (1 / 10 millionth of a second), there is no way you will ever get this kind of resolution using it. The reason is because of the thread context switch process, the DateTime.Now value has a resolution of 16 milliseconds or thereabouts on most machines.

However, it is possible to use the QueryPerformanceCounter API to get a very precise measurement of the time as it has a frequency component that is dependent on your CPU frequency. The frequency component basically measures how many times per second the counter is updated. You can get all the gory details from this KB: http://support.microsoft.com/default.aspx?scid=KB;en-us;Q172338, including how to compute the overhead of the API itself on a timer in order to make it "self adjusting".

There are a number of excellent examples of how to call these APIs both on the newsgroups and on various .NET related sites; so please don't waste your money paying $10, 20 or even $40 for somebody's "timer component"!

I put together my own class library implementation of this technique, along with a Logging class library that writes to a CSV file that will come up in Excel. Since each log entry is identified by a GUID in string form, it is possible for multiple processes to be writing to the log at any given time. Of course, when the CSV file gets very big it will start to affect your timings, but I have found this extremely useful for testing different parts of code. In fact, what I usually do is use the config file with a custom appSetting "Logging" that can be set to "true". At the top of each class in the project, we have a global variable "blnLogging" that checks to see if the config setting wants logging on. At this point in our code we can simply wrap calls to the logging component in "if" tests or use compiler directives and we are on our way.

First, the code for the Timer:

using System;
using System.Runtime.InteropServices;
using System.ComponentModel;
using System.Threading;
namespace PAB
{
public class HiPerfTimer
{
[DllImport("Kernel32.dll")]
private static extern bool QueryPerformanceCounter(out long lpPerformanceCount);
[DllImport("Kernel32.dll")]
private static extern bool QueryPerformanceFrequency(out long lpFrequency);

private long startTime ;
private long stopTime;
private long freq;
/// <summary>
/// ctor
/// </summary>
public HiPerfTimer()
{
startTime = 0;
stopTime = 0;
freq =0;
if (QueryPerformanceFrequency(out freq) == false)
{
throw new Win32Exception(); // timer not supported
}
}
/// <summary>
/// Start the timer
/// </summary>
/// <returns>long - tick count</returns>
public long Start()
{
QueryPerformanceCounter(out startTime);
return startTime;
}
/// <summary>
/// Stop timer
/// </summary>
/// <returns>long - tick count</returns>
public long Stop()
{
QueryPerformanceCounter(out stopTime);
return stopTime;
}
/// <summary>
/// Return the duration of the timer (in seconds)
/// </summary>
/// <returns>double - duration</returns>
public double Duration
{
get
{
return (double)(stopTime - startTime) / (double) freq;
}
}
/// <summary>
/// Frequency of timer (no counts in one second on this machine)
/// </summary>
///<returns>long - Frequency</returns>
public long Frequency
{
get
{
QueryPerformanceFrequency(out freq);
return freq;
}
}
}
}

And finally, the code for the Logging Class:

using System;
using System.IO;
using System.Text;
using System.Diagnostics;

namespace PAB
{
public class Logging
{
public double StartTicks;
public double EndTicks;
public double cumTime;
public string ActiveGUID=String.Empty;
public string strLogFileName = String.Empty;
private HiPerfTimer hpt;
public Logging(string strFileName)
{
if(strFileName!="")
{
strLogFileName = strFileName;
}
else
{
strLogFileName="DefaultAppLog";
}
hpt = new PAB.HiPerfTimer();
}

public string StartLogEntry(string strLogEntryName, string strComment)
{
string lf=String.Empty;
if (strLogFileName != "")
{
lf = @"\" + strLogFileName + ".csv";
}
else
{
lf =@"\DefaultAppLog.csv";
}
string strFullLogPathName= System.AppDomain.CurrentDomain.BaseDirectory.ToString() + lf;
string strLogEntryGUID= Guid.NewGuid().ToString();
ActiveGUID = strLogEntryGUID;
string strtime = DateTime.Now.ToShortDateString() + ": " + DateTime.Now.ToShortTimeString();


hpt.Start();
StartTicks= 0;// set to zero
cumTime=0;
Debug.WriteLine(StartTicks.ToString());
StringBuilder sbLog =new StringBuilder();
sbLog.Append("New Entry: ");
sbLog.Append(",");
sbLog.Append(strLogEntryGUID);
sbLog.Append(",");
sbLog.Append(strtime);
sbLog.Append(",");
sbLog.Append(strLogEntryName);
sbLog.Append(",");
sbLog.Append(strComment);
sbLog.Append("| Caller: ");
string strCallAssy = System.Reflection.Assembly.GetCallingAssembly().ToString();
strCallAssy = strCallAssy.Substring(0, strCallAssy.IndexOf(",") );
sbLog.Append(strCallAssy);

sbLog.Append(",");
sbLog.Append("0");
sbLog.Append(",");
sbLog.Append("0");
sbLog.Append("\r\n");
try
{
FileInfo fi = new FileInfo(strFullLogPathName);
FileStream sWriterAppend = fi.Open(FileMode.Append, FileAccess.Write, FileShare.ReadWrite);
sWriterAppend.Write(System.Text.Encoding.ASCII.GetBytes(sbLog.ToString()), 0, sbLog.Length);
sWriterAppend.Flush();
sWriterAppend.Close();
sbLog = null;
fi = null;
sWriterAppend = null;
}
catch (Exception ex)
{
sbLog = null;
return ex.Message;
}
return strLogEntryGUID;
}

public string AddLogEntry(string strLogEntryGUID , string strLogEntryName,string strComment)
{
if (strLogEntryGUID != ActiveGUID)throw new Exception("Log Entry GUID Mismatch.");

string lf =String.Empty;

if(strLogFileName.Length >0)
{
lf = @"\" + strLogFileName + ".csv";
}
else
{
lf = @"\DefaultAppLog.csv";
}

string strFullLogPathName= System.AppDomain.CurrentDomain.BaseDirectory.ToString() + lf;
string strtime = DateTime.Now.ToShortDateString() + ": " + DateTime.Now.ToShortTimeString();

hpt.Stop();
EndTicks =hpt.Duration;
cumTime+=EndTicks; // add to cum time elapsed

StringBuilder sbLog = new StringBuilder();
sbLog.Append("Add Entry: ");
sbLog.Append(",");
sbLog.Append(strLogEntryGUID);
sbLog.Append(",");
sbLog.Append(strtime);
sbLog.Append(",");
sbLog.Append(strLogEntryName);
sbLog.Append(",");
sbLog.Append(strComment);
sbLog.Append(",");
string strIntElapsed =String.Empty;


sbLog.Append(EndTicks.ToString()); // this event duration in sec
sbLog.Append(",");
strIntElapsed = cumTime.ToString();
hpt.Start();
sbLog.Append(strIntElapsed);
sbLog.Append("\r\n");
try
{
FileInfo fi = new FileInfo(strFullLogPathName);
FileStream sWriterAppend = fi.Open(FileMode.Append, FileAccess.Write, FileShare.ReadWrite);
sWriterAppend.Write(System.Text.Encoding.ASCII.GetBytes(sbLog.ToString()), 0, sbLog.Length);
sWriterAppend.Flush();
sWriterAppend.Close();
sbLog = null;
fi = null;
sWriterAppend = null;
}
catch (Exception ex)
{
sbLog = null;
return ex.Message;
}
return strLogEntryGUID;
}

public string CloseLogEntry(string strLogEntryGUID,string strLogEntryName,string strComment)
{
if (strLogEntryGUID != ActiveGUID)
{
throw new Exception("Log Entry GUID Mismatch.");
}
string lf= String.Empty;

if( strLogFileName != "")
{
lf = @"\" + strLogFileName + ".csv";
}
else
{
lf = @"\DefaultAppLog.csv";
}

string strFullLogPathName = System.AppDomain.CurrentDomain.BaseDirectory.ToString() + lf;
string strtime = DateTime.Now.ToShortDateString() + ": " + DateTime.Now.ToShortTimeString();
hpt.Stop();
EndTicks =hpt.Duration;
cumTime+=EndTicks; // add to cum time elapsed
StringBuilder sbLog =new StringBuilder();
sbLog.Append("Close Entry: ");
sbLog.Append(",");
sbLog.Append(strLogEntryGUID);
sbLog.Append(",");
sbLog.Append(strtime);
sbLog.Append(",");
sbLog.Append(strLogEntryName);
sbLog.Append(",");
sbLog.Append(strComment);
sbLog.Append(",");
sbLog.Append(EndTicks.ToString());
sbLog.Append(",");
sbLog.Append(cumTime.ToString());
sbLog.Append("\r\n");
try
{
FileInfo fi = new FileInfo(strFullLogPathName);
FileStream sWriterAppend = fi.Open(FileMode.Append, FileAccess.Write, FileShare.ReadWrite);
sWriterAppend.Write(System.Text.Encoding.ASCII.GetBytes(sbLog.ToString()), 0, sbLog.Length);
sWriterAppend.Flush();
sWriterAppend.Close();
sbLog = null;
fi = null;
sWriterAppend = null;
StartTicks = 0;

EndTicks = 0;
cumTime=0;
}
catch (Exception ex)
{
sbLog = null;
return ex.Message;
}
return strLogEntryGUID;
}
}


}

 

This will give you resolution between calls ranging in the .10 millisecond range (ten one-hundredths of a millisecond), suitable for highly precise code execution timing and logging. The table shows the time in seconds for each event, and the final column will show the cumulative time. If multiple processes have been writing log entries, they can be sorted easily by GUID once loaded in Excel. Here is sample output from the Excel CSV file:

New Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class Initialize class| Caller: TestPrecisionTimer 0 0
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.634454 0.634454
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.196146 0.8306
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.288015 1.118615
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.183828 1.302442
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.167697 1.470139
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.177111 1.64725
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.158721 1.805972
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.175908 1.98188
Add Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class kick off stored proc XYZ 0.167967 2.149847
Close Entry: fa578921-9a8f-44cd-94d9-2f0ccd9cbc46 11/12/2002: 10:56 AM DB Class returned from sproc XYZ 0.482202 2.632048

My Logging Timer Component is very easy to use. Say you have some different operations going on in your code and you would like to isolate how much time each portion of the code is really taking:


PAB.Logging lg = new PAB.Logging(""); // default app log filename in ctor or specify one
string strGUID=lg.StartLogEntry("Class name/ method name ","Description / comments");
// strGUID is used for subsequent calls
// your database code call here , when call returns:

lg.AddLogEntry(strGUID,"Class name/ method name ","Description / comments");

// you can use AddLogEntry as many times as you wish
// when your event is completed:

lg.CloseLogEntry(strGUID,"Class name/ method name ","end of whatever call");

// CloseLogEntry extinguishes this GUID and allows you to begin another "set" of logging events associated //by a new GUID. Multiple active code blocks can all be writing events at the same time.

If you want, you can download a full C# solution that has a Test Harness WinForms project in it that shows the use of the logging class in combination with the High Performance Timer class with a bunch of buttons that show various details of operation.

 

Download the Code that accompanies this article

 


Peter Bromberg is a C# MVP, MCP, and .NET consultant who has worked in the banking and financial industry for 20 years. He has architected and developed web - based corporate distributed application solutions since 1995, and focuses exclusively on the .NET Platform.