【ITニュース解説】Your Timer Is a Wall Clock, Not a Stopwatch: Four Elapsed-Time Myths and a Monotonic Probe

システムエンジニアを目指す初心者が、プログラムの実行時間を正しく計測することの重要性を理解する上で、この記事は非常に役立つ。多くの開発者が無意識のうちに行っている誤解や間違いについて解説し、正確な時間計測やリクエスト管理のための実践的な方法を提示している。

まず、プログラムが特定の処理にどれくらいの時間を要したかを測定するのは、一見単純に思えるが、実は非常に奥深い問題だ。例えば、同じ処理の実行時間をログとダッシュボードで確認すると、全く異なる数値が表示されることがある。これはどちらかが嘘をついているわけではなく、参照している「時間」の基準が異なるためだ。この混乱を避けるために、いくつかの共通の誤解を解き明かす必要がある。

最初の大きな誤解は、「time.time()の値を2つ取得してその差を計算すれば、それが処理時間になる」というものだ。多くの人がこの方法を用いるが、これは正しくない。time.time()が示すのは、通常「エポック（1970年1月1日0時0分0秒UTC）からの経過秒数」であり、「今何時か」という「壁時計（ウォールクロック）」の役割を果たす。しかし、コンピュータのウォールクロックは、時刻同期プロトコル（NTP）による時刻調整や、システムのサスペンド（一時停止）からの復帰などによって、急に時刻が進んだり、場合によっては戻ったりすることがある。このような調整が入ると、2つのtime.time()の値の差は、実際にかかった時間とは大きく異なるものになる。場合によっては負の値になることさえある。

正確な経過時間を測定するためには、「単調増加する（モノトニック）クロック」を用いるべきだ。LinuxシステムでいうCLOCK_MONOTONICのようなもので、Pythonではtime.monotonic()関数がこれに該当する。このクロックはシステムが起動してからの経過時間を返し、途中で時刻が調整されたり、前後したりすることが絶対にない。したがって、処理の所要時間を測る際にはtime.monotonic()を使うのが正しい。一方、time.time()のようなウォールクロックは、ログに「いつイベントが発生したか」というタイムスタンプを付与する際に利用するのが適切だ。つまり、ウォールクロックは「ラベル付け」に、モノトニッククロックは「期間の測定」に使うという明確な区別が重要になる。

次に、「プログラムのタイマーが突然大きく飛んだ場合、それはホストがスリープした証拠だ」という誤解がある。モノトニッククロックの値に大きなギャップ（飛び）がある場合、それは確かにプログラムがその期間、実行されていなかったことを示している。しかし、その原因がホストのスリープだけとは限らない。プロセスのCPUリソースが制限された（スロットリング）、他のプロセスにCPUを奪われた（プリエンプション）、あるいは入出力処理（I/O）が完了するまで待機していたなど、様々な理由でプログラムの実行が一時停止することがある。原因を特定せずに「スリープした」と決めつけると、適切な対策を講じることができない。

この問題に対処するためには、ウォールクロックとモノトニッククロックの両方を並行して記録し、それぞれの時間の進み具合（デルタ）を比較することが有効だ。両者のデルタを比較し、「ウォールクロックのデルタは大きいのに、モノトニッククロックのデルタが小さい」という状況であれば、それはウォールクロック自体が調整されたことを示唆している。反対に、「モノトニッククロックのデルタが大きく、ウォールクロックのデルタとほぼ一致している」場合は、プログラムが実際に長時間スケジュールされなかったことを意味する。このように両方の情報を組み合わせることで、漠然とした推測ではなく、具体的なデータに基づいて原因を特定できるようになる。

三つ目の誤解は、「タイムアウトが発生したら、それはリクエストが完全に失敗したことを意味する」というものだ。プログラムから外部サービスへのリクエストが一定時間内に応答しなかった場合、プログラムはタイムアウトと判断し、処理を中止することがある。しかし、この「タイムアウト」は、あくまで「自分のプログラム側での観測」に過ぎない。外部サービス側では、リクエストの処理が継続されており、タイムアウト後に完了している可能性も十分にある。この状況で、タイムアウトしたからといってすぐに同じリクエストを再試行すると、外部サービス側で同じ処理が二重に実行されてしまう恐れがある。これは、データの重複、不必要な課金、あるいは予期せぬ副作用を引き起こす可能性があるため、非常に危険だ。

この問題の解決策は、「重複排除キー（deduplication key）」を使用することだ。リクエストの内容から一意のハッシュ値を生成し、これをキーとして記録する。例えば、リクエストのペイロード（送るデータ）を正規化してハッシュ化することで、そのリクエストが過去に実行されたものと同じかどうかを判別できるようになる。このキーを、メモリ上の変数に保存するだけでなく、ファイルやデータベースなどの永続的なストレージに保存することが重要だ。これにより、プログラムが途中で再起動しても、過去のリクエスト履歴を参照し、重複した処理を防ぐことができる。タイムアウトは「不明」な状態を意味し、不明な状態には重複排除キーが不可欠だ。

四つ目の誤解は、「無料のモデルを使っているから、リトライは何回してもコストがかからない」という考えだ。確かに、サービス自体の費用は無料かもしれないが、「時間」という最も貴重なリソースは決して無料ではない。リトライを繰り返すことで、プログラム全体の実行時間が大幅に伸びてしまう可能性がある。例えば、30秒のタイムアウト設定で3回リトライした場合、本来数秒で終わるはずの処理が90秒以上かかることもあり得る。これは、システムの応答性低下や、他の重要な処理のリソース圧迫など、目に見えないコストにつながる。

このような無駄な時間を削減し、プログラムの実行効率を高めるためには、処理にかかる時間を適切に管理することが求められる。具体的には、外部サービスへの呼び出しを共通のラッパー関数で包み込み、その中でtime.monotonic()を使って実行時間を計測する仕組みを導入すると良い。さらに、バッチ処理全体に対して実行時間の上限（予算）を設定し、その予算を超過しそうになったら、残りの処理を中止してクリーンに終了するようなロジックを組み込むことも効果的だ。また、先に述べた重複排除キーと組み合わせることで、既に処理済み、あるいは実行中にタイムアウトしてしまったリクエストに対しては、無駄なリトライを行わずにスキップできる。ただし、time.monotonic()はシステムの起動からの時間を測るものであり、異なるホスト間での比較や永続的な保存には適さない点に注意が必要だ。

これらの原則をまとめると、プログラムにおける時間の扱い方について以下のような指針が得られる。イベントの発生時刻を知りたい場合は、タイムゾーン情報も含むUTC形式のウォールクロックを使用する。処理の所要時間を測定したい場合は、単調増加クロックであるtime.monotonic()を用いる。特定のリクエストが過去に実行されたものと同じかどうかを判別するには、リクエストの内容から生成したコンテンツハッシュをキーとして利用する。ホストがスリープしたかどうかを判断するには、ウォールクロックとモノトニッククロックの両方の進み具合を比較する。ジョブの実行をいつ停止すべきかを決定する際には、単調増加クロックを用いたデッドライン（期限）を設定する。

ただし、これらのアプローチにも限界がある。ここで紹介した方法で得られるデータは、あくまで「単一のホストで、ある一定期間に何が起こったか」という証拠に過ぎない。外部プロバイダーのサービスレベルアグリーメント（SLA）や、特定のハイパーバイザー内部の挙動に関する詳細な情報を示すものではない。また、一度の計測だけでシステムの性能を評価するベンチマークとは異なる。システムの稼働状況が異なる様々な期間で繰り返し計測を行うことで、初めて信頼できるデータが得られる。さらに、この方法はハードリアルタイム保証が必要なシステムや、厳密な請求・監査システムには不向きであり、状態を永続的に保存できない環境では重複排除キーも機能しない。そして何よりも、計測結果を実際に確認し、そこから得られる教訓を活かさなければ、ツール自体の価値は半減してしまう。

今日からできる簡単な一歩として、まず自分の環境でpython3 -c "import time; print(time.get_clock_info('monotonic'))"を実行し、利用可能なモノトニッククロックの情報を確認してみると良いだろう。そして、もし自分のコードの中に、2つのtime.time()の値を引き算して処理時間を計測している箇所があれば、そこをtime.monotonic()を使った計測に修正することを強く推奨する。この一つの変更だけでも、多くのシステムでより正確な実行時間計測が可能になり、問題解決の大きな手がかりとなるはずだ。あなたのプログラムのタイマーは、これまでどれくらいの時間、真実を語っていなかったのだろうか。