プログラムでなく、ループを測る — mere-ruby の spec 掃きを 90 分から 11 分にした日

mere-ruby は、自作の小さな ML 系言語 Mere で書いた Ruby サブセット処理系だ。 その適合性の記録はリポジトリに入った表で、ruby/spec の全群を本物の ruby と バイト単位で突き合わせて作る。作るのに 1 時間半かかっていた。いくつか着地する日は 1 日 6 回掃くのが普通なので、作業日の大半が掃きだった。

遅いのは処理系だと思い込んでいた。その思い込みは一度も測られていなかったし、 書き留める価値のある形で間違っていた。

最初の正直な測定

spec 1 ファイルを、ハーネス越しに、時計を当てて:

real 2.71   user 0.15   sys 1.89

user 0.15 秒。 2 つの処理系 — mere-ruby と参照の ruby — を合わせても小さな ファイルなら 0.1 秒ほど。残りは全部ファイルシステムで、それはハーネス自身の仕業だった。 require_relative と隣の shared/ や fixtures/ が解決するように、spec の木 （core・language・library・shared・fixtures）をファイルごとに 一時ディレクトリへ複製していたのだ。

1 ファイルにつき 4,333 ファイル。記録の 2,498 ファイル分で、1 回の掃きに約 1,080 万回。

数字を見れば直しは自明で、木を 1 回だけ作って各実行に渡す。90 分が 30 分になった。

2 つ目の代償は内側からは見えなかった。これだけファイルシステムを掻き回すと macOS の fseventsd が CPU 100% 超・数 GB 常駐に張り付き、掃きが終わった後も数時間そのままで、 マシン上の他のすべて — 次の掃きを含めて — が最大 8 倍遅くなる。その遅さを処理系の デッドロックだと読んで 1 時間を溶かした。ps aux | sort -k3 -rn 一発で犯人は分かった。

ハーネスが答えを決めていた

掃きが 3 倍速くなれば、次は並列化が自明の一手だ。群は独立していて、マシンは 10 コアある。 動いた。そして記録が動いた — 処理系には一切触れていないのに、2 回。

上限	記録が言ったこと
逐次	core/dir 18 DIFF・1 SLOW、全体で CRASH 0
6 ワーカー、同じ上限	core/dir 14 DIFF・5 SLOW
6 ワーカー、上限を両方 ×6	SLOW 13 → 4、そして CRASH 0 → 4

同一バイナリ、3 通りの表。差は DIFF・SLOW・CRASH の間を、どの上限が先に鳴るかで 滑っていた — そして上限はすべて wall clock だった。単独なら 24 秒のファイルは、 他に 5 本ワーカーがいれば 40 秒かかる。判定は処理系についての事実ではなく、 負荷についての事実になっていた。

その表にはもう一つ教訓が埋まっている。最初の修正は外側の上限を伸ばして何も変わらなかった。 ファイルが越えていたのは別の、内側の上限だったからだ。1 つの問いに 2 つの上限を持つ ハーネスは、片方をあなたから隠す。

本当に意味している量で縛る

「これは終わるか」は時計でなく CPU についての問いだ。25 CPU 秒を使うファイルは、 ワーカーが 1 本でも 6 本でも 25 秒使う。だから:

• SPEC_CPU（25 秒、RLIMIT_CPU）が「終わるか」に答える
• SPEC_WALL はその 24 倍で、「そもそも動いていない」プロセスだけを捕まえる。 比で書くと意図が残る — wall の 24 分の 1 も CPU を使っていないなら、それは待っている
• 外側の上限は SPEC_WALL から導出する。だから最初に鳴ることがありえない
• バイトが 3 つ目の上限で、掃きが番人を自分で起動するようにした。 手で起動する運用だったそれは、半日落ちていた

これを計画した前提は誤りで、測ったら即座にそう言われた。私は「stdin で止まる spec が いくつかあり CPU を使わないので、CPU 上限だけでは足りない」と書いていた。 実測すると、記録にある遅いファイル 9 本は全部 CPU 律速（84〜99%）。 私はその spec が何についてのものかという記憶から、あの文を書いていた。

SIGKILL は処理系が落ちたのではない

表の CRASH は「ruby が落ちないところで mere-ruby が落ちる」— 処理系についての主張と 定義されている。メモリ番人に殺された実行は分類器には「出力なし」として届くので、そこに 記録されていた。7 GB 欲しがるが動いてはいるファイルについて、記録は「処理系が落ちた」と 言っていた。

3 つの上限はいまや 1 つの判定 — ハーネスが止めた — を出し、行がどれかを名指す。 CRASH はまた 1 つのことだけを意味するようになった。

⚠ これは CRASH 0 を回復させるが、処理系は何もそれを勝ち取っていない。 分類し直しただけなので、その下にある事実 — ruby が数 MB で済むところで 2 つの spec が 6 GB を越える — は、欠落を記録する文書に書いた。欠落はそこに属する。

そして、記録は測定ではない

その修正の最初の版は、行に実測値を書いた — used 25.3s of 25s CPU, peaked 5.22 GB。 分類は安定し、記録は悪化した。不一致な行が 2 つから 7 つに増えたのだ。 5.22 GB と 5.01 GB は同じ事実で、違うバイトだからである。

記録と測定は求めるものが逆だ。 記録は 2 回読んで同じでなければならず、 測定は動くところにこそ価値がある。行には分類を、数値は commit しない per-run の log へ。

記録が私を捕まえた

これらすべての後、掃きは MATCH 1758 を返した。1764 ではなく。 6 ファイル、すべて core/env、MATCH から DIFF に落ちていた。

環境変数 1 個。wall 上限を内側のシェルに渡すために、ハーネスの許可リストへ足していた。 そして core/env は ENV のキー数を数える。両側が環境の見え方を別々に組み立てるので、 両方に足しても余分なキーは無料ではない — そして許可リストの上のコメントには、 まさにそれが、前回それで落ちた 5 ファイルの名前つきで書いてある。私はそれでも足した。

変数を消してもまだ 1 つずれていた。シェルが 1 段、これも余分だったのだ。 シェルは丸ごと消した。alarm のために perl はもともと鎖の中にいるので、 いまは perl が fork し、リダイレクトし、リストで exec し（シェルを介さない）、 alarm で子を kill する。環境には何も足されない。

読んでいては見つからなかった一つ

記録が再現するようになっても、1 ワーカーと 6 ワーカーで 1 行だけ動いた — core/exception/interrupt_spec。逐次では完走して DIFF になる。6 ワーカーでは参照 ruby が wall clock 10 分・CPU 0.07 秒で座り込み、wall 上限に当たっていた。

この spec は「自分の SIGINT で死ぬはずの子」を待っている。

シェルはバックグラウンドで起動したジョブの SIGINT と SIGQUIT を SIG_IGN にする。 そして SIG_IGN は fork だけでなく exec も越えて継承される。ワーカーは ( … ) & だ。 つまり 6 ワーカーではその下の全 spec プロセスが SIGINT を無視し、 1 ワーカー（前景）では誰も無視しなかった。

同じ popen を	結果
前景から	子が死ぬ（SIGINT (signal 2)）
背景のサブシェルから	子が死なない

並列の掃きは被検体の予定を変えていたのではなく、被検体そのものを変えていた。 exec 前の 2 行で直り、並列実行のたびに付いていた 10 分の尾が消えた。

私はこの症状をその日の早い時間に **「2 つの事実を結びつけられていない — 所見ではなく 未解明の問い」**として記録していた。その上には、整ってはいるが全部外れている説明が 3 つ並んでいる。明示的に未解明と書いたからこそ、後で見つけられた。 自信のある 1 文を書いていたら、問いは閉じていた。

測って捨てた 6 つの案

棄却した一覧は、記録の中でいちばん再利用されると思っている部分だ。 同じ数字を見た次の人は、同じ案を思いつくのだから。

案	実測	判定
参照側の出力を掃き間でキャッシュ	30 分のうち約 2 分	木の修正前なら 10 倍の価値があった
peak RSS から判定を取る	曖昧な 2 ファイルは両方の上限を超えている	答えの無いものは解けない
行に実測値を書く	不一致な行が 2 → 7	上記のとおり
大きい群から配る	719.9s 対 ベースライン 646–662s	遅い
6 でなく 10 ワーカー	736.7s、CPU は +50s	遅い。律速は共有された直列資源
corpus のプロセスごとに一意な /tmp	あるプログラムが File.basename(__FILE__) を出力する	両側は別プロセス。バイト一致が壊れる

最後の 2 つは一言ずつ価値がある。10 ワーカーが同じ結果により多くの CPU を使ったのは 競合で、残る律速が共有された直列資源だと言っている — 掃きの CPU の半分は system 時間、 つまりファイルシステムだ。並べ替えても本数を増やしてもそこは動かない。

結果

	前	後
ビルド + ゲート	約 6 分	約 4 分
フル記録の掃き	90 分、のち 30 分	11 分
8 本の source gate	約 29s	4.95s
うち 1 本 dead_defs_check	22.99s	0.64s
bracket_depth	75.04s	11.97s
corpus、両モード	111.65s	70.0s
CI	11 分 04 秒	8 分 34 秒

dead_defs_check がいちばん素朴だ。定義ごとに awk を 1 つ起動し、それぞれが使用箇所の 表を丸ごと走査していた — 2,575 プロセスで 7,577 識別子、1,950 万行スキャン。 2 つの表を 1 つの awk に読み込めば同じ問いに答えられる。

記録自体は動いていない: 103 群、2,498 ファイル、MATCH 1764、CRASH 0。 1 ワーカーと 6 ワーカーでバイト単位に一致するようになり、それが本来の主張で、 速さはその帰結にすぎない。

測り方について私が間違えたこと

スケジューリングの案を 2 つ試したら両方遅く出た。そのとき macOS のストレージ索引が CPU の 150% を食っていた。測定不能として両方撤回した — 数時間離れた 3 回の掃きは 比較ではない。

それから対照を走らせた。無改造のハーネスを、同じ負荷の下で。646 秒。 7 時間にわたるベースラインと整合している。負荷は高いが安定していた — 交絡ではなく定数で、2 つの変更はその外側に十分離れていた。 撤回のほうが誤りで、それを見つけたのは対照だった。

⚠ 居心地の悪い方の半分。その索引は午前中から見えていて、私はその時点で記録している。 それが「交絡」に格上げされたのは、数字が試している変更に不利に出てからだった。 大きい群から配って 10% 速く出ていたら、対照を取らずに commit していたはずだ。

だから規則は「意外な結果を疑え」ではない。前後は同じ窓の中でペアにすること。 そして疑うかどうかは、どう測ったかで決めること — どちらに転んだかで決めないこと。

余談 — 文書も同じ病気だった

これは全部書いてあるかと訊かれて、私は「はい」と答えた。それから確認した。

ループの文書は追記式で、3 回の編集が、生きている問いにもう真ではなくなった答え方を している節を 3 つ残していた。読者が最初に当たるのは一番古いものだ。 別の節は、後の測定が否定した主張をまだ掲げていた。173 行が本文と矛盾していた。

私はその日ずっと「記録が私の間違いを捕まえた」と書きながら、 記録そのものを誰も検査していない状態にしていた。 チェックイン済みの記録からマシンのパスを拒否するゲートは、いまや 同じ見出しを 2 つ持つ文書も拒否する — 節を置換して古い copy を消し忘れた編集の署名だ。

全 tracked 文書で誤検出ゼロを確認し、1 つ足して毒見した。