DateTime.UtcNow.Ticks sometimes jumps a remarkable amount

Question

In a tightly looped test application that prints out the value of DateTime.UtcNow.Ticks, I notice that the value will jump a remarkable amount once every hour or so. Look closely at the following sample data:

1:52:14.312 PM - 633614215343125000
1:52:14.359 PM - 633614215343593750
1:52:14.421 PM - 633614215344218750
1:52:14.468 PM - 633614215344687500
1:52:14.515 PM - 633614215998593750 <-- WAY different

The delta is 653906250 ticks (65.390 seconds). The only reason I can come up with is that the Windows Time service is doing some synchronization from underneath my feet. Are there any experts out there that can confirm this? Drifting a minute or so in about an hour seems pretty bad to me, but is that the case here?

Thanks in advance.

Answer 1

Can you post code to show how you generated this data? And provide details about the machine you are running this on?

Using the following, I'm not getting what you are getting.

        for (int i = 0; i < 10; i++)
        {

            Console.WriteLine(DateTime.Now.ToLongTimeString().ToString() + " - " + DateTime.UtcNow.Ticks.ToString());

            Thread.Sleep(10);
        }

Answer 2

Actually, just running some test with this loop:

static DateTime past = DateTime.UtcNow;
 static void PrintTime()
 {
  while (stopLoop == 0)
  {
   DateTime now = DateTime.UtcNow;
   Console.WriteLine("{0} - {1} d: {2}", now, now.Ticks, now - past);
   Program.past = now;
   Thread.Sleep(2000);
  }
 }

If I changed my system's clock time in between calls, the delta would jump accordingly. So if you have time synchronization running or some other process that affects system time, then that will be reflected in the output.

Answer 3

Esteban is correct, a system clock change would cause a change in delta time between consecutive polls. Does the Windows Time service make these changes hourly? Is drifting a minute off within an hour likely?

To catch this happening on your machine, if you kept track of the delta in change between checks, you can set a conditional breakpoint on an unusually high change in delta.

long delta = 0;
long ticks = 0;
long lastTicks = DateTime.UtcNow.Ticks;
while (true)
{
    ticks = DateTime.UtcNow.Ticks;
    delta = ticks - lastTicks;
    lastTicks = ticks;
    // Conditional breakpoint: delta > 100000000 Is True
    Console.WriteLine("{0} - {1}", ticks, delta);
}

Answer 4

The original output was caught in DebugView. My managed application was making a p/invoke OutputDebugString call, simply outputting DateTime.UtcNow.Ticks from a tight loop in a thread that also called Thread.Sleep(1).

System information for \\JLECOURSXP:
Uptime:                    6 days 6 hours 22 minutes 53 seconds
Kernel version:            Microsoft Windows XP, Multiprocessor Free
Product type:              Professional
Product version:           5.1
Service pack:              3
Kernel build number:       2600
Registered organization:
Registered owner:          setup
Install date:              6/15/2007, 3:35:29 PM
IE version:                7.0000
System root:               C:\WINDOWS
Processors:                2
Processor speed:           2.9 GHz
Processor type:            Intel(R) Pentium(R) D CPU
Physical memory:           3070 MB
Video driver:              RADEON 9250 - Secondary

Answer 5

Ehm...

How can you measure time this way when you can't tell for sure that you are not calling some blocking system call during this time (Like, potentially Console.WriteLine)?

In order to have a "working test" you would have to at least make sure:

• NOTHING else is running on your machine
• The process/thread priority is set to High or something like that
• Call NO system call... Do only computationl tasks
• Set thread affinity to a specific CPU so you don't get switched between CPUs

Even if you would do that, the OS would from time to time (15ms on a Windows Dual-Core desktop OS for example) preempt your thread.... And you could still definitely see that sort of "jump" in UTC Time-Stamp.

Just going from Userspace to Kernelspace (during a pre-emption / system call) and back, without doing any substantial kernel work, would take ~1000 CPU cycles...

If you process is put into a wait state (by calling some blocking IO) it could even be MUCH MUCH worse...

So I really don't get your "test". IMO this is perfectly normal.

Answer 6

I wish I had an answer for this question, all I have is another data point.

The original posters documented that every so often there were large jumps in time. In our application we see a similar thing except that the large jumps go back about 1 min or so per 50 minutes of time. From our data mining this has just started happing with in the last month. Yes we do a lot of I/O, primarily serial I/O, but a few threads are producing and consuming data through TCP sockets at a fairly hi volume, 100 Kb/50 ms.

Recently in our application we did bump the data rate from 75 ms updates to 50 ms updates, although we don't have any data to suggest that this caused our backward time jumping. We have looked at biosetting and ntp and the data there does not point to backward jumps.