Why is this code executing faster than expected?

Question

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:

3125040
2968788
2968788
2968788
3125040
2968788
2968788
2968788
3125040
2968788
2968788
2968788
3125040

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

Answer 1

Your sleep inside the loop is only 300ms, which isn't very long. You application will do the following:

• Sleep 5 secs
• print 0
• Sleep 300ms
• print 1
• Sleep 300ms
• print 2

etc.

Answer 2

Cannot reproduce. I wonder if it is something local to your machine; buffering, perhaps.

Answer 3

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.

Answer 4

I can't reproduce this, but you might want to consider a timer. It would be more reliable.

public class Counter
{
    private readonly TimeSpan initialDelay, incrementDelay;
    private readonly int maxCount;
    private Timer timer;
    private int count;

    public Counter(TimeSpan initialDelay, TimeSpan incrementDelay, int maxCount)
    {
        this.maxCount = maxCount;
        this.initialDelay = initialDelay;
        this.incrementDelay = incrementDelay;
    }

    public void Start(Action<int> tickBehavior)
    {
        if (timer != null)
        {
            Timer temp = timer;
            timer = null;
            temp.Dispose();
        }
        timer = new Timer(() =>
            {
                tickBehavior(count++);
                if (count > maxCount) timer.Dispose();
            }, null, initialDelay, incrementDelay);
    }
}

Use it:

Counter counter = new Counter(TimeSpan.FromSeconds(5), TimeSpan.FromSeconds(.3), 1000);
counter.Start((count) => Console.WriteLine(count););

EDIT

I'm using System.Threading.Timer, but Counter could be easily be modified to use System.Timers.Timer or System.Windows.Forms.Timer depending on your need. See this link for a description of when to use which timers.