続: WaitForSingleObjectのタイムアウトが早まるケース

前回こちらで記事を書いた後、せっかくなのでタスクスケジューラにNTPサーバとローカル環境との時間差データを取得するバッチを仕込んだところ、幸運にもスリープから復帰後2ミリ秒早まるケースが発生しました。
おまけに、さらにその1時間後の正時でも1ミリ秒の短縮が認められるという大幸運に恵まれましたので、早速取得したデータを眺めてみます。

※本記事はほんとに時間に気を遣うならそもそもWindowsは不向きなのは承知の上の興味本位の記事であり、数ミリ秒の誤差がケシカランなどとWindowsを責め苛む意図はありませんので、その点は予めご承知おきください(実際のところ、きちんとシステムを管理してしっかりプログラムを設計すればWindowsもかなりイケます)。

まず、スリープから復帰時に行ったw32tm /resync時点では以下の通りでした。

• SERVICE_CONTROL_TIMECHANGEがサービスに送信されたときのイベントログ
  (Kernel-General イベントID1)
  

  システム時刻は ‎2018‎-‎02‎-‎12T22:55:29.830597600Z から ‎2018‎-‎02‎-‎12T22:55:29.830579500Z に変更されました。

  例によって数十μ秒しか変わっていません。
• resync直後のNTPサーバとのオフセット(w32tm /monitorの値)
  

  ICMP: 0ms 遅延
NTP: -1.5356179s ローカル コンピューターの時刻からのオフセット

  1.5秒以上のずれがあります(※当環境のw32tmではこの時間差ではstepモードにはなりません)。
  オフセットがマイナスということはシステム時刻のほうが進んでいるということになります。
• 正時5分前のslewの様子
  

  07:55:31, d:+00.0004389s o:-01.5356436s
07:56:31, d:+00.0004562s o:-01.5180269s
07:57:29, d:+00.0004936s o:-01.4946638s

  1分あたり10~20ミリ秒の勢いでオフセットが縮まっています。
  ※slewモードで時刻が修正されている間はSERVICE_CONTROL_TIMECHANGEがサービスに送信されることはありません。
• スリープ復帰後3時間後のslewの様子(比較用)
  

  10:57:15, d:+00.0004337s o:-00.0187345s
10:58:15, d:+00.0003669s o:-00.0174196s

  1分当たり1.314ミリ秒しか変わっていません。

上記に加え、さらにresyncをせずに1時間経過した後に1ミリ秒早まったケースは以下の通りです(このケースは今まで一度も見たことがありませんでした)。当然、resyncを行っておらず、stepモードでの訂正もないため、この間はSERVICE_CONTROL_TIMECHANGEイベントは発生しません。そのため、9時までのタイムアウト時間を計算したタイミングは8時の処理が終わった直後になります。

• NTPサーバとのオフセット(w32tm /monitorの値)
  

  ICMP: 0ms 遅延
NTP: -0.4659728s ローカル コンピューターの時刻からのオフセット

• 正時3分前のslewの様子
  

  08:57:38, d:+00.0003108s o:-00.4597637s
08:58:38, d:+00.0003417s o:-00.4496952s
08:59:38, d:+00.0003683s o:-00.4396189s

  この段階でもいまだに1分当たり10ミリ秒単位で時間が縮まっています。
• スリープ復帰後3時間後のslewの様子は前述のため省略します。

2時間以後の鳩時計ではタイムアウト時間が早まることはありませんでした。

以上の観察から、タイムアウトが早まる理由を考察してみます。

• 今回のケースではシステム時刻のほうがNTPサーバよりも進んでいたため、NTPサーバと同期するにはシステム時刻を短くする必要がある
• w32tmはntpdとは異なりなるべく短時間にｼｽﾃﾑ時刻をNTPサーバに同期させようとする設計思想がある
• WaitForSingleObject,WaitForMultipleObjectsはタイムアウト時間が与えられたのち、一定時間毎に待機経過時間をミリ秒という伸びたり縮んだりする時間ではなくTSCなどCPUクロックをもとにしたtickを加算する形式で管理しているのではないか
• そのため、一定時間ごとに補正していても、tick解像度に対してslewモードで補正された伸縮幅が大きすぎて補正しきれず、時刻との誤差が累積してしまうのではないか
• 結果として、タイムアウト時間が本来期待するミリ秒数よりも早まるのではないか
  (タイムアウト時間が遅延するのはそれこそ100ミリ秒などざらに発生しますので誤差が出てもわかりません)

まあ、上記を疑ったからこそこういうデータを取ってみたわけですが、このデータからはその疑いは強まったといっていいでしょうか。

ま、どなたの役にも立たないと思いますが、とりあえず分かったような気になったのでとりあえずこの辺で。
お読みいただきありがとうございました。