簡単な状況説明
現在WindowsOS上でPythonもしくはC++を使用してあるアプリケーションをテストしています。そのアプリケーション内ではPCから後段につながるデバイスの状態をロギングするため、現在時間(nsオーダー)や○○カウンタ値、エラー値などを時間経過ごとに配列に格納し、最終的にxlsx (or csv)として出力しています。
今回、質問させて頂いたのは、成果物のログファイルを確認すると定期的に数十msオーダーの空白期間が生まれることに気づきました。この空白時間の原因についてしばらくデバッグを行いましたが、各種時間関数を使用して現在時間を取得する際に偶に大きな遅延が発生していることがわかり、結果としてWindowsOSのTickを生み出すハードウェアもしくはそのデバイスドライバに起因し、すなわちこれはOSレベルの問題ではないかと考えるまでに至りました。ただ、論理の飛躍や他にも考量しきれていない点等があるかと存じます。
このような現象を経験された方、もしくはWindowsOSレベルで知見のある方やそれ以外にも様々な意見をご教示いただけますと幸いです。
これまでに試したこと
- Pythonのtime.perf_counter()関数をWhileループの中で回してロギングする、贅肉のない非常にシンプルなデバッグ用アプリを作成+テスト → 空白時間発生
- Pythonの別関数(time.time())を使用して同様のテスト → 発生。
- C++のtimespec_get()を使用して同様のテスト → 発生。この時点でOSレベルの話だと思い始める
- これまでのテストもWindows上の他アプリケーションは立ち上げないでパフォーマンステストをしていたが、スタートアップのプロセスも全て停止(セキュリティ関係も)してテスト(他のプロセス影響を懸念) → 結果ほぼ変わらず。
- さらに今度は各種ブラウザやアプリケーションを立ち上げ、今度は色々なプロセスが走っている状況で同様のテスト → 結果ほぼ変わらず。
これらの結果を踏まえて、各言語の時間関数は、大元にはTickカウンターのようなものがありOSがこのHWを参照して各言語の各時間関数を使えるようにしていて、このデバイスドライバの部分に何か問題があるのか?という推測の流れです。ただ、デバイスドライバ部分にこのような問題(バグ)があるとは考えにくく、上記試行をしても除去しきれていない他プロセスの影響があるのか?という気もする。
テストコードサンプル
この空白時間をデバッグした際のコードは以下のような非常に簡単なコードです。
Python
1def time_monitor(): 2 t0 = t1 = cnt = pcol = 0 3 ret = [[]] 4 while True: 5 if cnt > 500000: 6 break 7 # get current time 8 t1 = time.perf_counter() 9 # t1 = time.time() 10 ret.append([t1, pcol]) 11 cnt += 1 12 pcol += 1 13 if pcol == 512: 14 pcol = 0 15 print("done.") 16 pandas.DataFrame(ret).to_excel("time.xlsx")
ロギンググラフ例
上記のようなコードでロギングを行った結果のグラフが以下になります。縦軸は上記コードのpcolに該当し、毎サイクルごとにインクリメントされます。横軸がtime.perf_counter()等の時間関数で取得した現在時間(秒オーダー)であり、定期的にプロットがない領域(白い部分)がご確認いただけると思います。これが数十msほどの空白時間で時間関数の遅延により発生しています。この結果はPythonの他の時間関数や他の言語(C++)を使用しても多少違いはあれど同じような結果になります。
補足情報(FW/ツールのバージョンなど)
- Pythonアプリの実行はVScode、IDLE等を使用
- Python 3.7 , 3.10
- Windows 10, 11
