Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

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

Tags:

c#

wpf

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?!?! enter image description here

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();
    }
}
like image 683
Gary Willette Avatar asked Apr 19 '16 17:04

Gary Willette


1 Answers

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.

like image 112
usr Avatar answered Sep 28 '22 05:09

usr