WaitForSingleObject with timeout returns long after the timeout
There is this almost legacy code, involving a simple TThread, used as a timer, based on WaitForSingleObject() and an event handle, like so
TTimerThread = class(TThread)
private
FInterval: cardinal;
FEvent: THandle;
FSomeClass: TSomeClass;
protected
procedure Execute; override;
end;
....
procedure TTimerThread.Execute;
var res: cardinal;
begin
repeat
log('Start WaitForSingleObject() with %d', [FInterval]);
res := WaitForSIngleObject(FEvent, FInterval);
log('End WaitForSingleObject() with result %d', [res]);
if res = WAIT_TIMEOUT then
if not Terminated then
Synchronize(FSomeClass.SomeMethod);
until Terminated;
end;
The code is a bit stripped down, in respect of some app specific failchecks (when not to fire) and logging.
the log calls would show up in log file as similar to:
2016/11/12 17:49:08:056 $1130 llDebug Start WaitForSingleObject() with 20
2016/11/12 17:49:09:015 $1130 llDebug End WaitForSingleObject() with result 258
Log function prints the value of NOW with format, $1130 is the current thread, llDebug is the loglevel. There is nothing logged between these 2 calls (the log file is per "functionality"/"module")
In this case the wait was for a whopping 959 ms !?
the FEvent member is created in the main thread (just as the thread timer itself) like so:
FEvent := CreateEvent(nil, false, false, nil);
So the thread itself does not create windows, nor uses COM or anything like it. If the SomeMethod would be using such, it's in a Synchronized call so that executed in the main thread. For this particular test however, the SomeMethod just draws on a TImage.
The code calculates the FInterval to be 20 ms. The thread fires at about every 30/31 ms, most likely due to windows timer resolution.
We have 1 customer running windows 10, where the WaitForSingleObject(), every now and then (a good few minutes apart) will only returns after 400+ ms.
The SomeMethod executes in 1 ms, as it doesn't do much processing.
We don't require a high resolution timer because the current code works fine pretty much everywhere else, and once per 30 ms is just plenty, even with a 10-15 ms "error".
The timer controls a bunch of operations, which is why it executes at roughly 20ms interval, however for this issue we have eliminated everything else (explicitly) and left only 1 operation running, that's how we were able to debug this and see the WaitForSingleObject() not returning after 400+ ms, every few minutes.
There is a log call right before WaitForSingleObject() and one right after (also logging the interval), so it's 100% sure the WaitForSingleObject() returns after 400+ ms even though the interval is 20ms. Logging shows the return value of WaitForSingleObject() being WAIT_TIMEOUT, as expected.
The question is: what could be causing this behavior in WaitForSingleObject()? I mean I can understand a few ms extra due to CPU being busy, too many threads (not the case in this app) but almost half a second on a system with peak load less than 30% is weird.
Thanks
Considering the logging calls in the question, in the timer thread's Execute procedure, if they end up writing to log file in the same thread, this would block until the write operation is complete. Since start time is retrieved before the first write operation, then the log interval would include not only the wait time ( WaitForSingleObject ) but also the first write operation. This can explain the general bias towards 30ms instead of 20ms. A misbehaving I/O subsystem or congestion can also explain occasional extended time periods.
Retrieve the start time before the wait operation, but don't write it. Write both start and end times after the wait call returns. Then the logs will reflect waiting time more accurately and most likely the extended delays will turn out to be I/O bound. It's very unlikely that WaitForSingleObject would be inaccurate.
Also consider offloading log writing to a worker thread.
链接地址: http://www.djcxy.com/p/62484.html上一篇: 如何发现在pac中使用的de代理