Stopwatch and DateTime.UtcNow producing unexpectedly large timing variations

Question

We have application logs that record performance information for various expensive operations. We use both Stopwatch and DateTime.UtcNow in our logging, and we are finding that these values can differ MUCH more than would be expected, even given DateTime.UtcNow's ~20ms precision. My question is what could cause this and can it be fixed?

The information recorded is:

• StartTime (DateTime.UtcNow)
• Duration (TimeSpan.FromSeconds((after - before) / (double)Stopwatch.Frequency), where after and before are the values of Stopwatch.GetTimestamp() at the beginning and end of the operation
• EndTime (DateTime.UtcNow)

You would expect EndTime to be close to StartTime + Duration, but in some cases it is way off. We sampled 10000 such measurements, looking for cases where EndTime and (StartTime + Duration) differed by more than 20ms. We found the following:

• ~2% of entries are off by > 20ms
• Of these, they are off by an average of 100ms (max is 1.4seconds)
• Of these, in some cases the stopwatch-calculated end time is greater than the DateTime-based end time, but in most cases the stopwatch time is smaller

Machine info

• Windows Server 2012 R2 Hyper-V VM running on top of Windows Server 2012 R2
• 32GB ram for VM, 8 virtual CPUs

Answer 1

This is to be expected. StopWatch uses QueryPerformanceCounter (QPC) under the hood, while DateTime.UtcNow uses the computer's real-time clock (RTC).

• QPC comes from your CPU's timestamp counter (TSC), and is highly precise, but has no basis for accuracy with relation to UTC.
• The RTC is on the computer's motherboard, and is usually built with cheap crystal oscillators. It is accurate, but not precise.

For measuring elapsed time, you want precision, and thus should use Stopwatch.

For getting the current time of day, you want accuracy, and thus should use DateTime.UtcNow.

A great read with lots of supporting details can be found here on MSDN.

The variations you've measured are due to clock drift in the RTC. Your RTC will (all by itself) fall a few milliseconds ahead or behind of real time. This is quite common, and is periodically corrected by NTP synchronization. For minor adjustments, the OS will spread out the correction in smaller intervals, a few milliseconds at a time, over the course of several seconds.

As far as a workaround goes, you could consider a class like this:

public static class PreciseClock
{
    private static readonly DateTime StartTime = DateTime.UtcNow;
    private static readonly Stopwatch Stopwatch = Stopwatch.StartNew();

    public static DateTime GetCurrentUtcTime()
    {
        return StartTime + Stopwatch.Elapsed;
    }
}

However, the downside is that you are making the assumption that the RTC is in perfect sync when the class is initialized. In reality, you have no guarantee of that.

If you wanted some level of guarantee, you might consider making the NTP call yourself. I've implemented a class that does exactly that in NodaTime.NetworkClock. It implements the IClock interface from Noda Time. It periodically makes a call to an NTP server, and tracks the time between calls using a Stopwatch. You would use it like this:

// grab the clock's singleton instance
var clock = NetworkClock.Instance;

// optionally set the ntp server during your app's startup
clock.NtpServer = "pool.ntp.org"; // or whatever server you want to sync with

// Get the current utc time whenever you like
DateTime utcNow = clock.Now.ToDateTimeUtc();

Also, there is such a thing as a "Multimedia Timer", or "High Precision Event Timer" (HPET) that is available on most modern hardware. It offers even greater precision than QPC. However, there is no direct class that exposes that in .NET Framework. If you search you will find a few implementations that wrap the Win32 functions that provide it. Usually, this is overkill unless you're doing real-timey things like graphics or audio.