Why is this code executing faster than expected?

I have this code:

    public void replay() {
        long previous = DateTime.Now.Ticks;
        for (int i = 0; i < 1000; i++) {
            Thread.Sleep(300);
            long cur = DateTime.Now.Ticks;
            Console.WriteLine(cur - previous);
            previous = cur;
        }
    }

Which is invoked as a separate thread like this:

        MethodInvoker replayer = new MethodInvoker(replay);
        replayer.BeginInvoke(null, null);

However, if I watch the output, it acts strangely. It outputs i in pairs. For example, it'll wait a full wait, then output i, then quickly output the next i too, then wait again. Why is it doing that and how can I correct it?

It outputs this:

If I increase the sleep to more than a second this doesn't happen.

Solution

Change the code to eliminate display latency in your analysis:

public void replay() 
{        
    Thread.Sleep(5000);
    DateTime start = DateTime.Now;      
    for (int i = 0; i < 1000; i++) 
    {            
          Console.WriteLine(string.Format("Exec:{0} - {1} ms",
                i, DateTime.Now - start));
          start = DateTime.Now;
          Thread.Sleep(300);        
    }
}

Looking at your modified output, there is less than 5% variance (15ms out of the 300) in the loop delay. This is normal, due to the uncertainties involved in when the OS actually assigns timeslices to the thread... (If I recall correctly, in a windows OS, this is normally only every 20 ms !)

The larger discrepancy you perceive in the console output is almost certainly due to display latencys.