CODEWITHSUNDEEP
.netwindowsdatetimetime
Jeffrey LeCours
Jeffrey LeCours

Reputation: 1473

DateTime.UtcNow.Ticks sometimes jumps a remarkable amount

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.

Upvotes: 2

Views: 3581

Answers (5)

damageboy
damageboy

Reputation: 2117

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.

Upvotes: 1

Jeffrey LeCours
Jeffrey LeCours

Reputation: 1473

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

Upvotes: 0

Jeffrey LeCours
Jeffrey LeCours

Reputation: 1473

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);
}

Upvotes: 0

Esteban Brenes
Esteban Brenes

Reputation: 1163

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.

Upvotes: 2

Matt Lacey
Matt Lacey

Reputation: 65586

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);
        }

Upvotes: 0

Related Questions