Tuesday, April 28, 2009

DateTime.Now Vs. System.Diagnostics.Stopwatch

Occasionally all of us, as programmers would like to see how fast or how slow a C# function can execute. I am sure, most of us must have used DateTime.Now for the measurements. Roughly on these lines,

DateTime startTime = DateTime.Now;

// Some Execution Process

DateTime endTime = DateTime.Now;
TimeSpan totalTimeTaken = endTime.Subtract(startTime);


Now, does DateTime.Now accurately measure performance? No, it does not. DateTime.Now, according to MSDN has a resolution of ~16ms, which means it is not very precise.

Environment.TickCount
Another approach would to use system tickcount as kept by Environment.TickCount. This keeps the number of milliseconds since the computer was started. Unfortunately it is stored as a signed int, so every 49 days it is actually counting backwards. We can compensate for this by just taking off the most siginificant bit.

Stopwatch
Another better approach is to use Stopwatch. System.Diagnostics offers Stopwatch that automatically checks for high precision timers. You can check if the Stopwatch is using high-precision timers by checking via Stopwatch.IsHighResolution() method.


Stopwatch swTimer = Stopwatch.StartNew();
//Some execution process here
foo()
swTimer.Stop();


Watch for the difference in the code results

protected void Page_Load(object sender, EventArgs e)
{
DateTime sStartTime, sEndTime;
TimeSpan tsTotalTimeTaken;

sStartTime = DateTime.Now;
for (long lCount = 0; lCount < 100; lCount++)
{
Thread.Sleep(1);
}//for(int iCount=0; iCount<100; iCount++)

sEndTime = DateTime.Now;

Stopwatch swTimer = Stopwatch.StartNew();

for (long lCount = 0; lCount < 100; lCount++)
{
Thread.Sleep(1);
}//for(int iCount=0; iCount<100; iCount++)

swTimer.Stop();

tsTotalTimeTaken = sEndTime.Subtract(sStartTime);

Response.Write("Elaspsed Time according to DateTime.Now(): " + tsTotalTimeTaken.Milliseconds + "
");
Response.Write("Elapsed Time according to StopWatch(): " + swTimer.Elapsed.Milliseconds);
}



Output:

4 comments:

Dan said...

It's great that you're pointing out the usefulness of System.Diagnostics.Stopwatch; but are you aware that Thread.Sleep(1) is useless? The granularity of Thread.Sleep is generally between 10-16ms, so Thread.Sleep(1) should put the thread to sleep for anywhere between 1 and ~16 ms.

Anonymous said...

Environment.TickCount is also not working.

Anonymous said...

I can't believe that everyone has let Dan's comment stand for this long.

Thread.Sleep(1) is NOT useless in this scenario. Inside a loop like this, if you don't do the sleep(1), you will notice that your CPU gets pegged. With the sleep(1), the cpu doesn't even register the load.

I agree that it is not sleeping only 1ms, but it's used in both examples so it's at least averaged out.

Anonymous said...

There are a couple of things wrong with this test. First, Sleep(1) is an unknown. If you have a very busy system, you do not know exactly how long you will sleep. You only know the minimum is 1ms. I've been running tests recently with creating hundreds of busy threads, and a Sleep(1) sleeps for hundreds of milliseconds when Sleep(1) is called. A Thread.SpinWait or a simple for(1 to 50000) is at least consistent, and measurements can be considered accurate.
The second thing wrong with this test code is that it is only run one time. If you reverse the order of the Stopwatch and DateTime calls, you will have the opposite results thanks to JIT. You should run the test multiple times to get a better reading. I ran 100 times with no difference between the two methods (sometimes there was 1-2ms difference, one way or the other).