Omoikane開発日記：GCを12%軽くし、調査に使うnayutaも育てた日

今日もOmoikaneの開発状況をcc-sakuraで確認していた。新しい機能が一つ増えて終わり、という日ではなかった。GCの調査が少し進み、テストの足場にあった問題を直し、その調査に使う静的解析ツールも改良した。

一番分かりやすい成果は、あるGC改善候補について、Linux上の80世代iframe保持テストが平均51.94秒から45.48秒になったことだ。同じ条件で修正前後を5組比較し、平均で12.44%短くなった。ただし、これでブラウザ全体が12%速くなったわけでも、MacのCIで続いている失敗が直ったわけでもない。その確認はまだ先に残っている。

もう一つ面白かったのは、「このテスト、そもそも計算量が重くなっていないか」と聞いたところから、nayutaの改善と配布までつながったことだった。調査する対象だけでなく、調査に使う道具も同じ日に育っている。

この記事は2026年11月4日22時22分ごろまでに確認した記録を基にしている。執筆中にも検証は動いているので、ここから先の結果は混ぜない。参加環境のハンドルネームは伏せ、実装担当、検証担当、調整担当、実機担当という役割で書く。cc-sakuraでの開発方法そのものは昨日の記事にまとめたので、今日はその仕組みの中で何が起きていたかを残したい。

動いている仕事と、終わった仕事は違う

朝から晩までずっと同じ画面を見張っているわけではない。私は途中でroomを確認して、各自が何をしているのか、こちらの判断を待って止まっていないかを聞いている。AI同士で相談して進められる部分は、そのまま進めてもらう。

今日の流れを追うと、実装担当が修正案を作り、別環境でテストを回し、独立した担当が結果を読み直すという往復が多かった。修正前に落ちたケースが、修正後には通る。同じソースを使ったか、同じテストを実行したか、ログの集計に漏れがないか。そうした確認がroomに積み上がっていく。

これは安心材料になる一方、単に「テスト成功」と言われただけでは何が終わったのか分からなくなる。対象一件が通ったのか、unit全体が通ったのか、integrationも終わったのか。通常のfeatureなのか、JITの検証用featureを有効にしているのか。条件が違えば、同じPASSという単語でも意味は違う。

そこで、今日の状況は三つに分けて見ることにした。変更そのものの妥当性、ローカル検証の到達点、CIを通してマージできる状態か。この三つは連動するが、同じものではない。良さそうな修正ができても、CIがディスク不足で止まれば最後の確認は残る。

22時22分時点の未マージPRは23件あった。そのうち一件は保存用で、もともとマージ対象ではない。残りもすべてが同じ理由で止まっているわけではないが、MacのGate5とCIの容量問題が広く影響している。新しいPRが作られているので作業は進んでいる。それでも、mainに取り込まれた変更だけを見ると、進み方は遅く見える。

80回のループなのに、なぜこんなに重いのか

長く追っているのが、80世代のiframeを保持するテストの失敗だ。このテストは、iframeの文書を更新しながら過去の文書への参照を残し、古い世代も正しく使えることを確かめる。参照を外した後には、不要になった文書が回収されることも確認する。

大まかな形だけ書くと、次のようになる。

80回繰り返す:
    iframeの文書を更新する
    更新した文書への参照を配列に残す
GCを実行する
保持した80世代が読めることを確認する
参照を外す
GCを実行する
古い文書やノードが回収されたことを確認する

テストの表面には、何重ものループが並んでいるわけではない。それぞれの更新は別のスクリプト実行になっている。それでも、一回の更新の中で、それまでに蓄積した文書や参照を全部見るなら、全体の仕事量は単純な80回では済まない。

世代を一つ増やすたびに既存の世代を走査すると、仕事量は1、2、3と増える。合計すれば二乗に近づく。さらに別の走査が内側にあれば、見た目以上に重くなる。Rust側のループだけを見てO(N)と言っても、呼び出し先の処理を定数として扱ってよいかは別に調べる必要がある。

そこで「テスト自体がO(n^m)みたいな実装になっていないか」と聞いた。テストが悪いと決めつけたいわけではない。製品の不具合を見つけるためのテストが、別の無駄な処理によってタイムアウトしているなら、そこも調査対象にしたかった。

ここで重要なのは、80世代を保持すること自体には意味があることだ。参照が生きている古い文書を、都合のよい個数で捨ててはいけない。回数を減らして通すだけでは、検証したかった性質を弱める可能性がある。負荷を減らすなら、何を保証したいテストなのかを保ったまま、無駄な処理を取り除きたい。

今の計測は80世代に固定した修正前後比較なので、計算量の次数まで確定したわけではない。10、20、40、80世代と変えて時間や走査回数を見れば、増え方はもっと分かる。ただ、まずは現在落ちている条件で、具体的な修正が効くかを確かめる段階にいる。

GC改善は、Linuxで5組とも同じ方向に動いた

今回の候補は、minor GCで扱う参照の処理について、重複した投入を減らすものだ。古い世代を無条件に無視するような変更ではない。保持する必要がある参照は維持したまま、同じ仕事を重ねて行う部分を減らす。

候補は固定コミット0344ada3として保存した。基準となるmainとの差分はGC関連の6ファイルで、例外保持の別修正は含めていない。複数の改善を一緒に載せると、どの変更が時間差を作ったのか分からなくなるためだ。

比較はAを修正前、Bを修正後として、AB、BA、AB、BA、ABの順に行った。毎回ビルドし直すとコンパイル時間やキャッシュ状態が測定に入り込むので、AとBのテストバイナリを保存し、それを直接実行している。通常feature、対象テスト一件、テストスレッド一つという条件をそろえた。

表は実行順にかかわらずAとBの列をそろえている。10回の実行はすべて成功した。平均はAが51.938秒、Bが45.476秒で、差は6.462秒。平均に対して12.44%の短縮になる。担当の報告だけでなく、別の担当も元ログから集計し直して一致を確認した。

この結果はかなり分かりやすい。5組すべてでBが短く、各条件のばらつきより差が大きい。ただし、このLinux環境、この単一テスト、この設定での観測だ。ブラウザ全体の応答速度や、別のCPUでの改善率を表しているわけではない。

もう一つ紛らわしいのが、テスト全体の約52秒と、問題になっているJavaScript実行の5秒制限の関係だ。テストは複数のスクリプト実行やGCなどを含む。その合計時間が短くなっても、ある一回の実行が制限を超えなくなるとは限らない。今回は内部の5秒に対する余裕までは測れていない。

だから「12%速くなったので解決」とはしなかった。次はMacで同じ候補を比較する。今日の時点で実機担当を再開し、共有ホストで重い処理が重ならないことを確認して、AとBのビルド準備に入った。Linuxで使ったバイナリを持っていくのではなく、Mac上でそれぞれビルドして比較する。

最初の一組はAとBを両方実行する。Aで問題が再現しなければ、その一組で止めて「実機では元の失敗を再現できなかった」と記録する。元のRuntimeLimitが再現した場合は予定した5組を走らせる。ビルド失敗やSIGKILLを、元のテスト失敗と同じ扱いにしないことも事前に決めた。

二行の修正でも、確かめる範囲は広い

GCの性能調査とは別に、例外の寿命に関する修正も進んだ。PR #1718は、iframeのスクリプト評価が例外を返した後、currentScriptを解除する間もその例外を保持する変更だ。

後始末のためにJavaScriptを実行すると、その中でGCが起きることがある。Rustのローカル変数に例外が残っていても、その値がGC側から到達可能として認識されているとは限らない。これから呼び出し元へ返すつもりの例外が、返す前に回収されてしまう。

修正の中心は、例外を一時的なRootedで保持する短いコードだった。

let _error_root = result.as_ref().err().cloned().map(Rooted::new);

大事なのは行数ではなく、この変数が生きている区間だ。currentScriptの解除、realmの復元、返却値の構築まで保持し、関数を抜けた後には一時ルートを解放する。ずっと保持すれば回収されない問題に変わってしまうので、守るだけでなく手放すことも確かめる必要がある。

回帰テストでは、cleanupの最中に実際にGCを起こすようにした。通常featureの同じ条件で、修正前は二件とも失敗し、修正後は二件とも成功した。opaqueなthrowとnative Errorのcauseを扱い、例外の同一性や内容、最後に回収できることを見る。

ここでも、確認できた範囲を広げすぎないようにしている。もともとの調査には例外メッセージが数値に見えるケースもあったが、その現象全体の因果が、この二行だけで証明できたわけではない。入力移行の差分を含むツリーでは修正前失敗、修正後成功の観測があり、別の診断用ツリーでは両方成功していた。

それでも、cleanup中に返却予定の例外が回収される問題は、専用のテストで修正前後を確認できた。これは独立した修正根拠になる。関連する現象を全部一つの説明に押し込めず、再現できた不具合から閉じていく方が、後で読み返しやすい。

ローカルの通常設定では6,311件成功、0件失敗、24件ignored。CIのJIT関連設定でも、unitの4分割を合計して4,950件成功した。選択したテスト名と実際に成功した名前を照合し、重複と欠落も確認している。ただし、integration側は別の問題で止まった。このPRも、まだ全体成功ではない。

テストを支えるサーバーが、先に帰ってしまう

今日の別の修正は、製品のJavaScript処理ではなくテスト用HTTPサーバーだった。PR #1725では、WorkerCspFixtureの寿命とI/Oの期限を見直している。類似する所有者側fixtureはPR #1717で分けて扱っている。

問題の一つは、fixtureが作られてから累積10秒で終了することだった。テスト本体がまだそのサーバーを必要としていても、時間が来たらサーバーだけが先に終了する。環境が速ければ通り、別の負荷で少し遅くなれば接続できなくなる。テスト対象の不具合に見えて、足場の寿命が足りていない。

旧fixtureを使った小さな再現では、10.1秒後の要求がConnectionRefusedになった。修正では所有者のfinishやDropによる停止に寿命を結び付けた。作成時から何秒たったかより、まだ使われているかどうかを基準にする。

もう一つはread timeoutの意味だった。読み込み一回の待ち時間に5秒を設定しても、body全体を5秒で読み終える保証にはならない。少しずつデータが届けば、一回ごとの待ちは短いまま、全体では長くかかる。旧実装では10バイトを0.6秒ごとに送ると、約6.035秒後に受理された。

そこでbody全体の絶対期限を設け、responseの書き込みにも期限を持たせた。停止通知を確認する短いpollも入れる。短い応答なら普通はすぐ書けるが、相手が読まない状況では別だ。その経路を確かめるため、回帰テストでは実際にbackpressureがかかる条件を作った。

レビューではContent-Lengthの扱いにも問題が見つかった。パースに失敗した値や整数の範囲を超えた値が、0へ変換される経路があった。これでは「大きすぎるbodyを拒否する」という検証を通らず、空のbodyとして扱えてしまう。不正値、overflow、重複を入口で拒否し、確保する直前に64KiBの上限を確認する形へ直した。

さらに、停止テストのready通知が早すぎるという指摘もあった。readを始める前にreadyを送ると、I/O待機中に停止したつもりでも、実際にはread前に停止してPASSすることがある。テストコードが何を確かめたかまでレビューしないと、回帰テストを増やしただけでは安心できない。

PASSの数を足すだけでは、全体成功にならない

このfixture修正では、関連テスト24件が成功し、integrationとdocを合わせた1,388件も成功した。通常buildも成功した。一方で、既定の並列度で走らせたunitはsummaryを出す前にSIGKILLで中断した。

実行中にはOOMのカウンタ増加が観測されている。unitプロセスの観測RSS最大は約6.24GB、cgroup全体のmemory.current最大は約7.17GBだった。ただし、これらは別の指標だし、1秒ごとの標本でもある。cgroup全体の値を、そのまま対象プロセスが使ったメモリとは言えない。

その後、保存した同じunitバイナリを一スレッドで動かすと、4,928件成功、0件失敗、24件ignoredで終わった。これは有用な補助結果だ。少なくとも、単一スレッドのその実行では最後まで進めた。

ただ、開始時のメモリや実行時刻も違うので、「並列度だけが原因だった」とまでは言っていない。まして、直列で通ったから並列の失敗を消してよいわけでもない。#1714で未解決として追い、PRには両方の結果を残している。

CIにも似た注意が必要だった。#1718のGate4 integrationはリンク中にSIGBUSが出て、その後のbuildにはNo space left on deviceが出た。後段の容量不足は確認できるが、先行するSIGBUSまで同じ原因だったと断定する材料は足りない。テスト結果のsummaryもなく、この区画の検証は未完了になる。

ローカルのintegrationが成功していても、CIではJIT関連featureやignoredを含める条件が違う。だからローカル結果は補足にはなるが、そのCI区画が通ったことの代わりにはならない。この区別は少し面倒だが、後から「全部通っていたはずなのに」となるのを避けるために必要だと思う。

標準runnerで続けるなら、成果物の置き方を考える

CI容量の問題は今回だけではない。#1691などで追っている。今後も標準runnerで進める方針なので、容量不足のたびに大きいマシンへ逃がすことは前提にできない。

そのため、内部的にビルドを分け、必要な成果物だけを次の工程へ渡し、不要な途中生成物を消す案も検討している。リポジトリ自体を分割したいわけではない。同じリポジトリでも、工程の境界や生成物の所有者を整理できれば、あるrunnerに全部を抱えさせずに済む可能性がある。

ただし、分割すれば必ず得になるわけでもない。最終段階で再ビルドが必要なら時間を取り戻せないし、artifactとして大量に運べば転送と保存が増える。見るべきものは一つのディレクトリの最終サイズだけでなく、各工程の最大使用量、引き継ぐ量、再生成の有無だ。

今日、この案が完成したわけではない。GCとテスト失敗の切り分けが先に進んでいて、容量の設計は引き続き残っている。新しく起きた失敗の原ログを既存Issueへ足し、同じ問題を別々の場所で何度も調べないようにしている段階だ。

私としては、CIが落ちるたびにもう一回押して運に任せる状況を減らしたい。実行を増やす前に、何が未確認で、その一回で何を知りたいのかをそろえておく。その方が、待ち時間の長い開発では効いてくる。

nayutaが、ループの外まで見に行けるようになった

計算量の話から、nayutaを使えないかという話になった。このツールは先日の記事で紹介した、Rustの計算量候補を探す静的解析CLIだ。最初は主にループの構造を見ていた。

今日のPR #28では、走査対象内の同期関数への多段呼び出しや、イテレーターを消費するときの処理を合成できるようになった。線形な処理をする関数をループの中で呼べば、二乗の候補として報告する。明示的なuseの別名や、型注釈のある変数の固有メソッドなどにも対応している。

mapやfilterが並んでいるだけで、その数だけNを掛けるわけではない。一回の走査として扱い、collectやcountなどで消費する段階を見て、クロージャ内の処理を加える。再帰と相互再帰はリスク候補として伝播するが、入力がどう減るかの漸化式を解くわけではないので、条件付きの見積もりになる。

これなら、前より調査の入口を広くできる。実際にOmoikaneへ適用したところ、イテレーターによる走査を新しく拾えた。ただ、roomで以前から気にしていた文書IDからrealmを探す処理は、まだ出てこなかった。

コードを見ると、その箇所はiter().find_map(…)だった。消費メソッドの一覧にはfindがあるがfind_mapがなかった。そこでnayutaのIssue #29を起票した。最小のRustコードと、Omoikaneでの実際の用途、期待する診断を付けた。

修正はPR #30に入り、v0.4.0としてまとまった。単純なfind_mapだけでなく、外側のループ、クロージャ内のループや関数呼び出し、map/filterとの連結、同名の一般メソッドを誤認しないこともテストしている。手元で30件すべて成功し、Omoikaneのwindow_event.rsでも、前回拾えなかった三箇所をO(N)候補として検出できた。

この往復はよかった。ツールを作ってから用途を探しただけでなく、実際の調査で足りないところが見え、それを小さい再現にしてツールへ返せた。検出対象が増えたことを、元の利用箇所で確かめるところまでつながっている。

O(N⁴)という表示を、そのまま結論にしない

v0.4.0はcc-sakuraで作業者へ案内した。導入方法と一緒に、不具合や検出漏れを見つけた場合はnayuta側へIssueを立てることも伝えた。対象プロジェクトの不具合と、解析ツールの不具合は起票先を分ける。

最初に導入したLinux側の担当は、固定したGC改善候補に適用した。変更ファイルだけを見ると呼び出し先が走査範囲から外れることがあるので、修正前後で同じGCソースディレクトリ全体を解析し、差分を読む方法にした。

Aは26ファイルで88候補、Bは27ファイルで91候補だった。増えた三件は追加テストとテスト用の観測処理に由来するという整理になった。この改善は重複処理を減らすもので、計算量の次数が下がらなくても実時間が短くなることはある。警告の数だけで性能改善を採点することはできない。

一方、remember_ephemeron_allocationの呼び出しにはO(N⁴)という候補が出た。これをそのまま「四乗のバグが見つかった」とは扱っていない。実装にはseen付きのworklistがあり、同じポインターを繰り返し処理しない仕組みがある。解析器がその重複排除をモデル化できず、呼び出しのコストを過大に合成している可能性がある。

それでも、見て終わりではなかった。seenは呼び出しごとに作り直されるので、一回の探索が線形でも、昇格する参照ごとに探索を始めれば、全体では「昇格数×到達するグラフの大きさ」の仕事になるかもしれない。これはソースを読んだ時点の見立てで、実時間への影響はまだ測っていない。

つまり、表示された次数は確定値ではないが、コードを読む場所を絞る役には立っている。どの呼び出しをどの入れ子として合成したかを追い、ツールの見落としなら最小再現を作る。製品側に本当の重複作業があるなら、計測して別の改善へつなげる。その二段階で使いたい。

次に欲しい道具も、今日の失敗から見えてきた

roomの議論を読み返して、nayuta以外にも静的解析で助けられそうな箇所を整理した。実際に手間がかかったレビューを、次回も全部手作業で繰り返す必要はないはずだ。

候補は五つあり、Omoikaneにdebug_toolラベル付きで記録した。タイムアウト・停止・join経路、GC発生点をまたぐroot保持、内部APIの公開境界、パース失敗と上限検証、並行テストの同期と状態到達だ。いずれも開発候補で、実装済みではない。

例えば、ループのたびに期限を作り直していないか。Dropがjoinする先に、停止を見ないI/Oがないか。GC対象の値を持ったまま、GCを起こし得る関数を呼び、その後で値を使っていないか。こうした形を候補として挙げてくれるだけでも、人間やAIのレビューは始めやすくなる。

もちろん、名前だけで判定してはいけない。read timeoutを更新することが正しい設計もあるし、既定値への変換が必要な入力もある。別のrootが値を保護している場合もある。最初から万能な安全性の証明を目指すより、何を仮定して警告したかが分かる道具の方が使いやすそうだ。

今日の開発では、二行の修正を確かめるために多くの検証が必要になり、逆に、小さな解析ルールの追加が実プロジェクトの調査を前に進めた。コードを書く速さだけでは、どちらも説明できない。何を確認したいかを定め、そのための再現や道具を整える時間がかなり大きい。

執筆時点ではMacの比較結果はまだ出ていない。入力APIの非公開化はPR #1724まで進み、fixture修正のCIも動き始めている。次にroomを開いたときに知りたいのは、Macで元の失敗が再現したか、候補で変わったか、そしてCIの容量問題をどう抜けるかだ。

今日はmainへ入った変更の数だけでは測りにくい日だった。それでも、GCの比較には数値が出て、テストの足場の問題は具体的な修正になり、nayutaは実際の調査で使える範囲が広がった。このくらいの粒度で記録しておけば、明日また同じ問題を最初から説明し直さずに済む。