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

WaitForMultipleObjectsでも同じです。

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

通常、タイムアウト値に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_TIMECHANGEやSERVICE_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幅の統計データをコツコツ収集してやる必要がありそうですが、とてもそんなことは今もできないのですが、謎は謎なので、また忘れてしまわないようにチラシの裏に記録する次第です。

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