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. |
|