Task.Delay in .net fires 125ms early

Question

So I'm having a really strange behavior with a c# task delay that is kind of making me insane.

Context: I'm using C# .net to communicate with one of our devices via R4852. The device needs roughly 200ms to finish each command so I introduced a 250ms delay inside my communication class.

Bug / bad behavior: The delay inside my communication class sometimes waits for 250ms and sometimes only waits for 125ms. This is reproducible and the same behavior occurs when I'm increasing my delay. E.g. if I set my delay to 1000ms every second request will only wait for 875ms, so again there are 125ms missing. This behavior only occurs if there is no debugger attached and only occurs on some machines. The machine where this software will be used in our production department is having this issue, my machine that I'm working on right now doesn't have this issue. Both are running Windows 10.

How come that there are 125ms missing from time to time? I already learnt that the Task.Delay method is using a timer with a precision of 15ms. This doesn't explain the missing 125ms as it at most should fire a few milliseconds too late instead of 125m too early.

The following method is the one I use to queue commands to my device. There is a semaphore responsible so that only one command can be executed at a time (_requestSemapohre) so there can only ever be one request being processed.

public async Task<bool> Request(WriteRequest request)
{
    await _requestSemaphore.WaitAsync();    // block incoming calls
    await Task.Delay(Delay);                // delay
    Write(_connectionIdDictionary[request.Connection], request.Request);           // write
    if (request is WriteReadRequest)
    {
        _currentRequest = request as WriteReadRequest;
        var readSuccess = await _readSemaphore.WaitAsync(Timeout); // wait until read of line has finished
        _currentRequest = null;                 // set _currentRequest to null
        _requestSemaphore.Release();            // release next incoming call
        if (!readSuccess)
        {
            return false;
        }
        else
        {
            return true;
        }
    }
    else
    {
        if (request is WriteWithDelayRequest)
        {
            await Task.Delay((request as WriteWithDelayRequest).Delay);
        }
        _requestSemaphore.Release();            // release next incoming call
        return true;
    }
}

The following code is part of the method that is sending the requests to the method above. I removed some lines to keep it short. The basic stuff (requesting and waiting) is still there

// this command is the first command and will always have a proper delay of 1000ms
var request = new Communication.Requests.WriteRequest(item.Connection, item.Command);
await _translator.Request(request);

// this request is the second request that is missing 125ms
var queryRequest = new Communication.Requests.WriteReadRequest(item.Connection, item.Query);    // query that is being sent to check if the value has been sent properly
if (await _translator.Request(queryRequest))    // send the query to the device and wait for response
{
    if (item.IsQueryValid(queryRequest.Response))   // check result
    {
        item.Success = true;
    }
}

The first request that I'm sending to this method is a WriteRequest, the second one a WriteReadRequest.

I discovered this behavior when looking at the serial port communication using a software named Device Monitoring Studio to monitor the serial communication.

Here is a screenshot of the actual serial communication. In this case I was using a delay of 1000ms. You can see that the sens0002 command had a delay of exactly 1 second before it was executed. The next command / query sens?only has a 875ms delay. This screenshot was taken while the debugger was not attached.

Here is another screenshot. The delay was set to 1000ms again but this time the debugger was attached. As you can see the first and second command now both have a delay of roughly 1000ms.

And in the two following screenshots you can see the same behavior with a delay of 250ms (bugged down to 125ms). First screenshot without debugger attached, second one with debugger attached. In the second screenshot you can also see that there is quiet the drift of 35ms but still nowhere close to the 125ms that were missing before.

So what the hell am I looking at here? The quick and dirty solution would be to just increase the delay to 1000ms so that this won't be an issue anymore but I'd rather understand why this issue occurs and how to fix it properly.

Cheers!

Answer 1

As far as I can see, your times are printed as delta to the prev. entry.

In case of the 125/875ms you have 8 intermediate entries with each roughly 15ms (sum roughly 120ms)

In case of 250/1000ms you have 8 intermediate entries with each roughly 5ms (sum roughly 40ms) and the numbers are actually more like 215/960ms.

So, if you add those intermediate delays, the resulting complete delay is roughly the same as far as I can tell.

---

Answering the question for everyone who just wants a yes / no on the question title: The First Rule of Programming: It's Always Your Fault

It's save to assume, that Task.Delay covers at least the specified amount of time (might be more due to clock resolution). So if it seems to cover a smaller timespan, then the method used to test the actual delay is faulty somehow.