C# await Task.Delay(1000); only takes 640ms to return

Question

So, this is simple to explain, but I have searched and cannot find anyone with the same issue. My problem originated in a long-term periodic task which was running more frequently than I wanted. It seems every Task.Delay() I create and await returns in about 65% of the delay I specified in ms.

The problem boiled down to the following line of code returning in roughly 640-660ms (According to visual studio. I set a breakpoint on this line of code and the one following it, and it said that's how long had passed):

await Task.Delay(1000); 

On two other machines, the IDENTICAL code base runs just fine. Not only this simple statement above, but the periodic tasks as well. Is there a setting somewhere that would affect Task.Delay(int millisecondsDelay)? Tick type, clock speed, anything, system clock??? I am at a loss...

EDIT:

In the snippet below, EtMilliseconds is anywhere from 130-140ms, which is the same approx. 65% of expected duration seen above. Never anything outside that (besides the first time into the while() which is irrelevant).

Long EtMilliseconds;
Stopwatch etWatch = new Stopwatch();
etWatch.Restart();

while (true)
{
  EtMilliseconds = etWatch.ElapsedMilliseconds;
  taskDelay = Task.Delay(200);
  etWatch.Restart();
  await taskDelay;
}

EDIT 2:

The following code causes EtMilliseconds to be once again 131ms or so. Using Thread.Sleep seems to have no effect...

public partial class MainWindow : Window
{
    public MainWindow()
    {
        InitializeComponent();
    }

    private void button_Click(object sender, RoutedEventArgs e)
    {
        long EtMilliseconds;
        Stopwatch etWatch = new Stopwatch();
        etWatch.Restart();

        while (true)
        {
            EtMilliseconds = etWatch.ElapsedMilliseconds;
            label.Content = EtMilliseconds.ToString();
            etWatch.Restart();
            Thread.Sleep(200);
        }
    }
}

This snippet is the same but uses Task.Delay(200). This one updates the GUI label correctly (the Thread.Sleep does not) and it is either 131 or 140ms. Always...

public partial class MainWindow : Window
{
    public MainWindow()
    {
        InitializeComponent();
    }

    private async void button_Click(object sender, RoutedEventArgs e)
    {
        Task taskDelay;
        long EtMilliseconds;
        Stopwatch etWatch = new Stopwatch();
        etWatch.Restart();

        while (true)
        {
            EtMilliseconds = etWatch.ElapsedMilliseconds;
            label.Content = EtMilliseconds.ToString();
            taskDelay = Task.Delay(200);
            etWatch.Restart();
            await taskDelay;
        }

    }
}

EDIT 3:

Using DispatcherTimer instead, I still get approx 130ms from my Stopwatch.ElapsedMilliseconds... BUT here's the strange thing. If I also update a display of DateTime.Now(), they increment by just about 200ms (or slightly more), which is what I would expect. What the?!?!

public partial class MainWindow : Window
{

    public long etMilliseconds;
    public Stopwatch etWatch;

    public MainWindow()
    {
        InitializeComponent();
        this.DataContext = this;
    }

    //  System.Windows.Threading.DispatcherTimer.Tick handler
    //
    //  Updates the current seconds display and calls
    //  InvalidateRequerySuggested on the CommandManager to force 
    //  the Command to raise the CanExecuteChanged event.
    private void dispatcherTimer_Tick(object sender, EventArgs e)
    {
        // Updating the Label which displays the current second
        tBoxCurrTime.Text += DateTime.Now.ToString("yyyy_MMM_dd-hh:mm:ss.fff_tt") + "\n";
        tBoxMilliSecElapsed.Text += etWatch.ElapsedMilliseconds + "\n";
        etWatch.Restart();

        // Forcing the CommandManager to raise the RequerySuggested event
        CommandManager.InvalidateRequerySuggested();
    }

    private void button_Click(object sender, RoutedEventArgs e)
    {
        etWatch = new Stopwatch();

        //  DispatcherTimer setup
        DispatcherTimer dispatcherTimer = new System.Windows.Threading.DispatcherTimer();
        dispatcherTimer.Tick += new EventHandler(dispatcherTimer_Tick);
        dispatcherTimer.Interval = new TimeSpan(0, 0, 0, 0, 200);
        dispatcherTimer.Start();

        etWatch.Restart();
    }
}

Answer 1

Just to close this out, in case anyone else is having a similar issue, I found the solution to my problem. About a month ago, my Windows 7 'Aero' effects began to move VERY slowly. In searching for a solution to that problem, I found the following:

http://www.tomshardware.com/forum/57307-63-slow-motion-aero-transitions

The solution I used, which is in the link above, is to:

Run CMD as administrator. Type "bcdedit /set useplatformclock true" and press enter (w/o quotation marks). Restarted computer and my problems were resolved.

I don't fully understand the inner-workings of that command, so if someone would like to elaborate, please do. But I know that not only did it solve my slow aero effects, but my stopwatch timer is on the nose now!

Thanks for all your efforts guys, I do appreciate it!

Gary

Answer 2

I'm putting out a guess answer based on the experiments done so far.

The Stopwatch class uses the Windows "performance counter". I have often read that on some systems it returns inaccurate data. This appears to happen with older hardware and/or older operating system versions.

For example, the time can jump around based on what core you are executing on. This probably is not the issue here because your timings are consistently off. But it's an example of problems with this kind of time data.

I guess that Visual Studio uses Stopwatch as well.

This also fits the fact that the problem only happens on your machine. The other machines probably have different time hardware.

Try this:

var sw = Stopwatch.StartNew();
var startDateTime = DateTime.UtcNow;

Thread.Sleep(200);

sw.Stop();
var endDateTime = DateTime.UtcNow;

And post the results. My prediction is that the Stopwatch version is wrong and the DateTime-based version shows a little over 200ms.

As far as I'm aware the Windows Kernel uses the time source that DateTime.UtcNow uses for it's own timers and delays. AFAIK that is a hardware interrupt that, by default, ticks at 60Hz and causes the timer to update a global time variable at that rate. This means that even if DateTime.UtcNow is wrong it should be consistent with Thread.Sleep. But we know that DateTime.UtcNow is right. Otherwise you would have noticed significant system time drift.

Maybe you can try disabling the piece of hardware that provides Windows with the high frequency counter. Stopwatch.IsHighResolution should return true now and should become false when you disable this piece of hardware. On my machine it's called "HPET" in the device manager.