Windows上で扱うタイムスタンプ関数には謎の遅延(空白時間）が生まれる？

簡単な状況説明

現在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

jbpb0

2023/05/25 02:18

一応リアルタイムosであるwindows ce https://ja.wikipedia.org/wiki/Microsoft_Windows_Embedded_CE でも、 https://www.cqpub.co.jp/interface/toku/200010/toku1_3.htm 「Windows CEやLinuxなどの場合は，割り込みマスク時間以前に割り込み応答時間自身が，数msから数十msのオーダである」だそうです (リアルタイムosではない)普通のwindowsなら、なおさら

qwerty022986

2023/05/25 02:51

ご回答ありがとうございます。これはTickタイマーからの割り込み部分を言及されていますか？まあどちらにせよWindowsでリアルタイム要求の高いアプリケーションは動かすな、という話ですかね…

jbpb0

2023/05/25 03:16

https://www.cqpub.co.jp/interface/toku/200010/toku1_3.htm の「図11」の直前に、「割り込み応答時間」は「割り込みが発生してから割り込みハンドラにコントロールが移るまでの時間を指す」と説明されてます

tmp

2023/05/25 09:05

time.perf_counterを２度呼んでその差が1ms以上なるか確認してみましたが、不定期に最大2ms程度の差は出ますが、周期的にはでませんし、10msも発生しませんでした。 CPythonでperf_counterを見たらQueryPerformanceFrequency,QueryPerformanceCounterが使われていたので（https://github.com/python/cpython/blob/main/Python/pytime.c#L1236） C言語でもQueryPerformanceFrequency,QueryPerformanceCounterで確認すると、不定期の1ms,2ms程度の同じ症状になりました。 timespec_getは、同じ症状にはなりませんでしたが、もっと変なことになった（放置、多分別の問題）以上により、推測すると定期的に同じ時間空くので、gcの処理時間ではないでしょうか？ gc.disable();などで同じ結果になりますか？といろいろ書いてますが、pythonは、使っていないのでよくわかりません.

行動規範の内容に同意します

回答2件

単にpytonのGC待ってるだけとか、ret.appendのアロケーションにかかってるだけでは？

ret.append部を除いて、代わりに
if t1-t0>0.001: print( t1,t0)
t0=t1
みたいなコード挟んだけど、このif文のprint発火しなかったですよ。

投稿2023/05/25 09:10

matukeso

総合スコア1590

空白期間でコンテキストスイッチが起きて CPU が他のプロセスを実行しているのではないでしょうか。
Windows ではタイムスライスが 10ms 単位とかだった記憶があります。

投稿2023/05/25 01:26

int32_t

総合スコア20856

qwerty022986

2023/05/25 02:20

ご回答ありがとうございます。やはりそうなんでしょうね… できる限り他のプロセスは起動しないようにしてはいるのですがこれは避けられないのでしょうかね… もしWindowsで・Python等の1アプリで１CPUを占有・さらに同時に走る他プロセスをなくすなどの原因切り分けできる手段をご存知でしたらご教示願いたいです

int32_t

2023/05/25 02:36

プロセスがコンテキストスイッチを起こした回数をカウントする分析ツールがあるようなので、それを使えばこれが原因かどうかは判定できるかもしれません。 >・Python等の1アプリで１CPUを占有 >・さらに同時に走る他プロセスをなくすそれは、できないはずです。できたらマルチタスクOSとして重大な欠陥となります。

qwerty022986

2023/05/25 04:39

そのようなツールがあるのですね。少し探してみたいと思います。ありがとうございます。＞それは、できないはずです。できたらマルチタスクOSとして重大な欠陥となります。やはりそうですよね…WindowsIoTであればコアのアイソレーションはできたと記憶しているのですが、通常Windowsでは無理ですよね…

行動規範の内容に同意します

あなたの回答