2018年2月13日火曜日

続: 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ミリ秒などざらに発生しますので誤差が出てもわかりません)
まあ、上記を疑ったからこそこういうデータを取ってみたわけですが、このデータからはその疑いは強まったといっていいでしょうか。

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

2018年2月12日月曜日

WIN32APIのWaitForSingleObjectのタイムアウトが早めに発生するケース

WaitForMultipleObjectsでも同じです。

ちょっとしたプログラムを書く際には必ずと言っていいほどお世話になるWaitForSingleObjectWaitForMultipleObjectsですが、表題のケースがあったことを思い出したので今年一本も記事を書いていないためネタにしてみます。

通常、タイムアウト値にINFINITEを指定しない限り、監視対象オブジェクトがシグナル状態にならなければ指定期間(ミリ秒)「以上」経過すると、結果がWAIT_TIMEOUTとして制御が戻ってきます。この期待は、ほぼ裏切られることなくまずこのように動作します。

しかし、まれにそうでなく、「指定時間に達していないのに」数ミリ秒早く「タイムアウト」が発生してしまうというのが今回のお話です。なお、現時点では原因は究明できていません。

例えば、正時毎に時間の数だけハトを鳴かせる鳩時計サービスを作ることを考えてみます。
ざっくり以下のようになると思います。
  1. 次に来るべき正時を求める
  2. 現在時刻を求める
  3. 1から2を引いて時間差を求める
  4. 3で得られた値をタイムアウト値にして、サービス終了指示、時刻変更通知、レジューム通知を監視しながらWaitForMultipleObjectsで待機する
  5. WaitForMultipleObjectsでイベントを検出したら1に戻ってやり直すか終了する。
    いずれのイベントも発生しないままWAIT_TIMEOUTで終了した場合は正時になっているので時刻を取得して時間数に応じてハトを鳴かせる
  6. 1に戻る
ここで、5で正時になる1ミリ秒前に復帰してしまうと、タイムアウト後はまだ59分59.999秒で、時は変わっておらず、正直に(あるいは手抜きで)GetLocalTimeで得られたSYSTEMTIME.wHourをそのまま使用すると意図しない結果になってしまいます。
通常はこんなことは発生しないのですが、発生するケースがあります。

まあ、今回の例では解決策は簡単で、タイムアウト後直近の正時を改めて求めてハト時計の鳴動回数を決定するか、再度不足している時間待機すればいいだけですので対策自体はあっさり完了します。
実際に事象が発生する以上、その対策を盛り込んだコードを書いてそれで終了ですが、そもそもタイムアウトしてはいけないはずの時間にタイムアウトしてくることは気に入りません。

当方では、このような事象が発生するのはシステムがスリープから復帰したあとの初回の時報だけで稀に発生しています。極端なケースでは2ミリ秒も早くタイムアウトしてしまったケースも確認しました。これは「マイクロ秒までは拙者不覚候付御免被下度候」とか口走ってごまかせるような計算誤差などというレベルではない大きな数値です。
しかし、この事象が発生した場合でも、2回目以降は十数時間にわたってきっちり期待通り誤差0~+1ミリ秒程度でタイムアウトを起こし続け、早めにタイムアウトを起こすということは発生しません。
また翌日、スリープから復帰させると再現する場合があるという、偶然にしてはできすぎていますが、かといって調査するには面倒な状況です。

なお、5のイベントは実際のサービスではSERVICE_CONTROL_TIMECHANGESERVICE_CONTROL_POWEREVENTイベントで、そのイベントを受信する都度次の正時を再計算することは言うまでもありません。

そこで、この事象が発生するマシンのスリープ復帰後のwindowsの時刻の較正の手順を見直してみます。なお、時刻合わせはw32tm.exeでNTPサーバと同期させています。
  1. スリープから復帰(システム時刻はスリープ前の時刻とほとんど同じまま)
  2. カーネルによりハードウェアクロックの値をシステム時刻に適用する(ここでシステム時刻は現在時刻になる)
    2.1 サービスに対しSERVICE_CONTROL_TIMECHANGEが送信される
  3. w32tm(Time-Service)がNTPサーバと通信を開始する
  4. Power-Troubleshooterが「システムは低電力状態から再開」を宣言する
  5. 30秒後、w32tm /resyncを発行(これだけは当環境固有)
    5.1 resync完了後サービスに対しSERVICE_CONTROL_TIMECHANGEが送信される。
となっていますが、5.のresync後のイベントログのKernel-GeneralイベントID1を見ると、時間の変更幅は1ミリ秒どころか数十マイクロ秒レベルでしか変化しておらず、多分これはslewモードでの訂正幅1回分ということではないかと思いますので、これは2ミリ秒もタイムアウト時間が早まる原因とは思えません(w32tm.exeの場合、1秒以上((Windowsサーバでは5分以上))NTPサーバと差異があればstepモードで一気に時刻合わせをするという狼藉を働きます)。
加えて、スリープ復帰後に数時間おきに何度もresyncしても同様にタイムアウトが早まる現象は発生しません。

なお、NTPサーバとのオフセット値が実際には10ミリ秒以上あるケースでも5での時間変更幅は数十μ秒です。この値はw32tm /stripchartでperiod:1で計測して変化していく数値と概ね同じなので、やはりまずはslewモードでの訂正幅1回分だけ時刻を変更してSERVICE_CONTROL_TIMECHANGEを発行しているものと思われ、これはこれで期待通りの動作です。
10ミリ秒以上誤差があるのならそれが原因ではないか!?と指摘されそうですが、実際にstripchartを眺めている時間があるなら、このままずっとNTPサーバとローカル時計のオフセットが+(プラス)十数ms~-(マイナス)十数msの間を右往左往し続ける様子を見ることができます。そのように右往左往していながらスリープ復帰直後以外は正しくWaitForSingleObjectのタイムアウトは決して早まることがありません。文字通り指定時間満了をもって「タイムアウト」が発生します。

実はこの事象、個人用途で数年前にざっくり作ったサービスで確認した事象で、上記までは調べて今まですっかり忘れていたところ、先日ふとイベントログを見るとやっぱり現在でも早めにタイムアウトが起きたというログが記録されているのを見て、ネタにしてみた次第です。

もしさらに調べるとしたら、スリープから復帰した直後はw32tmで同期しているときよりもはるかに大きな(しかし1秒未満の)NTPサーバとローカルクロックとのオフセット値があるはずで、それがまずどのような値をとっていたのか、また、タイムアウトが早まってしまう初回の正時までにslewモードでどのようなstripを見せるのか、その際のstrip幅の統計データをコツコツ収集してやる必要がありそうですが、とてもそんなことは今もできないのですが、謎は謎なので、また忘れてしまわないようにチラシの裏に記録する次第です。

結果を求めてここまで読み進められた方には誠に申し訳ございません。