測ることが、対象を変える

本教材の測定環境(Docker Desktop の Linux VM、各条件3回測定)で、同じ strace に2種類の処理を測らせました。

対象                                  素        strace有り   倍率
A: 20万回の write(2)                 0.0457     8.5218     約186倍
B: 200万回の算術ループ(syscall無し)  0.1408     0.1494     約1.06倍

道具もマシンも測定回数も同じで、違うのは対象だけです。素の実行では write 1回あたり約228ナノ秒、strace 越しでは約42.6マイクロ秒。対象より観測の費用が二桁大きい。この8.52秒は、もう元の処理の性質ではありません。

だから**「strace は何倍遅い」という問いには答えがありません**。言えるのは「この道具でこの対象を測ると何倍」までです。strace(1) の man は BUGS 節で減速を認めていますが——

A traced process runs more slowly than a non-traced one.

——倍率やパーセンテージの記述は man のどこにもありません。全文を探して0件でした。

前節Aと同じ処理を strace -c に測らせました。

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
99.90    0.707004           3    200001           write
0.05    0.000324           4        66           rt_sigaction
...

write に 0.707秒と報告されています。ところが同じ実行の所要時間は約8.9秒でした。差は約8.2秒、全体の約92%です。

この差を「strace が自分の費用を引いて消した」と読むのは誤りです。man の -c の節はこう書いています。

This shows system time (CPU time spent in the kernel), which is independent of wall clock time.

-c が集計するのは**カーネル内で使った CPU 時間(system time)**で、壁時計ではありません。-w の節にも The default is to summarize the system time. とあります。約8.2秒の差の主因は、この集計がそもそも壁時計を数えていないことです。-O の推定がこのうちどれだけを引いたかは、出力からも man からも分かりません。

だから 0.707 秒は「間違い」ではなく、答えている問いが違うのです。気づく方法は man 自身が書いています。素の実行を別の手段で計って突き合わせる、それだけです。

カーネル公式も同じです。Documentation/trace/ftrace.rst が71マイクロ秒の遅延をトレースして見せた直後の注記です。

Note that by enabling function tracing, we incur an added overhead. This overhead may extend the latency times.

カーネルが、自分の出した測定値に「観測によって伸びている可能性がある」と添えている。観測の費用は道具の粗さの話ではなく、測るという行為に付いて回る性質です。

なお観測手段をコスト構造で選び分ける話は、図解コース「サンプリングとトレーシング — コスト構造が違う」が扱います。