Tuesday, December 4, 2007

DateTime.Now Precision Issues... Enter StopWatch!

I'm a little bit embarrassed by this one. Previously I bogged about DateTime.Now Precision, or the lack there of. I first discovered this phenomenon while performing my performance tests for my blog post NHibernate Access Performance, which showed the differences between property and field level access within NHibernate.

Basically I found that DateTime.Now was not very precise and worked horribly as a benchmarking tool to test relative performance. Well, now I've come to my senses and realized that the nail I was banging on was really a screw, and using the hammer wasn't really the best tool for the job. I've now come to learn of the screwdriver which answers my benchmarking needs. It turns out the System.Diagnostics.StopWatch class exists for just the purpose I was trying to use DateTime.Now for. DateTime.Now is not supposed to be accurate enough to be used for diagnostics.

The StopWatch class is very simple. To use it you basically construct an instance of the object, Call Start(), perform your operations and then call Stop(). The StopWatch will contain a property ElapsedTicks with the most accurate elapsed time available.

While I wish I knew about this before when I originally recorded the benchmarks, I know about it now, and I always say I enjoy learning new things. With this new found knowledge of the StopWatch class I decided to re-run my NHibernate Access Performance tests to see how they looked. The results were dramatically different than I found with the DateTime mechanism.

First, I re-ran the 100,000 accesses test with two threads running synchronously. This is meant to replace my original test I ran. These results can be seen below. Note that all times are in milliseconds.


I then decided to run these same tests again but this time in a synchronous manner, meaning that only one test would be running at any given time. These results can be seen below:


In truth, these last numbers are probably the most accurate representation of the true performance implications of using the various NHibernate access strategies.

Of interest though is that fact that my earlier tests for property level access were showing values of close to 600 ms for the basic property setter where as a simple switch to the StopWatch showed just 62 ms. There was a difference of a full order of magnitude? I was actually surprised by just how much these numbers varied. It turns out that the accuracy of DateTime.Now is even worse than I thought.

--John Chapman

2 comments:

Barfield said...

The DateTime.Now gets updates around 10 times per second (could be depending on hardware and software setting). So its an 'ok' second and minutes timer. The highfrequencyperformancetimers aka real time clock or stopwatch offer better timing but use up more system resources.

MartinF said...

Hello,

thanks for sharing this.

I know that this post is quite old but i tried downloading the source and run the tests with .Net 4 and the newest build of NHibernate (from Hornget).

I couldnt make the Codedom work but the basic getter and setters test showed that a private field was considerable faster than using a property.

Actually a private field was only about 3 times slower than using the lightweight approach.


Best regards

Martin

Blogger Syntax Highliter