超时后的 WaitForSingleObject 返回很长时间答案

【问题标题】：WaitForSingleObject with timeout returns long after the timeout超时后的 WaitForSingleObject 返回很长时间
【发布时间】：2016-11-12 11:12:27
【问题描述】：

这几乎是遗留代码，涉及一个简单的 TThread，用作计时器，基于 WaitForSingleObject() 和一个事件句柄，就像这样

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;

关于一些特定于应用程序的故障检查（何时不触发）和日志记录，代码有点精简。

日志调用将显示在日志文件中，类似于：

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函数以格式打印NOW的值，$1130是当前线程，llDebug是日志级别。这两个调用之间没有任何记录（日志文件是每个“功能”/“模块”）

在这种情况下，等待时间高达 959 毫秒！？

FEvent 成员是在主线程中创建的（就像线程计时器本身一样），如下所示：

FEvent := CreateEvent(nil, false, false, nil);

所以线程本身不创建窗口，也不使用 COM 或类似的东西。如果 SomeMethod 将使用这样的方法，它会在同步调用中，以便在主线程中执行。然而，对于这个特定的测试，SomeMethod 只是在 TImage 上绘制。

代码计算出 FInterval 为 20 毫秒。线程大约每 30/31 毫秒触发一次，很可能是由于 Windows 计时器分辨率。

我们有 1 位客户运行 Windows 10，WaitForSingleObject() 时不时地（相隔几分钟）只会在 400 多毫秒后返回。

SomeMethod 在 1 毫秒内执行，因为它不做太多处理。

我们不需要高分辨率计时器，因为当前代码在其他任何地方都可以正常工作，而且每 30 毫秒一次就足够了，即使有 10-15 毫秒的“错误”。

计时器控制着一堆操作，这就是它以大约 20 毫秒的间隔执行的原因，但是对于这个问题，我们已经（明确地）消除了其他所有内容，只留下了一个操作运行，这就是我们能够调试并查看的方式WaitForSingleObject() 在 400+ 毫秒后没有返回，每隔几分钟。

WaitForSingleObject() 之前有一个日志调用，之后有一个日志调用（也记录间隔），因此即使间隔为 20 毫秒，也 100% 确定 WaitForSingleObject() 在 400+ 毫秒后返回。日志显示 WaitForSingleObject() 的返回值为 WAIT_TIMEOUT，正如预期的那样。

问题是：WaitForSingleObject() 中出现这种行为的原因是什么？我的意思是，由于 CPU 很忙，我可以多理解几毫秒，线程太多（在这个应用程序中不是这种情况），但在峰值负载低于 30% 的系统上几乎半秒是奇怪的。

谢谢

【问题讨论】：

标签： multithreading delphi winapi

【解决方案1】：

考虑到问题中的日志调用，在计时器线程的Execute 过程中，如果他们最终在同一个线程中写入日志文件，这将阻塞直到写入操作完成。由于开始时间是在第一次写入操作之前检索的，因此日志间隔不仅包括等待时间 (WaitForSingleObject)，还包括第一次写入操作。这可以解释对 30 毫秒而不是 20 毫秒的普遍偏见。行为不端的 I/O 子系统或拥塞也可以解释偶尔延长的时间段。

获取等待操作前的开始时间，但不要写。在等待调用返回后写入开始时间和结束时间。然后日志将更准确地反映等待时间，并且很可能延长的延迟将成为 I/O 绑定。 WaitForSingleObject 不太可能不准确。

还可以考虑将日志写入卸载到工作线程。

【讨论】：