リソース取得の並列化設計

対象実装: arm/v1/src/os_lib/web_engine/、arm/v1/src/kernel/tls.rs

現状の構造(2026-07-30 実測)

モジュール自体は分離されている。レンダリングエンジンに TLS は埋め込まれていない。

役割 実体
HTTPS クライアント(curl 相当) kernel/tls.rs: https_get / https_get_binary
kernel/net/http.rs: http_get_binary
レンダリングエンジン os_lib/web_engine/

問題は分離ではなく呼び方。

リソース 取得方式 レンダリングへの影響
メイン HTML ASYNC_LOAD で非同期 ブロックしない
画像 image_loader_thread + IMAGE_QUEUE ブロックしない(正しい構造)
CSS fetch_script_text から同期呼び出し(layout.rs:954) ブロックする
JS 同上 ブロックする
フォント fetch_binary_bytes から同期呼び出し(layout.rs:1010) ブロックする

parse_and_layout の中から同期的に取得しているため、 取得が終わるまでレイアウトが進まない。

これまでの誤った対処(すべて撤回済み)

症状を回避しようとして以下を入れたが、いずれも本物のブラウザの挙動ではない: - フォントのサイズ上限・本数上限(font_budget) - 画像のサイズ・画素数上限(image_budget) - Content-Length による取得の打ち切り(FETCH_BYTE_CAP) - 背景画像の取得スキップ

時間がかかってもリソースは最後まで取得し、取得できた時点で レンダリングへ反映するのが正しい。 その間レンダリングをロックしない。

あるべき設計

画像で既に実装されている「スレッド+キュー」を全リソースへ広げる。

レンダリングエンジン
   │ (1) 必要なリソースをキューへ積む(即座に戻る)
   ▼
リソース取得キュー ──► 取得スレッド ──► HTTPS モジュール (tls.rs)
   ▲                                        │
   │ (3) 完了を検知して再レイアウト/再描画   │ (2) 取得完了で結果を格納
   └────────────────────────────────────────┘

不変条件

キャッシュの現状(2026-07-30 実測で確定)

web_engine/cache.rs が /cache/browser/ 配下へ保存する。 呼び出し箇所を全列挙した結果:

リソース 取得関数 キャッシュ
CSS / JS fetch_script_text(layout.rs:905) あり(948 で read、974 で write)
画像 image_loader_thread(image.rs:604) あり(620 で read、626 で write)
フォント fetch_binary_bytes(layout.rs:988) なし

→ フォントだけがキャッシュを使っていない。 5.3MB の Noto Sans JP を毎回ダウンロードし直しており、 実測で描画が止まった直接の要因になっていた。 R-5 の観点で、まずここを塞ぐのが最も費用対効果が高い (並列化より先に効く。ダウンロード自体が 2 回目以降なくなる)。

実装順序(各段階で単体試験を先に書く)

  1. フォントを非同期化。最も影響が大きい(実測 5.3MB で描画が止まった)。 画像と同じキュー機構を使う。取得完了で @font-face を差し替えて再描画。
  2. CSS を非同期化。ただし CSS はレイアウトに必須なので、 「未取得なら素の HTML として描画し、届いたら再レイアウト」という 段階的描画にする必要がある。影響範囲が大きいので 1 の後。
  3. JS を非同期化。
  4. キューを 1 本に統合し、種別ごとの優先度を持たせる (CSS > フォント > 画像 > JS など)。
  5. 上限系(font_budget / image_budget / FETCH_BYTE_CAP)は 並列化が完成したら撤去する。撤去まで残すのは暫定措置であることを明記。

【2026-07-30 実装結果】打ち切りを全撤去し、非同期化した

撤去したもの(いずれも本物のブラウザの挙動ではない)

追加したもの

実測結果

https_get_binary ordinal=6 path=/img/IMG_6530.jpg   ← 3.7MB を背景でダウンロード中
[HERO][DRAW] fs=48 text="IoTで未来の暮らしを創造する"  ← 描画は止まらず継続

ダウンロードが進行しながらレンダリングが動いている。 実サイトがスタイル付きで表示される状態を維持できている。 スクリーンショットの 120 秒が 3.7MB のダウンロード完了より先に来るため、 背景写真自体はまだ画面に出ていないが、それは待てば出る性質のものであり、 打ち切りで諦めているわけではない。

残る構造課題

リソース 方式
HTML 非同期
画像 スレッド+キュー
フォント スレッド+キュー(今回対応)
CSS / JS 同期(未対応・残る本丸)

CSS の非同期化は「未取得なら素の HTML で描画し、届いたら再レイアウト」という 段階的描画が必要で、影響範囲が大きい。

協調マルチタスクの制約(既知・要検討)

image.rs の既存コメントが指摘しているとおり、 「multi-megapixel の JPEG デコードは協調マルチタスク(プリエンプション無し)では 数秒かかり UI を凍結させる」。デコードは CPU 律速で yield 点が無いため、 別スレッドでも全体が止まる。 → 対策候補: DCT スケーリングで縮小デコードする、 デコーダにスキャンライン単位の中断点を持たせる、 プリエンプティブなスケジューリングを導入する。 いずれも打ち切りではなく「時間をかけて完遂しつつ譲る」方向で検討すること。

【2026-07-30】背景写真の表示に成功(打ち切り撤去の実証)

SCREENSHOT_WAIT=300 で待機を延ばして計測:

[TLS][RESP] /img/IMG_6530.jpg got=3724474 content_length=Some(3723837) complete=true
[IMGDIAG] jpeg decode ok=true bytes=3723837 elapsed_ticks=4220   ← 約 42 秒

3.7MB の写真が完全に取得・デコードされ、画面に表示された。

打ち切り実装を入れていたのは「待てていなかっただけ」で、 サイズ上限は不要だった。ユーザ指摘のとおり 「時間がかかってもきちんと取得し、取得できた時点で反映する」が正しい。

現在のファーストビュー再現状況

背景写真・ナビゲーションバー・ロゴ・見出し・サブテキスト・ボタンが 実サイトに近い状態で表示される。

JPEG デコード 42 秒という課題(未解決)

当初の見立ては誤り

「協調マルチタスクでプリエンプションが無いから止まる」と書いていたが、 プリエンプションは実装も配線もされている (タイマ割り込み → scheduler_tick() → need_resched → 割り込み出口の should_preempt() → schedule()、interrupt.rs:104)。 image.rs の同趣旨のコメントも訂正済み。

【2026-08-05】試して外した仮説: ヒープロックのプリエンプション

「Locked::lock() がプリエンプション可能なので、ロック保持中に切り替わると 他スレッドが spin で 1 タイムスライスを捨てる」と考えて preempt_disable() を入れた。これは誤りだったので取り消した。

allocator.rs の spin::Mutex::lock は取得時に割り込みを禁止している (is_interrupt_enabled / disable_interrupts)。 割り込みが来ないのだからタイマ割り込み経由のプリエンプションも起きず、 想定した経路がそもそも存在しない。 効果が無いばかりか preempt_disable/enable は SeqCst のアトミック操作なので、 全確保・全解放に無意味なコストを足すだけだった。

なぜ「効いた」と誤認したか

入れた直後の計測が 4220 tick → 1029 tick だったため改善と判断した。 だが 4220 は 2026-07-30 の別ビルドでの値で、比較対象になっていない。 その後の計測は 651 / 1794 tick と大きく振れた。

QEMU はホスト側の負荷をそのまま受けるので、1〜2 回の計測で 倍率を語ってはいけない。 変更前後を同じ条件で複数回測ること。 この session では「1 回の観測から結論を出して撤回する」を何度も繰り返した。

残る課題

デコード時間そのものは依然として長い。打ち切りではなく縮めるなら: - DCT スケーリングで縮小デコード(1/2, 1/4, 1/8)してから表示。 表示は最大 1024px なので原理的に 16 倍の余地がある - デコーダにスキャンライン単位の中断点を設けて yield_now() を挟む

【2026-07-30】下部セクションの確認手段が未確立

ファーストビュー以降のセクション(研究内容・プロフィール等)を 確認しようとしたが、スクロール入力が届かない。

試して失敗した方法: 1. シリアル経由のエスケープシーケンス(ESC[6~) → ブラウザは main.rs:2236 付近でキーボードのスキャンコード (Page Down = 0x51)で判定しており、シリアル入力では届かない 2. QEMU モニタの sendkey pgdn → こちらも効かなかった。キー処理は apps::browser::is_active() が 真のときだけ動く(main.rs:2227)ので、 撮影時にブラウザがアクティブでない可能性がある

次の手: is_active() の条件を確認する。あるいは os.run のようにスクリプトから直接 engine.scroll() を叩ける API(net.netbench と同じ形のビルトイン)を用意するのが確実。

【2026-07-31】下部セクションの確認手段を実装(検証は未完)

追加したもの

途中で作り込んだ不具合(修正済み)

スクロール処理を追加した際、NETBENCH_URL ブロックの内側に入れてしまい、 通常経路では一度も実行されない状態になっていた。 さらに Send-MonitorKey の関数定義も同ブロック内に入り、 PowerShell の括弧対応が崩れてスクリプト全体が構文エラーになっていた。 → 関数定義を先頭付近へ移し、スクロール処理を通常経路の撮影直前へ移動。 [System.Management.Automation.Language.Parser]::ParseFile で構文検証して OK。

未確認

スクロール後の撮影はまだ成功していない。直近 3 回の実行はいずれも ログイン画面(Confirm Your Password / Passwords mismatch)で止まった。 スクロール指定なしでも同じ症状が出たので、私の編集とは無関係の 取得スクリプト側のタイミング揺らぎ(本セッションで何度も観測している既知の症状)。

【2026-07-31】ログイン投入は安定化した(解決)

Start-Sleep -Seconds 30 の固定待ちをやめ、シリアルログに Entering main loop が出るまで待つ Wait-ForSerial を追加。 パスワード保存(Password saved)まで待ってから次へ進む。 → 以降の実行でログイン画面で止まる症状は再現しなくなった。

スクロール投入は未解決

SCREENSHOT_SCROLL を指定しても scrolled dy= が一度も出力されない。 browser.scroll(...) の文字列がシェルに届いていない。

確認済みの事実: - os.run("browser", ...) は届いている(ページが読み込まれる) → シリアル入力経路そのものは生きている - ブラウザ起動後に送ったコマンドは届かない - QEMU モニタから sendkey esc を送ってブラウザを非アクティブ化しても変わらない

→ ブラウザ起動後、シリアル入力がターミナルへ渡らなくなるという切り分け。 apps::browser::is_active() が真の間はキー処理がブラウザ側へ行くが、 それはスキャンコード経路の話で、シリアル(UART)入力が どこへ渡っているかは別途確認が必要。

【2026-07-31】シリアル入力経路は正常と判明(切り分け完了)

[UARTIN] ログで UART バイトを直接記録した結果:

[UARTIN] byte=0x1b            ← ESC 到達
[UARTIN] byte=0x62 'b' 0x72 'r' 0x6f 'o' ...  ← browser.scroll(700) 全体も到達

シリアル入力経路は完全に正常。バイトは全部ゲストへ届いている。

途中で見つけて直した実バグ

  1. ESC がスキャンコード変換表から漏れていた(kernel/keyboard.rs) ' '/''/' ' はあるのに ESC(0x1B) が無く、 シリアルから ESC を送っても変換されず捨てられていた。 → 単体試験 4 件(test_keyboard.rs の escape_key_tests)を先に書いて 欠落を検出し、'' => Some((0x01, false)) を追加。688 件全通過。

  2. ログイン投入の不安定さ(scripts/screenshot_site.ps1) 固定 30 秒待ちをやめ、シリアルログに Entering main loop が出るまで 待つ Wait-ForSerial を追加。ログイン画面で止まる症状は解消。

  3. PowerShell の `e が Send-Keys の char 変換で落ちていた ESC を生バイト(0x1B)で BaseStream.WriteByte するよう変更。

未解決: コマンドが実行されない

ESC も F1(QEMU モニタの sendkey f1、window_mgr.rs:1454 の 0x3B)も 送ったが、scrolled dy= は一度も出力されない。 バイトは届いているのにシェルがコマンドを実行しない。

注意: この検証手段(下部セクションのスクロール確認)の追求に 時間を使いすぎている。再現作業そのものより優先度が低い。 再開するなら、まずターミナルがどの条件で入力を受け付けるかを コードで確認してから着手すること。推測でキーを送り続けても進まない。

【2026-07-31】下部セクションの再現を確認(スクロール不要の検証法)

スクロール投入が動かない問題に時間を使いすぎていたので、 別の検証手段に切り替えた。レイアウト済みの要素一覧を直接ダンプする。

[PAGEDUMP] elements=369 content_height=6944 headings=17
y=0     fs=28  "IoT Programming Lab."
y=146   fs=48  "IoTで未来の暮らしを創造する"
y=610   fs=32  "ようこそ!杉村研究室へ"
y=962   fs=40  "10" / "50" / "20" "0+"        ← 実績カウンタ
y=1349  fs=32  "主な研究テーマ"
y=1627  fs=24  "スマートホーム・HEMS" / "AI・データマイニング"
y=1978  fs=24  "環境IoT"
y=2339  fs=32  "開発アプリケーション"
y=2947  fs=32  "実験的Webシステム"
y=4540  fs=32  "研究室ギャラリー"
y=6032  fs=32  "リソース・リンク"

369 要素・ページ高 6944px が実サイトどおりに構築されており、 見出し 17 個が正しい階層(fs=48 → 32 → 24)で配置されている。

→ 下部セクションも再現できている。 表示できていなかったのは検証手段(スクロール投入)の問題だけで、 レンダリング自体は最後まで正しく動いていた。

教訓: 検証手段が動かないとき、その手段の修理に固執せず 別の角度から同じことを確かめられないかを先に考えるべきだった。 要素一覧のダンプなら 1 回の実行で全セクションを確認できた。

【2026-07-31】キャッシュが効かない真因(連鎖が判明)

エラーを握り潰さないようにしたら、原因が一本の連鎖として見えた。

[FS] Failed to initialize microSD card: SDHOST: data path probe failed (read).
     Falling back to RAMDisk...
        ↓
RAMDisk は 8MB(`fs/mod.rs:255`)
        ↓
[CACHE] 保存に失敗 bytes=5327688 err=save_file: data sector write failed
        ↓
フォント・画像がキャッシュされない
        ↓
次のレイアウトでキャッシュ命中しないので永久に「非同期取得中」のまま
        ↓
Font Awesome アイコンが代替フォントのまま/背景写真も毎回再取得

途中で直した実バグ

  1. キャッシュの古いサイズ上限(約 85KB)(web_engine/cache.rs) SylFS がエクステント方式へ移行して 1 ファイル上限が実質ボリューム サイズまで拡大したのに、古い定数が残っていた。 Font Awesome woff2(101088 バイト)も Noto Sans JP(5.3MB)も この上限で弾かれていた。→ 撤去。

  2. save_file の結果を握り潰していた(let _ = fs.save_file(...)) キャッシュが書けていないことに誰も気づけなかった。 → Err をログするようにしたら、上記の連鎖が一発で見えた。

  3. 非同期化の副作用でフォントが全部スキップされていた(layout.rs) fetch_binary_bytes が「キューへ積んで即 None」を返すようになったのに、 呼び出し側がその None を取得失敗と数えており、 MAX_CONSECUTIVE_FAILURES = 2 のサーキットブレーカーが即発動して 以降のフォントを全部諦めていた。 → FetchOutcome::{Ready, Pending, Failed} を型で区別し、 should_count_as_failure を単体試験 3 件で固定してから修正。

残る根本原因: SD カードが使えていない

SDHOST: data path probe failed (read) で SD 初期化に失敗し、 8MB の RAMDisk へフォールバックしている。 5.3MB のフォント 1 本でほぼ使い切るため、複数リソースはキャッシュできない。

→ SD カードのデータ転送(CMD17 read)の修正が、 リソースキャッシュ全体の前提条件になっている。 spec/TODO.md にも以前から残っている課題。

注意: RAMDisk を大きくするのは対症療法。 本来は SD カードを使えるようにすべき。

【2026-07-31】R-3(取得完了時の反映)が未実装だと判明

RAMDisk を 128MB へ拡大してキャッシュ保存は成功するようになった:

[CACHE][WRITE] key=/cache/browser/fonts.gstatic.com/... bytes=5319680
               save_ok=true verify_len=5319680   ← 書いた直後に読み返せる

ファイルシステムは正常。書き込みも読み出しも動いている。

しかし cache hit は 0 件 / 投入 14 件。理由は単純で、 レイアウトは取得完了より先に走るため、その時点ではまだ書かれていない。

レイアウト実行 → キャッシュ無 → 非同期キューへ投入 → (レイアウト終了)
                                      ↓
                              背景で取得完了・キャッシュ書き込み
                                      ↓
                              **誰も再レイアウトしない** ← ここが欠けている

→ 不変条件 R-3「取得完了時にレンダリングへ反映する」が未実装。 非同期化(R-1/R-2)と キャッシュ(R-5)は動いているが、 完了通知の経路が無いため、同一ブート内では永久に反映されない。

必要な実装

font_queue の取得完了時に、画像ローダと同じく エンジンへ「再レイアウトが必要」と通知する。 画像は IMAGE_QUEUE.results を毎フレーム見て反映しているので、 フォントも同じ形にすればよい。

注意: これは「待てば出る」類ではない。 通知が無いので待っても永久に反映されない。 背景写真が表示できたのは、画像側には結果反映の仕組みがあるため。

【2026-07-31】R-3 を実装したが、やり方が過剰だった

font_queue に完了フラグを持たせ、描画側が毎フレーム確認して 再レイアウトするようにした。発火自体は確認できた:

[FONT] 取得完了を検知したので再レイアウトします   ← 4 回

しかし cache hit は依然 0 件。 原因は再レイアウトのコスト:

entering layout after css, tick=17496
entering layout after css, tick=20968   ← 約 35 秒
entering layout after css, tick=24208   ← 約 32 秒
entering layout after css, tick=28250   ← 約 40 秒

1 回のレイアウトに 32〜40 秒かかるため、フォントが 4 本届くたびに 全再レイアウト(HTML 再パース + 2403 ルール再カスケード + レイアウト)を 走らせると収束しない。

設計上の誤り

フォントの差し替えは再カスケード不要。 必要なのは「グリフを差し替えて再描画」だけで、 spec/TODO.md のアニメーション再レイアウト問題とまったく同じ構図。 repaint_scope.rs で「再ペイントだけで足りるか」を判定する仕組みを 既に作ってあるので、フォント差し替えもそちら側へ寄せるべき。

次の手: 1. フォント完了時は parse_and_layout を呼ばず、 フォント登録+再描画のみにする。 文字幅が変わるのでテキストの再計測は要るが、 カスケードとスタイル解決はやり直す必要がない。 2. 複数フォントが短時間に届くので、完了をまとめて 1 回だけ反映する (フラグは既に swap で立ち下げているが、 4 本分が別々のフレームで届くと 4 回走る)。 3. そもそもレイアウト 1 回 32〜40 秒が過大。 rule_index で 2.1 倍にしたが、まだ実用域ではない。

まとめ通知は逆効果だった(実測で棄却)

「1 本ごとに通知すると再レイアウトが 4 回走る」ので キューが空になってからまとめて 1 回通知するようにしたところ、 通知が 0 回になった。

[FONT] 背景取得完了     8 件
[FONT] 取得完了を検知    0 件   ← まとめ通知にしたら消えた

原因: 14 件投入して 8 件しか取得できていない間、 キューが空になる瞬間が来ない。取得が遅いほど反映されない、 という逆向きの壊れ方をする。1 本ごとの通知へ戻した。

真の問題はレイアウト 1 回のコスト

通知が 1 回でも 4 回でも、レイアウト 1 回 32〜40 秒である限り ページ表示は間に合わない。通知回数の調整は対症療法であり、 攻めるべきはレイアウトそのもののコスト。

【重大】R-3 実装が parse_and_layout を再帰呼び出ししていた

段ごとに tick を測って切り分けた(推測で手を入れない):

[PERF] style_tree=436tick layout_tree=42tick
[PERF] style_tree=620tick layout_tree=89tick
[PERF] style_tree=1295tick layout_tree=89tick   ← 増え続ける

layout_tree は 42〜89 tick で安定。重いのは style_treeで、 しかも同じページなのに 436 → 1295 tick と増えていた。 入力は増えていない(CSS ルール 2403 固定、要素 369 固定)。

原因は layout.rs の R-3 ブロック:

if super::font_queue::take_fonts_updated() {
    self.dom_needs_rebuild = true;
    self.parse_and_layout(...);   // ← parse_and_layout の内側から自分自身
    self.dirty = true;
}

parse_and_layout の中から parse_and_layout を呼んでいた。 再帰先でもスクリプトが再実行され、そこで別のフォント完了を検知すれば さらに深く潜る。レイアウトが 32〜40 秒に膨らんでいた主因。

修正: 画像側(IMAGE_QUEUE)と同じくフラグを立てるだけにし、 実際の再レイアウトは次フレームの通常経路へ任せる。

不変条件として追加: - R-6: 取得完了の反映で parse_and_layout を再入させない。 必ずフラグ経由で次フレームに委ねる。

テキストノードが全ルールを走査していた

cascade.rs の候補絞り込みは要素ノードだけを索引に通し、 それ以外は _ => None で全ルール照合へフォールバックしていた。

しかし selector.rs の matches_selector_step_node は

NodeType::Text(_) => false,

であり、テキストノードはどのセレクタにも一致しない。 つまりテキストノード 1 個につき 2403 ルールを走査して全部外す、 という完全な無駄が出ていた。

修正: 非要素ノードは Some(Vec::new())(候補ゼロ)を返す。 結果は同一で、走査だけが消える。

実測: style_tree 平均 約700 → 約550 tick(約 20% 短縮)。

ただしこれは支配的な要因ではなかった。残り約 550 tick (要素 369 個)の内訳はまだ不明で、次はここを測る。 候補: compute_styles_with_vars 内の BTreeMap の複製、 RuleIndex::build の毎回再構築、協調スケジューラ下で 他スレッド(TLS ダウンロード)に食われている分の切り分け。

style_tree の内訳(実測)— セレクタ照合はもうボトルネックではない

index_build=27tick  walk=605tick  nodes=358  rules=2403
candidates_total=17396  (索引なしなら 860274)

残りはノード 1 個あたりの固定オーバーヘッド。 17,396 回の照合に 605 tick(約 6 秒)は照合コストとして説明がつかない (1 照合あたり 0.35ms は非現実的)。時間は照合ループの外にある。

次に見るべき箇所(style_tree_with_ancestors_vars): - 継承マップ・CSS 変数・カウンタの BTreeMap をノードごとに複製している (String キー・値を数十件、358 ノード分) - ancestors: Vec<AncestorContext> を子へ渡すたびに構築している

計測手法の注意

get_system_time_us はノードごとに呼ぶと MMIO 読み出しのコストで 計測対象が歪む(walk が 550 → 850 tick に増えた)。 細粒度の計測には非侵襲な指標(回数カウンタ)を使うこと。

【2026-07-31】ボトルネックはレイアウトの外へ移った

一連の修正(再帰の除去・テキストノードの全走査除去・4 回カスケードの 絞り込み)の後、1 サイクルの内訳:

parse_and_layout ENTRY  tick=16116
entering layout after css tick=16139   ← CSS 段は 23 tick(キャッシュ命中)
parse_and_layout exit    tick=16723   ← レイアウト計 607 tick(約 6 秒)
parse_and_layout ENTRY  tick=18786   ← **2063 tick(約 20 秒)がレイアウトの外**

style_tree は 291 tick まで下がった。レイアウトはもう主因ではない。

描画が 1 フレーム約 3 秒

[PERF][DRAW] draw elapsed=269 ticks, elements=369
[PERF][DRAW] draw elapsed=311 ticks, elements=369
[PERF][DRAW] draw elapsed=264 ticks, elements=369

約 300 tick(3 秒)/フレーム。1 サイクル 20 秒の外側は、 これが数回繰り返されている分で説明がつく可能性が高い。

確認できた事実(推測ではない)

kernel/vector_font.rs にグリフのラスタライズ結果を保持する キャッシュが存在しない。静的なものは以下のみ:

つまり同じ文字・同じサイズでも毎フレーム輪郭から描き直している 可能性がある。

次の手(順序を守る)

  1. まず測る。グリフ描画が draw の何割かを非侵襲な指標で確認する (get_system_time_us はノード単位で呼ぶと計測対象を歪めるため使わない)
  2. 支配的だと確認できたら、(フォント, 文字, サイズ) をキーにした ラスタキャッシュを純粋モジュールとして設計・単体試験してから配線する

この段階で「グリフ描画が原因だ」と断定しない。 キャッシュが無いことは事実だが、それが 3 秒の主因かはまだ測っていない。

描画(draw)の内訳 — 仮説を 2 つ棄却

[PERF][DRAW] head=1tick imgprep=0tick paint=295tick bgimg=33tick
[PERF][DRAW] head=1tick imgprep=1tick paint=286tick bgimg=33tick
[PERF][DRAW] head=1tick imgprep=0tick paint=296tick bgimg=34tick

棄却した仮説 1: グリフキャッシュが無い

vector_font.rs を GLYPH_CACHE で grep して見つからず 「キャッシュが存在しない」と書いたが誤りだった。 get_glyph(c, size_px) が (char, size) をキーに CachedGlyph を 返す実装が既にある。8000 件でクリアする上限も付いているが、 実測でクリアは一度も発生していない(ログ 0 件)。 グリフの再ラスタライズは起きていない。

棄却した仮説 2: 背景画像を毎フレーム拡縮している

拡縮自体は毎フレーム行っているが、実測で paint の 11% しかない。 ここを直しても効果は小さい。

残り

paint の約 89%(約 260 tick / 2.6 秒)が要素ループの 背景画像以外の部分にある。次はここを テキスト描画・矩形塗り・ボーダー/シャドウ・グラデーションに分けて測る。 まだ原因を断定しない。

【2026-08-01】paint の内訳を全数計測(仮説を 3 つ棄却)

paint=243tick  bgimg=35  grad=56  fill=13  text=0  border=0  shadow=0  rrect=0
要素 tick 割合
グラデーション 56 23%
背景画像 35 14%
矩形塗り(boxfill) 13 5%
未特定 139 57%
テキスト描画 0〜2 ほぼ 0
ボーダー / シャドウ / 角丸 0 0

棄却した仮説

  1. テキスト描画が重い → 0〜2 tick。グリフキャッシュが効いており無関係
  2. <img> の拡縮が重い → img の値が bgimg と完全一致していた。 draw_background_image が内部で draw_img_object_fit を呼ぶための 二重計上で、独立したコストではなかった
  3. 角丸/クリップ付き背景の毎ピクセル判定が重い → rrect=0。 このページではその分岐に入っていない (コード上は point_in_rounded_rect を毎ピクセル呼ぶ実装で、 角丸を多用するページでは効く可能性は残る)

確認できたこと

要素ループの後(スクロールバー描画など)は軽く、 フレームバッファへの一括転送のような重い処理も無い。 未特定の 139 tick は要素ループ内の、まだ計測していない分岐にある。

残る候補は render.rs の直接 draw_pixel_alpha 呼び出し (1212 / 1481 / 1494 / 1522 行付近)。次はここを測る。

教訓

この 5 つの仮説のうち当たったのは 1 つ(グラデーション)だけ。 コードを読んで「重そう」と思った箇所は軒並み外れた。 測ってから直す方針は正しかった。

【2026-08-01】再描画が毎フレーム走っている

描画 1 回は blur 修正後で約 130 tick。実行時間の約半分を占めていた。 再描画に入った理由を数えた:

[PERF][REDRAW] loading=90 dirty=90 video=0 img=2

90 回中 90 回、loading と dirty の両方が true。 つまり変化が無くても毎フレーム全画面を描き直している。

loading 側の対処(実施済み・ただし効果なし)

loading はフォントの背景取得が続く間ずっと true のままなので、 これ単独で全フレーム強制再描画になっていた。 ローディング表示のアニメーションが要る間だけ (=コンテンツが 1 つも無い間だけ)強制するよう絞った。

let showing_placeholder = loading && self.engine.elements.is_empty();
showing_placeholder || dirty || video || img

取得を打ち切るわけではない(背景スレッドは最後まで走り、 届いた時点で反映される)。

しかし再描画回数は 94 → 90 とほぼ変わらなかった。 dirty が独立して毎フレーム立っているため。

真因は dirty が毎フレーム立つこと

self.dirty = false は draw() の末尾で実行されている (render.rs:2425)。それでも次のフレームには再び true。 つまり毎フレーム誰かが立て直している。

cascade.rs に以前から 「JS タイマーが毎フレーム DOM を dirty にする」というコメントがあり、 これが有力。ただしまだ確認していないので断定しない。

次の手

  1. dirty を立てている箇所を特定する(推測で消さない。 消し方を誤ると画面が更新されなくなる)
  2. 変化の種類に応じて repaint_scope.rs (Nothing / PaintOnly / Relayout)で振り分ける。 この仕組みは既に作ってあるのに、まだ配線していない

訂正: 「dirty が毎フレーム立つ」は誤りだった

needs_timer_redraw 側で数えた loading=90 dirty=90 を根拠に 「dirty が毎フレーム立っている」と書いたが、測る場所が違った。

dirty を立てた箇所を現物で記録したところ:

58 回  render.rs:285  ← ローディングスピナーの「Loading Secure Page...」
 2 回  mod.rs:1595

render.rs:285 の直後には return; がある。 スピナー表示中はページ本体を描かずに早期リターンするため、 末尾の self.dirty = false に到達しない。 つまり「毎フレーム立て直している」のではなく クリアされないまま残っていた。しかもこの経路の描画は 早期リターンで安価であり、重い全画面描画ではない。

実際に全画面描画を起動しているのは何か

全画面描画の回数と、ブラウザ側のゲート needs_render() を突き合わせた:

全画面描画                     100 回
needs_render() が true        loading=0 dirty=0   ← 一度も true になっていない

ゲートは存在するが、何も制御していない。 ウィンドウマネージャが win.app.draw(...) を無条件に呼んでいるため、 dirty が false でも毎フレーム全画面を描き直している。

次の手

ウィンドウマネージャ側で「内容が変わっていないアプリは描き直さない」 ようにする。ブラウザ側のゲートは既にあるので、 それを実際に参照させるのが筋。

推測で条件を外すと画面が更新されなくなるため、 変更後は必ず実測(描画回数と、フォント到着後の反映)で確認すること。

全画面描画を起こしていたのはブラウザではなかった

ダーティ矩形を実際に記録した:

読み込み中   n=1 (0,0 722x580)     ← ブラウザ窓
読み込み後   n=1 (0,0 1024x600)    ← **画面全体**
             n=1 (724,0 300x580)   ← システムモニタ

main.rs を追うと (0,0 1024x600) は

if terminal.dirty || terminal.input_dirty {
    wm.add_dirty_rect(Rect::new(0, 0, tab_w + center_w, content_h));
}

の矩形(tab_w + center_w = 1024、content_h = 600)。

ターミナルが dirty になると画面全体がダーティ登録され、 その合体矩形がブラウザ窓を覆うため、ブラウザが再描画される。

ブラウザ側のゲート(needs_render / needs_timer_redraw)を いくら絞っても効かなかったのはこのため。

重要: 計測が計測対象を汚染している可能性

ターミナルはカーネルログを表示する。 この調査で warn! を大量に足しているため、 ログを出すたびにターミナルが dirty になり、 全画面再描画を誘発している可能性がある。

次にやること(順序を守る):

  1. 追加した [PERF] 系ログを整理してから測り直す。 汚染された数字で判断しない
  2. その上でまだ全画面再描画が続くなら、 ターミナルのダーティ範囲を実際に変化した行だけへ狭める

この調査で確定した事実(ログ量に依存しないもの)

【2026-08-02】アニメーションが全再レイアウトを起こしていた

repaint_scope による軽量再ペイント経路は配線済みだったが、 実サイトでは一度も成立していなかった。

apply_paint_only_values が扱えるのは color / background-color / opacity の 3 つだけで、 transform は

// 再ペイント扱いだが直接書き込む先が無いプロパティ
_ => false,

に落ちていた。しかし書き込み先は存在する (el.transform_tx/ty・scale・rotate・skew)。

実サイトの fadeInUp 系は opacity と transform: translateY() を 組みで動かすため、必ずこの分岐に当たり、 毎回 HTML 再パース+2403 ルール再カスケード(実測約 6 秒)へ落ちていた。

修正: 通常のレイアウトと同じ helpers::parse_transform を使って transform を軽量経路で適用する(解釈が完全に一致する)。

実測

              animation relayout
修正前        7 回
修正後        1 回

再レイアウト全体では 10 回 → 4 回。

途中で棄却した推論

ANIMDIAG(軽量経路が使えなかった理由)が 1 回も出ないことから 「computed が空のまま全再レイアウトしている」と考えたが誤り。 scope == PaintOnly でも apply_paint_only_values が false を返す 経路があり、その場合は診断が出ない作りだった。 computed が空のとき早期に戻す修正自体は残してある(無害かつ正しい)。

【2026-08-02】ヒーロー背景写真が出ない件の決着

経過

スクリーンショットでヒーローが単色グラデーションに見えた。 順に切り分けた:

  1. 画像取得の成否がどこにも出ていなかった → 完了ログを追加 ([IMG] 取得・デコード完了。1 画像 1 回。spec/logging_policy.md L-3) → IMG_6530.jpg は 3,723,837 バイト・1024x768 で取得・デコード成功
  2. キャッシュから引けているか → [IMG][MISS] を追加したが出ない=命中している
  3. 上に乗るグラデーションが不透明では → stops=a=66 すなわち alpha=0x66(40%)で正しく半透明だった
  4. 描画関数に到達しているか → [BGIMGDIAG] img=1024x768 box=924x529 mode=Cover すなわち到達して正しい寸法で描いていた

結論: バグではなかった

画像が届く前にスクリーンショットを撮っていただけ。 3.7MB の取得に時間がかかる。SCREENSHOT_WAIT を 300 秒にしたら 写真(机の上のコーヒーカップ・手帳・万年筆)が正しく描画された。

外した仮説

「半透明グラデーションが毎フレーム重ね塗りされて写真を潰している」 と考えたが誤り。描画回数はグラデーション 121 回 / 画像 61 回で 確かに 2:1 だったが、写真は正しく見えている。 回数比だけを根拠に原因と決めつけていた。

得たもの

切り分けの過程で足したログのうち、以下は残す(L-1/L-3):

一時的な [BGIMGDIAG] / [GRADDIAG] は目的達成につき削除(L-4)。

【2026-08-04】ギャラリー画像が届かない: 取得順の問題

#gallery を表示すると、画像 3 枚が [Image: 研究室の様子](alt テキスト)のままになる。

ログを見ると画像は要求されている:

https_get_binary ordinal=14 host=www.sugi-lab.net path=/img/top8.jpg

ordinal=10..13 が Noto Sans JP(1 本 5.3MB × 4 = 約 21MB)で、 画像はその後ろに並んでいる。実行時間内に届かない。

alt テキストを出すこと自体は取得中の正しい挙動なので、 描画のバグではなく取得順の問題。

直し方

実ブラウザは種類ごとに優先度を持つ:

  1. CSS(レンダリングをブロックする)
  2. 表示領域内の画像
  3. Web フォント(font-display: swap なら代替で先に描ける)
  4. 表示領域外の画像

このサイトの CSS は font-display: swap を指定しているので、 フォントより表示領域内の画像を先に取るのが正しい。

現状は投入順(= HTML/CSS に現れた順)でしかない。 font_queue と IMAGE_QUEUE が別々にあるのも、 優先度を付けられない一因。

次: 取得キューを 1 本化し、種類と可視性で優先度を付ける。 打ち切りはしない(R-2)。順序を変えるだけ。

【2026-08-05】並列取得への変更(ユーザ指摘)

「優先度で順番を入れ替える」案を書き始めたが、 並列で取って届いた順に反映する方が本質的という指摘を受けて方針変更。

直列だった理由

font_queue / IMAGE_QUEUE とも thread_active: bool で ワーカーが 1 本だけだった。5.3MB のフォントや重い画像を 1 つ取っている間、同じキューの後続は一切進まない。

実測: ギャラリー画像 3 枚がフォント 21MB の後ろに並び、 実行時間内に届かず alt テキストのままだった。

修正

active_workers: usize(上限 4 本)にして、 待ち行列がある間はワーカーを増やす。 通信待ちの間はスケジューラへ譲るので、重い 1 本が他を止めない。

結果: ギャラリー写真 3 枚が表示されるようになった。

【2026-08-05】画像の自然サイズが使われていなかった

App_Store_Badge_US-UK_135x40.svg(本来 135×40)が 画面外へはみ出すほど大きく描かれていた。

原因は 2 つ:

  1. 画像到着後に再レイアウトしていなかった poll_image_results はキャッシュへ入れて再描画するだけで、 要素の箱はプレースホルダ寸法のまま。届いた画像がそこへ 引き伸ばされる。実ブラウザは寸法未指定の画像が届くとリフローする。

  2. ネットワーク画像の寸法を知る経路が無かった values.rs の <img> 寸法決定は src が / 始まり (ローカル FS)のときしか解決できず、それ以外は既定の 400×200。

    デコード完了時に register_image_natural_size で登録し、 レイアウトが拾うようにした。

結果: バッジが正寸(135×40)で描かれるようになった。

踏んだリグレッション

再レイアウトのために dom_needs_rebuild を立てたら is_new_page 扱いになり image_cache がクリアされ、 届いた画像が捨てられて alt テキストへ戻った。 同じ文書の再レイアウトではフラグを立てないよう修正。

【2026-08-05】「DOM は組み直す・キャッシュは残す」を分けた

踏んだ二律背反

フォント/画像が届いたときの再レイアウトで:

どちらか一方では直らない。

正しい分け方

let is_new_page = self.dom_needs_rebuild || self.last_html != html;   // DOM 組み直し用
let is_document_changed = self.last_html != html;                      // キャッシュ破棄用

スクロール位置の保持でも同じ判定を使っている(2026-08-03 の修正)。

結果: 画像は各 1 回だけデコードされ、 #projects / #gallery の画像が表示され、色被りも解消した。

【2026-08-05】画像パスの律速を実測で切り分けた

まず内訳を測った

デコードを速くしようとしていたが、その前に内訳を測るべきだった。

[IMGPERF] path=/img/IMG_6530.jpg bytes=3723837 cache=false
          fetch=3685tick decode=1092tick polls=80342

取得がデコードの 3 倍以上。デコードを 16 倍速くしても 全体は 1.3 倍にしかならない。縮小デコードは優先度が低い。

外した仮説(すべて片方ずつ変えて実測)

仮説 変更 結果 判定
受信ウィンドウが小さい 8192 → 32768 3746 → 3906 tick 効果なし(戻した)
TLS 受信の待ちが 10ms 刻みで粗い sleep(1) → 数十回 yield_now() 3746 → 3704 tick 効果なし(戻した)
1 ポールの回収数が少ない 8 → 32 フレーム 3685 → 8329 tick 2.3 倍悪化(戻した)
ポーリング間隔が粗い 100ms → 50ms 3685 → 3907 tick 効果なし(戻した)

成功率はどの条件でも 13/13、truncated=0 で変わらなかった。

2026-07-30 の「全滅」の原因が分かった

当時は間隔(100→20ms)と回収数(8→64)を同時に変えて 8/8 全滅し、「詰めると阻害する」と結論していた。

今回回収数だけを 8→32 にしたところ、 成功率は 13/13 のまま遅くなった(全滅はしない)。 つまり全滅の原因は回収数ではない。残るのは間隔側。

回収数を増やすと遅くなる理由は、QEMU の usb-net が デバイス側に 1 フレームしか持てないため、予算を増やしても 空振りの待ちが増え、その間 USB_LOCK を握り続けて 他を止めているとみられる。8 のままが正しい。

私の見立ても外れた

「100ms × 8 フレーム × 1500B = 120KB/s が上限」という計算は 実効 100KB/s とよく一致したので正しく見えたが、 間隔を半分にしても速くならなかったので誤り。

実際には poll_usb_ethernet_data_plane の内側で USB 転送の同期待ちに時間を使っている。 だから外側の間隔をいくら詰めても変わらない。

次に見るべき場所

kernel/usb.rs の poll_usb_ethernet_data_plane の中。 1 フレーム収穫あたりのチャネル再装填と完了待ちの手順 (spec/l1_l2_usb.md)。ここを測らずに外側をいじっても動かない。

教訓

M-1: 最適化の前に内訳を測る。 「重そうな方」を直感で選ぶと、3 倍重い側を見逃す。

M-2: 変数は片方ずつ変える。 同時に変えた過去の観測は「どちらが原因か分からない」情報しか残さない。 今回それを 1 つずつ潰して初めて当時の結論の誤りが判明した。

M-3: 計算が実測とよく一致しても、それは仮説の裏付けにならない。 その仮説から導かれる別の予測(間隔を半分にすれば倍速)を 検証して初めて確かめられる。

【2026-08-05】並列化がファイルシステムを壊していた

症状

キャッシュが機能しておらず、毎回 14MB(フォント 5.3MB × 2+画像 3.7MB)を 取り直していた。ログには意味不明なエラーが並ぶ。

[CACHE] 保存に失敗 ... err=read_sector: sector out of range or buffer too large
[CACHE] 保存は成功したのに読み返せない key=... bytes=5327688
[SylFS] Failed to read bitmap sector 10
[SylFS] read '...': data sector 19997 unreadable: both primary and mirror corrupted
[SylFS] read_file('...') failed: extent list unreadable

真因: get_fs() に排他が無い

kernel/fs/mod.rs の get_fs() には、以前からこう書かれていた。

今後 FS へアクセスするコードを Core 1〜3 側(spawn_on_core の新規 呼び出し等)に追加する場合は、先に排他機構(spin::Mutex 等)の 導入を検討すること

この session でリソース取得を 4 並列にしたとき、この警告を見落とした。 複数のワーカースレッドが同時に web_engine/cache.rs 経由で FS を触り、 空きセクタビットマップが壊れていた。 同じセクタが二重に割り当てられれば、当然データも索引も壊れる。

対処

kernel::fs::FS_LOCK(spin::Mutex<()>)を追加し、 read_cache / write_cache の操作全体で保持する。 保存と読み返しの間も手放さない(間に割り込まれると 「保存したのに読めない」が再発する)。

get_fs() は &'static mut を返すので、ロックを関数の中へ隠せない (借用が呼び出し側へ渡るため)。呼び出し側が持つ設計にしてある。

結果(実測)

修正前 修正後
[CACHE] 異常 毎回複数 0
SylFS のエラー・破損 毎回複数 0
ビットマップ読み出し失敗 あり 0
fetch(3.7MB 画像) 平均 4256 tick 2006 tick

単体試験 846 件パス、描画に回帰なし。

併せて直したもの

allocate_sector がビットマップの余剰ビット(切り上げで生じる、 実在しないセクタに対応するビット)を配っていた。 満杯付近で存在しないセクタ番号を返し、 「満杯」ではなく sector out of range という無関係なエラーになっていた。 範囲外なら確保せず満杯として報告する。単体試験 2 件で固定。

教訓

F-1: コード中の「〜する場合は先に〜を検討すること」という 申し送りは、条件を満たした時点で守る。 今回は自分で条件(他コアからの FS アクセス)を作っておきながら見落とした。 並列度を上げるときは、触る共有資源を全部洗い出すこと。

F-2: 「保存に失敗」「読み返せない」のような症状のログだけでは 原因に届かない。read_file が内部で持っていた extent list unreadable という具体的な理由が決め手になった。 握り潰さずに理由を残しておくと、後から効く。

【続】排他の穴は 1 箇所では済まなかった

cache.rs の read_cache / write_cache だけロックしても不十分だった。 get_fs() の呼び出しを全部数えたら、ワーカースレッドから走る経路が 他に 5 箇所残っていた。

場所 経路
image.rs の is_local 分岐 画像ワーカー(最大 4 本)の中
cache.rs::clear_browser_cache 一覧取得と削除の間に割り込まれる
layout.rs::fetch_script_text localhost の CSS/JS 読み
layout.rs::fetch_binary_bytes localhost のフォント読み(ワーカー)
mod.rs の壊れたキャッシュ削除 ローダースレッド

1 箇所塞いでも、残りが同じビットマップを無防備に触れば同じこと。 共有資源に排他を入れるときは、その資源へ触る経路を全部数える。

最終実測

fetch=1878tick   ← このセッションの最良値(開始時は平均 4256 tick)
[CACHE] 異常 0 件 / SylFS エラー 0 件 / ビットマップ破損 0 件
[NET][STATS] total=12 ok=12 truncated=0
ログ混線 0 行

単体試験 846 件パス、描画に回帰なし。

未解決(申し送り)

単体試験がまれに 1 件だけ落ちる(845 passed; 1 failed)。 3 回連続で再現せず、落ちた回もテスト名を採取できなかった。 次に遭遇したら make test の出力を丸ごと保存して failures: 節からテスト名を取ること。

【2026-08-05】CSS/JS の非同期化を試して差し戻した

動機(測定に基づく・正しかった)

parse_and_layout を段ごとに測ると、

html=1  css=4  style=40  layout=5  flatten=7  合計=57tick
html=0  css=12 style=135 layout=29 flatten=7  合計=183tick

計算そのものは軽い。にもかかわらず関数全体は 92〜2176 tick。 差の正体は fetch_script_text の同期通信待ちだった。 ここに「CSS / JS は同期(未対応・残る本丸)」と書いてあったとおり。

やったこと

フォント用のキュー(font_queue)へ積んで待たずに返すようにした。 やることは「取得してキャッシュへ書き、届いたら知らせる」で同一なので流用できる。

レイアウトは 30〜164 tick まで落ちた(狙いどおり)。

差し戻した理由

ページが素の HTML のまま描かれた。

external_css_cache と cached_stylesheet を到着時に捨てるようにしても 直らなかった。原因は未特定。

見た目が壊れたまま残す方が害が大きいので同期へ戻した。 描画が元どおりになることを確認済み。

分かったこと

非同期化は「キューを差し替える」だけでは終わらない。 「初回は CSS 無しで描き、届いたら確実に当て直す」経路を 作り込む必要がある。少なくとも次の 3 点を先に決めること。

  1. スタイルシートの抽出結果をどの条件で捨てるか (external_css_cache / cached_stylesheet / dom_needs_rebuild の関係)
  2. 届いた CSS がどのレイアウトで確実に読まれるか (到着とレイアウトの順序保証)
  3. 素の HTML で描いた状態から戻れることの確認手段 (スクリーンショットで見るしかない現状でよいか)

教訓

R-6: 性能のための変更が見た目を壊したら、原因究明より先に戻す。 壊れたまま次の調査へ進まない。 今回は測定(レイアウト 30〜164 tick)としては成功だったが、 それは差し戻した後も記録として残せる。

【2026-08-05・続】CSS/JS 非同期化: 2 度試して 2 度とも戻した

1 回目の差し戻しは私の誤判定だった

「ページが素の HTML のまま描かれた」として戻したが、 これは撮影が CSS 到着前だっただけ。計装して確かめると

[CSSDIAG] 抽出 ext_len=124813 bridge_src=false
[CSSDIAG] inline_css_len=124813 cache_hit=true rules_before=2403

2403 ルールが正しく当たっており、スタイル付きで描画されることも スクリーンショットで確認できた。見た目 1 枚で原因を決めつけていた。

2 回目は本物の回帰だった

採用して測り直すと、2 回続けてページ自体が読み込めなくなった。

Loading Secure Page... のまま
[NET][STATS] after-resp total=3 ok=3      ← 正常時は total=13

CSS/JS をフォント用ワーカーへ積んだことで同時接続が増え、 メイン HTML の取得が進まなくなったとみられる。 この TCP/TLS スタックが同時接続に弱いことは既知 (spec/TODO.md の「接続回数依存の劣化」)。

差し戻して total=13 ok=13 と描画の完全復帰を確認済み。

入れる前に要るもの(更新)

  1. リソース種別ごとの優先度と同時接続数の上限 メイン HTML を最優先にし、CSS/JS/フォント/画像は後回しにする。 「実装順序」節の 4(キューを 1 本に統合し優先度を持たせる)が 非同期化の前提条件だったと分かった。順番が逆だった。
  2. 到着時に external_css_cache / cached_stylesheet を捨てる処理 (render.rs に実装済み。これ自体は正しく、残してある)
  3. 「読み込めた/読み込めない」を撮影に頼らず判定する手段 (今回 2 回とも撮影して初めて気付いた。[NET][STATS] の total が普段と桁違いに少ないことを機械的に見るべき)

教訓

R-7: 見た目 1 枚で原因を決めつけない。 「スタイルが当たっていない」ように見えても、 当たっているのに撮影が早いだけということがある。 計装して中の状態を見てから判断する。

R-8: 依存順序を確かめてから着手する。 非同期化は「キューの優先度制御」が先に要る作業だった。 spec の実装順序にそう書いてあったのに、後ろから手を付けた。

【2026-08-05】非同期化の前提条件を 1 つ実装した(優先度制御)

前節で「実装順序の 4(キューを 1 本に統合し優先度を持たせる)が 非同期化の前提条件だった」と分かったので、その最小実装を入れた。

入れたもの: web_engine/fetch_limit.rs

  1. メイン HTML の取得中はリソース取得を新たに始めない ページの他の何よりもメイン HTML が優先される (それが無ければ描くものが無い)。 非同期 CSS で [NET][STATS] total=3 になった直接の原因への対処。
  2. 同時に走るワーカー総数の上限を種別横断で持つ (フォントと画像で別々に 4 ずつ持っており、実際には 8 本張れていた)

判定は純粋関数 may_spawn(main_in_flight, active, queued) に切り出し、 単体試験 6 件で固定(tests/src/test_fetch_limit.rs)。

上限値は実測で決めた

最初 4 にしたら背景写真が届かなくなった。

上限 4: [NET][STATS] total=12   [IMGPERF] 出ず(画像が 200 秒に間に合わない)
上限 8: [NET][STATS] total=13   [IMGPERF] fetch=3531tick   描画も完全

3.7MB の画像は最も重く、並列度を半分にすると間に合わない。 観測された不具合の原因は「同時数が 8 だから」ではなく 「メイン HTML と競合したから」だったので、そちらだけを直し、 総数は現状維持(8)にした。ここは安全網として置く。

残る前提条件

非同期化にはまだ足りない。次は:

教訓

R-9: 上限値は実測で決める。 「同時接続に弱いから減らす」は方向としては正しくても、 減らしすぎると重いリソースが間に合わなくなる。 両側に失敗モードがある値は、両側を測ってから決める。

【2026-08-05・総括】CSS/JS 非同期化は 3 度試して 3 度とも戻した

経過

回 症状 対処 結果
1 素の HTML に見えた — 誤判定。計装すると ext_len=124813 rules=2403 で正しく当たっていた。撮影が CSS 到着前だっただけ
2 メイン HTML が読めない(total=3、正常時 13) fetch_limit(メイン HTML 取得中はリソース取得を始めない) 変わらず total=3
3 門が閉じている間の投入が滞留していた pump()(毎フレーム起こし直す) total=12 まで回復。だがCSS が当たらない

3 回目は取得もキャッシュ破棄も動いているのにスタイルが当たらない。原因は未特定。

見た目が壊れたまま残さないため同期へ戻し、 total=13 ok=13 と描画の完全復帰を確認済み。

副産物(残してある。いずれも独立して正しい)

追加 内容
fetch_limit.rs メイン HTML を最優先にする門と、種別横断の同時数上限。単体試験 6 件
font_queue::pump / image::pump 投入時にしかワーカーを起こさない作りの穴を塞ぐ。門が無くても、投入が重なった瞬間に取りこぼす可能性があった
到着時の external_css_cache 破棄 非同期化したときに必須。同期でも害は無い

次にやるときの手順

憶測で往復しないために、先に計装を入れてから着手する。

教訓

R-10: 同じ変更で 3 回失敗したら、変更をやめて計装を作る。 今回 1 回目は誤判定、2 回目と 3 回目は別の原因で、 そのたびに新しい対処を足していた。 中が見えないまま対処を積むと、直った理由も直らない理由も分からない。

【2026-08-05・総括】CSS/JS 非同期化は 9 回試して未達

実測で得た数字(これは確か)

[CSSTRACE] 到着 path=/css/modern-style.css 投入から=987tick   ≒ 9.9 秒
[CSSTRACE] 到着による再レイアウト 到着から=626tick            ≒ 6.3 秒

投入から反映まで 16 秒。同期版なら最初のレイアウトで揃う。

私が出して撤回した結論(9 回ぶん)

# 疑ったこと 実際
1 CSS が取れていない 取れていた(撮影が早かっただけ)
2 メイン HTML と競合 門を入れても変わらず
3 投入が滞留 pump() で解消したが変わらず
4 描画に届いていない 中は全部正常だった
5 到着が遅すぎる 一部正しいが決定打ではない
6 優先度が無い 入れても変わらず
7 style_tree がハング 誤り。ログ末尾を「止まった」と誤読
8 ヒープ競合 誤り。ワーカー停止でも変わらず
9 フォントがまだ同期 誤り。2026-07-30 に非同期化済み。コードを読まずに書いた

7・8・9 は事実誤認。 うち 9 は、その場でコードを開けば 1 分で分かった。

教訓

R-11: ログの末尾は「そこで止まった」の証拠にならない。 実行が終わっただけかもしれない。行番号と実行終了時刻を突き合わせる。

R-12: 「〜のはずだ」で原因を書かない。 その場でコードを開く。 9 回目の誤りは fetch_binary_bytes を 1 行読めば防げた。測定より安い確認を飛ばしていた。

R-13: 症状に対して対処を積み上げる前に、 段ごとの所要時間を測る。9 回目にようやく測って、 16 秒の内訳(9.9 + 6.3)が一度に出た。最初にやるべきだった。

残した資産

追加 内容
fetch_limit.rs メイン HTML 優先の門、種別横断の同時数上限、種別優先度。単体試験 13 件
font_queue::pump / image::pump 投入時にしかワーカーを起こさない既存の穴を塞ぐ
[CSSTRACE] 計装 段ごとの所要時間・ノード数・深さ。訂正はすべてこれで可能になった
到着時の CSS キャッシュ破棄 非同期化に必須。同期でも害なし

次にやること

draw() の回数が減る理由を測る(draw() 1 回の中ではなく、 draw() と draw() の間で GUI スレッドが何をしているか)。 それが分かるまで非同期化には手を付けない。

【2026-08-05】sleep() は「ちょうど」ではなく「最低でも」

一斉計測(web_engine/perf.rs)を入れた最初の成果。

見つけ方

[PERF][ALL] で全体を 1 回で見たところ、 送信待ちが 12191 tick(約 122 秒)で最大の単一コストだった。

そこでその中身を 3 つに割って、また 1 回で見た。

送信待ち=12191/39
sleep実測=12163/1105   ← ほぼ全部がこれ
応答確認=9/1105        ← ほぼ 0(ロック待ちではない)
eth poll=16/1105       ← ほぼ 0

ロック競合でもポーリングでもなく、sleep() そのものだった。

原因

1105 回 × POLL_STEP=3 = 3315 tick のはずが、実測 12163 tick。 sleep(3) は実際には約 11 tick かかる(3.7 倍)。

スケジューラの sleep(n) は「最低でも n tick」であって 「ちょうど n tick」ではない。他スレッドが動いていれば延びる。

待ちループはこれを waited += POLL_STEP(指定値の足し算)で 数えていたため、「600ms 待って再送」のつもりが実際は 2.2 秒だった。

対処

実経過で数える。

let t_wait0 = get_ticks();
while get_ticks().wrapping_sub(t_wait0) < WAIT_PER_TRY { ... }

結果(同じ 39 回の送信で比較)

送信待ち ok/total
修正前 12191 tick 12/12
修正後 3945 tick 12/12

3.1 倍短縮、約 82 秒の削減。成功率は変わらない。 (この回は画像デコードが 2128→4110 tick と倍増しており  ホスト負荷は高い方だった。それでも 1/3 になっている。)

教訓

R-14: sleep(n) を「n だけ待った」として時間を数えない。 実経過を測る。 指定値で数えると、負荷が高いときほど 静かに何倍も待つことになる。

R-15: パラメータを動かしても結果が変わらないときは、 そのパラメータが効いていない。値を変え続けず、 その処理の中身を割って測る。 今回 3 通り試して合計が動かず、中身を割った 1 回で原因が出た。

【2026-08-05】無条件の待ちを 6 箇所まとめて撤去

R-14(sleep(n) は「最低でも n」)が分かったので、 同じ形の待ちを一括で洗った。

見つかったもの

sleep(50)(500ms 固定)が 6 箇所。すべて 「要求を送ったのでサーバ処理を待つ」という無条件の待ちだった。

場所 用途
tls.rs × 4 HTTPS の GET / POST / バイナリ取得
net/http.rs × 2 HTTP の生リクエスト / GET

いずれも直後の受信ループがどのみち待つので、純粋な上乗せ。 しかも実測 3.7 倍で約 1.85 秒になっていた。

対処

net::tcp::wait_for_first_byte(local_port, max_ticks) を 1 つ作り、 6 箇所すべてを置き換えた。上限は同じ 50 tick のまま、 届いたら即座に返る。待ちは実経過で数える。

効果(変えた当人を直接測った)

[PERF][ALL2] 初回応答待ち=23/12

12 回の呼び出しで合計 23 tick(1 回 2 tick)。 修正前は 1 回あたり約 185 tick(500ms × 3.7)だったので、 12 回で約 2200 tick ≒ 22 秒の削減。

https取得 のような端から端の数字は 23000〜36000 tick と 回ごとに大きく振れるため、この差は埋もれて見えなかった。 変えた当人を測ったから 1 回で分かった(C-6)。

この 2 つで削れた合計

修正 削減
送信待ちを実経過で数える 12191 → 3945 tick(約 82 秒)
無条件 500ms を 6 箇所撤去 約 2200 → 23 tick(約 22 秒)

合わせて約 104 秒。成功率・描画に変化なし。

【2026-08-05】TLS 受信バッファの O(n²) を潰した

見つけ方(実機 2 回)

送信待ちを直したあと、[PERF][ALL] の最大項目は受信待ちになった。 その中身を割るスロットを足して 1 回測る。

受信待ち=40968/16661
  受信sleep=8102/5191   ← sleep は 1.6 tick/回。過剰ではない
  recv呼出=233/6684     ← ほぼ 0
  差分 ≒ 32633          ← どちらでもない

sleep でも recv でもない 32633 tick がループ内に残っていた。

原因

読むたびに self.buffer.drain(0..len) していた。 TLS はレコードヘッダ 5 バイトのように小さく読むので、 そのたびに残り全体を前へ詰め直すことになる。O(n²)。

対処

読み出し位置 pos を持ち、詰め直しをやめた。 新しいデータを追記する直前にだけ、読み終わった前半を捨てる。

// 読み出し: 詰めない
buf[..len].copy_from_slice(&self.buffer[self.pos..self.pos + len]);
self.pos += len;

// 追記の直前だけ詰める
if self.pos > 0 { self.buffer.drain(0..self.pos); self.pos = 0; }

効果

受信待ち 呼び出し回数 ok/total
修正前 40968 tick 16661 10/10
修正後 11647 tick 25416(増えている) 13/13

約 29300 tick 削減。 呼び出し回数はむしろ増えているのに 所要時間は 3.5 分の 1。

修正後の内訳は 受信sleep=11229 がほぼ全部で、 無駄が消えて正当な待ちだけが残ったことが確認できる。

この一連で削れた合計

修正 削減
送信待ちを実経過で数える 約 8250 tick
無条件 500ms を 6 箇所撤去 約 2200 tick
受信バッファの O(n²) 約 29300 tick

いずれも成功率・描画に変化なし。単体試験 858 件パス。

教訓

R-16: 「内訳の合計が全体に足りない」ときは、 足りない分にこそ原因がある。 今回 sleep と recv を測って 8335 tick しか説明できず、 残り 32633 tick を探して drain に行き着いた。 分解して引き算が合うまで追うこと。

【2026-08-05・総括】ネットワーク経路の無駄は洗い切った

最終的な内訳(1 回の実行で全部出る)

[PERF][ALL]  https取得=27684/13 送信待ち=3970/39 受信待ち=11885/26743
             cache読=57/69 cache書=3636/14 css/js取得=6459/16
             fontface=157/8 font解析=4/11 img復号=2965/1
[PERF][ALL2] sleep実測=3917/686 応答確認=5/686 eth poll=45/686
             初回応答待ち=40/14 受信sleep=11615/6362 recv呼出=79/8925
[PERF][ALL3] DNS=96/15 TCP接続=746/14 TLS握手=3777/14

DNS も TCP 接続も軽い(96 / 746)。 残りは実質すべて送受信の待ちで、その中身は 受信sleep=11615(正当な待ち)が占める。

直したもの

修正 削減 確かめ方
送信待ちを実経過で数える 約 8250 tick 送信待ち
無条件 500ms を 6 箇所撤去 約 2200 tick 初回応答待ち
受信バッファの O(n²) 約 29300 tick 受信待ち

いずれも ok/total と描画に変化なし。

入れなかったもの(実測で否定)

案 結果
受信ループで眠る前に 32 回譲る 受信待ち 12496 → 11535(8%)に対し、譲る回数は 6234 → 30291(5 倍)。割に合わない
受信ウィンドウ 8192 → 32768 効果なし(spec/l1_l2_usb.md)
1 ポールの回収数 8 → 32 2.3 倍悪化
ポーリング間隔 100ms → 50ms 効果なし

ここから先

受信待ちは正当なネットワーク遅延であり、削るべき無駄ではない。 これ以上縮めるなら「待ち方」ではなく往復回数そのものを減らす方向だが、 ウィンドウ拡大は既に否定されている。 QEMU/SLIRP 経由という条件では、この経路は行き着くところまで来た。

残る大きな項目は cache書=3636/14(1 回 260 tick)と css/js取得=6459/16。次に測るならこの 2 つ。

【2026-08-05・重大】ワーカースレッドが 3 億回空回りしていた

見つけ方

まとめ取得を 6 回配線して 6 回とも [NET][STATS] total=3 で止まった。 毎回「取得のしかた」を変えていたが直らない。

7 回目に取得のしかたではなく、ループが回っているかを数えた。

[FQDIAG] iters=341562104 spawn=4 exit=341562100 cached=0 fetch=8 pending=0

ワーカーは 4 本しか起こしていないのに、 終了処理を 3 億 4 千万回通っていた。

原因

font_loader_thread / image_loader_thread は、 待ち行列が空になったとき return していた。

カーネルスレッドの入口関数から return してもスレッドは終わらず、 入口から再実行され続ける。

他のスレッド(web_engine/mod.rs の async_load_thread_entry、 main.rs の各所)はいずれも scheduler::exit() を明示的に呼んでいる。 この 2 箇所だけ作法が違っていた。

効果

修正前: iters=341562104  spawn=4  exit=341562100
修正後: iters=12         spawn=4  exit=4

3 億 4 千万回 → 12 回。

空回りは CPU を食い潰すので、通信・描画・レイアウトの すべてが遅くなっていた。total=3 で止まる回があったのも、 この空回りが CPU を奪っていたためとみられる。

教訓

R-17: スレッドの入口関数は return で終わらない。 scheduler::exit() を呼ぶ。 同じ役割の関数が他にあるなら、終わり方まで揃える。

R-18: 「処理の中身」を 6 回変えても直らないなら、 その処理が呼ばれているか / ループが回っているかを数える。 今回それを 1 回やっただけで原因に届いた。 中身より先に回数を見ること。

同じ形の欠陥を全スレッドで洗った

scheduler::spawn に渡している入口関数を全部数えた(5 つ)。

入口関数 終わり方 対処
async_load_thread_entry scheduler::exit() 正しい
font_loader_thread return 修正
image_loader_thread return 修正
video_playback_thread 関数末尾 修正
tab_thread_fn 既定 None(実装なし) 対象外

5 つのうち 3 つが間違っていた。 1 つ見つけた時点で残りを全部確認するのが要点 (spec/l1_l2_usb.md U-6 と同じ)。

確認

[FQDIAG] iters=12 spawn=4 exit=4 cached=0 fetch=8 pending=0
[NET][STATS] total=13 ok=13

修正前 iters=341562104 → 修正後 12。

複数回・複数サイトで確認した(2026-08-05)

1 回の実行・1 サイトでは検証として足りないので、繰り返して確かめた。

www.sugi-lab.net を 3 回

回 total/ok truncated [FQDIAG] TLS握手
1 13/13 0 iters=12 spawn=4 exit=4 3531/14
2 13/13 0 iters=12 spawn=4 exit=4 3534/14
3 13/13 0 iters=12 spawn=4 exit=4 3512/14

3 回とも完全に同一。 描画も毎回完成(写真・Web フォント・ボタン)。 FS 異常 0 件、ログ混線 0 行。

iters が 12 で揃っているのが要点。 修正前は 3 億回台で、しかも回ごとに大きく振れていた。

example.com(外部リソース無しのページ)

正しく描画。[FQDIAG] iters=0 spawn=0 exit=0 で、 取得すべき外部リソースが無ければワーカーは起動しない。 空回りしていた頃はここでも回り続けていたはずで、 軽いページでも CPU を食っていた。

この session の確定した改善(すべて実測)

修正 効果
ワーカーの return → scheduler::exit()(3 箇所) 空回り 3 億 4 千万回 → 12 回
送信待ちを実経過で数える 12191 → 3945 tick
無条件 500ms の待ちを 6 箇所撤去 約 2200 → 23 tick
TLS 受信バッファの O(n²) 受信待ち 40968 → 11647 tick
ヒープ/FS の排他(FS_LOCK) FS 破損 毎回複数 → 0
ログ行の不可分出力 混線 2/399 → 0
撮影ハーネスのログ読み 差分読み。起動失敗を検出して再送

【2026-08-05・達成】接続の使い回しが入った

7 回目にして配線できた。6 回の失敗の原因は、まとめ取得ではなく ワーカーの空回り(return でスレッドが終わらない、R-17)だった。 空回りを直したら、同じ配線がそのまま通った。

実測(3 回)

TLS握手 total/ok truncated
修正前 3512/14 13/13 0
修正後 1 2936/12 13/13 0
修正後 2 2962/12 13/13 0
修正後 3 2994/12 13/13 0

ハンドシェイク 14 回 → 12 回、3512 → 約 2950 tick(約 6 秒短縮)。 成功率・描画に変化なし。3 回とも同じ値。

仕組み

削減が 2 回にとどまる理由

まとめられるのは「同時に待ち行列へ並んでいる同一ホストのもの」だけ。 実サイトではフォント 8 本が別々のタイミングで発見されるため、 同時に並ぶ数が少ない。

さらに縮めるなら、@font-face を見つけた時点で まとめて投入する(1 本ずつではなく)方向。 上限(MAX_KEEPALIVE_BATCH = 4)も実測で決め直す余地がある。

まとめ取得をさらに伸ばす試みは戻した

まとめられる数を増やすため、 「@font-face を全部積んでからワーカーを起こす」 (enqueue_kind_deferred + spawn_workers)を試した。

狙いは正しい。1 本目を積んだ時点でワーカーが走り出すので、 残りが待ち行列へ並ぶ前に取得が始まり、同じ便に載らない。

ハンドシェイク 12 → 11(狙いどおり減った)
だが total=13 → 11、[FQDIAG] iters=0 spawn=0
→ **フォントも背景写真も届かない**

ワーカーが一度も起動しなかった。 起こす契機を 1 箇所に集めたため、その 1 回が fetch_limit の空き待ちに当たると誰も起こし直さない。

戻して total=13 ok=13、TLS握手=2911/12、 [FQDIAG] iters=11 spawn=4 exit=5 fetch=4 と描画の完全復帰を確認。

関数(enqueue_kind_deferred / spawn_workers)は残してあるが 呼んでいない。 入れるなら「起こす契機を 1 箇所にしない」 (積んだ側でも起こす/pump() が確実に拾う)ことが先。

教訓

R-19(取り下げ): 「起こす契機を 1 箇所に集約すると誰も再試行しない」 と書いたが、その観測は置換ミスによるものだった(下記参照)。 根拠が無いので取り下げる。

【2026-08-05】送信待ちは無駄ではなかった(実測で確認)

空回りと接続の使い回しを片付けたあと、最大項目は 送信待ち になった。

[PERF][ALL]  送信待ち=3173/36
[PERF][ALL2] sleep実測=3202/688

内訳はほぼ sleep。ここを削れないか調べた。

この待ちは何か

retry_write 経路。要求を送ったあと応答が来なければ パケットロストとみなして再送するための待ち。 この自作 TCP スタックには再送機構が無いので、ここが唯一の保険。

実際に再送しているかを測った

判断材料が無かったので 送信再送 を出すようにした。

[PERF][ALL4] 送信再送=44

36 回の送信に対し 44 回の再送。 この待ちは働いている。

待ちを延ばしても再送は減らない

「応答が遅いだけで再送しているのでは」と考え、 上限を 60(600ms)→ 150(1.5 秒)にして測った。

 60: 送信待ち=3173/36  送信再送=44
150: 送信待ち=3098/36  送信再送=44

再送回数がまったく変わらない。 待っても来ないものは来ない。 その 44 回は本当にパケットが失われている。 効果が無いので 60 のまま戻した。

結論

送信待ち の 3173 tick は必要な待ちであり、削れない。 減らしたいなら待ち方ではなく、 なぜパケットが失われるか(spec/l1_l2_usb.md の受信経路)を見ること。

教訓

R-20: 「待ち」を削る前に、その待ちが仕事をしているかを数える。 今回 送信再送=44 が出て初めて、削ってはいけない待ちだと分かった。 数えずに削っていれば、パケットロスト時に復旧できなくなっていた。

遅延投入は 2 度試して 2 度とも戻した(2 度目は置換ミス)

1 度目は「起こす契機を 1 箇所に集めたせい」と結論した(R-19)。 2 度目に pump が何に拒まれているかを数えて再試行したところ、

[FQDIAG]  iters=0 spawn=0 pending=0
[FQDIAG2] pump不可=0 同時稼働=0

pump不可=0 かつ spawn=0 は「キューが常に空」を意味する。 つまり遅延投入が一度も呼ばれていない。

調べると、置換がコメント文字列にしか当たっておらず、 実コードは元の enqueue_font のままだった。 一方 spawn_workers() だけが余分に入り、 それが iters=0 を招いていた。

つまり 1 度目の結論も怪しい

1 度目の iters=0 も、同じ置換ミスで 「積む側は変わらず、起こす側だけ壊れた」状態だった可能性が高い。 R-19(契機を 1 箇所に集めない)は、この観測からは導けない。 根拠が無いので取り下げる。

教訓

R-21: 文字列置換で書き換えたら、 実コードに当たったかを機械的に確かめる (grep -c で件数を見る、コメント行を除外する)。 コメントに当たっただけでもビルドは通り、 「変えたつもり」で実測して誤った結論を出す。

今回それで存在しない因果(R-19)を 1 つ作ってしまった。

遅延投入を正しく試した結果(3 度目・不採用)

R-21 に従い、置換が実コードに当たったことを grep -c(コメント除外)で確認してから測った。

従来:   TLS握手=2958/12  spawn=4  total=13 ok=13
遅延版: TLS握手=3525/13  spawn=6  total=13 ok=13

握手が 12 → 13 に増えて悪化。

理由

spawn_workers() は空きがある限り一度に 4 本起こす。 各ワーカーが待ち行列から 1 件ずつ持って別々に接続するので、 せっかく全部並べてもまとめ取得が成立しにくくなる。

「全部並べてから起こす」と「並列に起こす」は両立しない。 まとめたいなら並列度を下げる必要があり、 それは重いリソースが他を止める問題(MAX_FONT_WORKERS の理由)に戻る。

現状の選択

並列 4 本のまま、たまたま同時に並んだものだけまとめる。 これで握手 14 → 12。欲張らない。

さらに減らすなら、ワーカーを増やす前に 「同じホストの待ちが何件あるか」を見て 1 本のワーカーに多く持たせる設計が要る。 今の「1 ワーカー 1 便」では頭打ち。

【2026-08-05 バグ修正】まとめ取得がヘッダごと保存していた

症状

ページ上の Font Awesome アイコンがすべて空の四角になっていた。

追い方

  1. ログに [FONT] 解析開始 が Noto 4 本しか出ていない(FA が 0 本)
  2. 取得もキャッシュも登録も走っているのに registered=false
  3. 失敗ログ: [FONT] 未知のフォント形式 head=[48, 54, 54, 50]

head は {:02x?} 表示なので 48 54 54 50 = “HTTP”。 フォントの中身が HTTP 応答ヘッダで始まっていた。

原因

まとめ取得(keep-alive)で本文を切り出す位置が誤っていた。

// 誤: h は本文の開始位置なのに 0 から取っている
out.push(Some(buf[..h + w].to_vec()));

h は本文の開始位置なので buf[h..h + w] が正しい。 ヘッダ込みでキャッシュへ書かれ、フォント登録が弾いていた。

接続の使い回しを入れたときに混入した回帰。 ページは表示されており total=13 ok=13 も正常だったので、 数字だけ見ていたら気づけなかった。

対処

境界計算を純粋モジュール kernel/http_body.rs へ切り出し、 単体試験 9 件で固定した。とくに

を回帰として残した。

確認

修正前: [FONT] 解析開始 … Noto 4 本のみ/未知のフォント形式 5 件
修正後: [FONT] 解析開始 … FA 7 本 + Noto 4 本/未知のフォント形式 0 件

画面のアイコンも復帰。

教訓

R-22: 「ページが出ている」「成功率が正常」は、 中身が正しいことを意味しない。 今回 total=13 ok=13 のまま、保存内容だけが壊れていた。 バイト列を扱う変更は、先頭数バイトを見る確認を入れる。

同じ経路をもう 1 件直した(scheme の決め打ち)

まとめ取得で取れなかったぶんを待ち行列へ積み直す処理:

// 誤: is_https を true に決め打ち
q.pending.push((host.clone(), pp, true, _prio, true));

HTTP で取ったものを HTTPS として積み直すことになり、 再試行は必ず失敗する。元の値を使うよう修正した。

現状は選定側(queue_batch::may_start_batch / select_batch)が HTTPS だけを通すので実害は出ていなかったが、 片方の前提が変わった瞬間に壊れる書き方だった。

選定側の HTTPS 限定も回帰試験で固定した(3 件追加、計 919 件)。

教訓

R-23: 値を「その経路では必ずこうだから」と決め打ちしない。 今回は選定側の条件に依存した決め打ちで、 依存関係がコードに現れていなかった。 元の値をそのまま運ぶのが安全で、しかも短い。

3 件目: spawn の失敗を見ていなかった

scheduler::spawn はヒープ不足で 0 を返す。 だが 5 箇所すべてで戻り値を捨てていた。

// 誤: 枠を確保してから spawn し、失敗しても返さない
q.active_workers += 1;
super::fetch_limit::try_acquire(..);   // 枠を取る
crate::kernel::scheduler::spawn(..);   // 0 が返っても気づかない

失敗すると「ワーカーは居ないのに枠は埋まったまま」になり、 active_workers と fetch_limit の枠が同時に漏れる。 漏れは回復しないので、以後そのキューは永久に動かない。

ヒープが逼迫するのは大きなフォント(5.3MB × 4)と 画像(3.7MB)を同時に扱うときで、まさに起きうる場面だった。

5 箇所すべてで、pid == 0 なら両方を返すよう修正。

教訓

R-24: 「失敗しうる呼び出し」の戻り値を捨てない。 とくにその前に資源を確保している場合、 失敗経路で返さないと漏れが恒久化する。 確保と解放は同じ関数の中で対にする。

spawn の失敗を見ていない箇所を全部洗った(R-24 の横展開)

scheduler::spawn を呼ぶ 7 箇所すべてを確認した。

箇所 先に立てる状態 失敗時の実害
font_queue(3 箇所) active_workers + fetch_limit の枠 フォント取得が永久停止
image(2 箇所) 同上 画像取得が永久停止
mod.rs ローダー thread_active メイン HTML の読み込みが永久に始まらない
render.rs 動画 playing: true 停止も再開もできなくなる

7 箇所すべてが同じ形(状態を先に立てて、spawn の戻り値を捨てる)。 ヒープ不足は 5.3MB のフォント 4 本と 3.7MB の画像を同時に扱う場面で 実際に起こりうるので、机上の話ではない。

全箇所で pid == 0 なら状態を戻し、失敗をログに残すようにした (spec/logging_policy.md L-1: 失敗は必ず記録する)。

教訓(補強)

R-24: 「失敗しうる呼び出し」の戻り値を捨てない。 とくにその前に状態を立てている場合、 失敗経路で戻さないとその状態が恒久的に嘘になる。

R-25: 同じ形の欠陥は呼び出し箇所を全部数えてから直す。 今回 1 箇所直した時点でやめていたら、 より重い「メイン HTML が読めなくなる」経路が残っていた。

HTTP 応答の境界計算が3 重にあった

tls.rs に同じ計算の写しが 3 つあった。

関数 内容
find_header_end \r\n\r\n の直後を探す
parse_content_length ヘッダ部から長さを読む(文字列添字で切り出し)
response_looks_truncated 上の 2 つを自前で再実装

片方だけ直す事故のもとで、実際に本文の切り出しを誤って Font Awesome が全滅した直後に見つかった。 parse_content_length は文字列添字を使っており、 UTF-8 の途中で切ると panic しうる書き方でもあった。

kernel/http_body.rs へ一本化し、looks_truncated も移した。 単体試験 15 件(境界・WOFF2 の魔法数・chunked・切れ検知)。

この重複がバグの温床だった。 1 箇所直しても他 2 箇所が古いままなら、 「直したはずなのに再発する」ことになる。

2026-08-25 掃討: ロックと「空を入れる」欠陥

FS_LOCK は助言でしかなかった

kernel::fs::FS_LOCK は「FS を触るなら取ること」という取り決めだが、 get_fs() は &'static mut を返すのでロックを関数の中へ隠せない。 守るかどうかは呼び出し側任せになる。

説明文に「現状の取得者は cache.rs だけ」と書いてあり、 その記述が古いまま放置された結果、番人なしで FS を触る箇所が 4 つ増えていた。

場所 種別
layout/values.rs 画像サイズ解決 読み
apps/browser/mod.rs リロード 読み
apps/browser/mod.rs アドレス欄 読み
js/builtins/web_forms.rs localStorage 書き出し 書き

最後のひとつが重篤で、ワーカーの書き込みと重なると 空きセクタビットマップが二重確保され、無関係なファイルが壊れる。

R-26: 「現状の利用者は○○だけ」と列挙した注記は必ず古くなる。 数え上げではなく判定基準を書く。ここでは 「ブラウザのワーカースレッドと同時に走りうるか」。 UI スレッドだから安全、とは言えない。

ロックを保持したまま重い処理を呼ぶと、自分と取り合う

web_engine/mod.rs のローカルパス読み込みは FS_LOCK を保持したまま parse_and_layout() を呼んでいた。

レイアウトは <img> の寸法解決から FS を読み、 JS は localStorage の書き出しから FS を書く。 どちらも FS_LOCK を取るが spin::Mutex は再入できない。 画像 1 枚あるローカルページを開くだけで固まる。

R-27: ロックの保持範囲はその資源を触る文だけに切る。 保持したまま関数を呼ぶと、そこから先で何が起きるか追えなくなる。

パニックで永久に居座るロックがあった

AtmOS は panic = "abort" で巻き戻しが無いため、 ロックを持ったまま死ぬと誰も解放できない。 #[panic_handler] はヒープ・ネットワーク・USB を RecoverableMutex にして死んだコアから取り上げている。

FS_LOCK は後から足したのでこの手当てが漏れていた。 画像ワーカーは os_lib/webp(panic 禁止ポリシーの対象外と 明記されたベンダリング済みデコーダ)を回しながら FS_LOCK を取る。 壊れた WebP 一枚で以後 OS 全体の FS 操作が永久に止まる。

RecoverableMutex へ変更し、パニックハンドラに fs::force_release_locks(cid) を追加。単体試験 9 件で回復契約を固定した (同コアは解放する/別コアのロックは横取りしない/二度呼んでも安全)。

R-28: 「panic してもスレッドが死ぬだけ」と書いてある場所を見つけたら、 そのスレッドが握っているロックを数える。 隔離されるのは実行であって、資源ではない。

「空が居座る」対策を、捨てる側でやっていた

同じ形の欠陥が 2 つ見つかった。

場所 以前 直し方
cache::write_cache 0 バイトも保存し、以後永久に空が返る 入口で空を弾く
external_css_cache 初回の空が居座るので毎回捨てる 全部揃った時だけ保存する

CSS の方は影響が大きかった。捨てるということは 次のレイアウトで外部 CSS を全部取り直すという意味で、 フォントや画像が 1 つ届くたびにページ全体を組み直していた。 背景写真と本文フォントが間に合う前に描き直され、 4 回中 2 回、描画が不完全なまま止まって見えた。

R-29: キャッシュに不完全な値が入るなら、 捨てる側ではなく入れる側を守る。 「毎回捨てる」はキャッシュを無効化するのと同じで、 しかも無効化したことが計算量として表に出ない。

検証器が偽陰性を出すと、本物の不具合と区別できない

撮影スクリプトは「到達後に固定 120 秒待つ」だけだった。 遅い回は取得の途中で撮ってしまい、 ログ上は ok=9 のようにエラーゼロのまま件数だけ足りない形で出る。

ログの断片から終了を推し量る方法を 2 つ試して、どちらも外れた。

当てるのをやめ、OS 自身に [IDLE] font_pending= img_pending= active= main= を出させ、それがゼロで安定するまで待つようにした。

R-30: 外から状態を推測する判定は必ず外れる。 中の状態を明示的に出させる。 計装は速度のためだけでなく、検証の再現性のためにも要る。

パニックしたワーカーは取得枠を返さない

#[panic_handler] は非クリティカルなプロセスを scheduler::exit() でその場で殺す。巻き戻しが無いので、 ワーカーの fetch_limit::release() と active_workers -= 1 はどちらも実行されない。

枠は全体で 8 本(MAX_TOTAL_FETCH_WORKERS)しかない。 os_lib/webp は「カーネルの panic 禁止ポリシーの対象外」と ソースに明記されたベンダリング済みデコーダで、 まさにこのワーカーの中で回る。 壊れた WebP が 8 枚あれば枠を食い潰し、以後 フォントも画像も二度と読み込まれない。 しかも失敗ログすら出ずに黙って止まるので、 「なぜか画像が出ないページがある」という形でしか現れない。

直し方は 2 段構え。

  1. ワーカーは開始時に自分の PID で枠の所有を宣言する (fetch_limit::claim)。正常終了時に外す(unclaim)。
  2. パニックハンドラは on_process_died(pid) を呼ぶ。 ロックを取らず原子変数だけを触る。 ロックを取ると、そのロックを握ったまま死んだ場合に 回収そのものが固まる。 active_workers の補正は種別ごとの死亡数として積み、 毎フレーム走る pump() が遅れて回収する。

単体試験 7 件で契約を固定(種別を取り違えない/取り出したら 0 に戻る/ unclaim 済みは数えない/無関係な PID は無害/PID 0 は所有者にしない)。

R-31: 「パニックしてもそのスレッドが死ぬだけ」と書いてある場所では、 死んだスレッドが返し損ねる資源を数える。 ロックだけではない。上限付きのカウンタも同じで、 むしろこちらは失敗が静かなぶん見つけにくい。

なお、この 7 件はグローバルな原子変数を共有するので std::sync::Mutex で直列化してある。 並列のまま放置すると落ちたり通ったりする試験になり、 偽の失敗は本物の不具合を隠す。

待機判定がロックを取ると優先度逆転で止まる(自分で作った欠陥)

[IDLE] 行の出力位置を、ブラウザの draw() から ウィンドウマネージャの提示ループへ移した。 draw() は待機に入ると止まってしまい、 最後の行が古い標本のまま残るためである。

ところがこのとき、font_queue::pending_len() と image::pending_count() は spin::Mutex を取っていた。

低優先度のワーカーがロックを握っている最中に 提示ループがスピンへ入ると、ワーカーに実行が回らないので ロックも解放されない。典型的な優先度逆転である。

実測: 取得の開始 16 件に対し決着 9 件。 キューは空(font_pending=0 img_pending=0)なのに active=5 のまま 900 秒動かなかった。

待ち件数は原子変数の写しにし、判定側はロックを取らない。 正確さは、キューを変更する側(既にロックを持っている側)が 毎回書き写すことで保つ。フォント側 6 箇所、画像側 2 箇所。

R-32: 止まらないループ(描画・提示・割り込み)から ロックを取ってはいけない。とくに優先度が異なるとき、 spin::Mutex は待つのではなく相手の実行機会を奪う。 状態を覗きたいだけなら原子変数の写しを置く。

R-33: 計装を「止まらない場所」へ移すときは、 そこが何を触ってよい場所かを先に確認する。 今回は「古い標本が残る」という正しい問題意識で移したが、 移した先の制約を確認しなかったため、 観測のための行がシステムを止めた。

タイマ割り込みがスレッドの持つロックを待っていた

scheduler_tick() はタイマ割り込みから呼ばれる(interrupt.rs)。 ところが RUNQUEUES[cid].lock() で待っていた。

スレッド側は同じキューを割り込み許可のまま取る箇所が 12 ある (spawn、sleep、yield_now の一部など)。 そのスレッドを同じコアのタイマ割り込みが叩くと、 ハンドラは自分が中断させた相手の持つロックを待つ。 割り込み出口へ戻れないので相手が解放する機会も来ず、 そのコアが永久に固まる。

spawn はフォント/画像のワーカーを起こすたびに通るので、 ページを開けば毎回この窓を通っている。

取り逃した 1 tick はタイムスライスの数え落としにすぎず、 次の tick で数え直される。待たずに諦めるのが正しい。 try_lock へ変更した。

同じ理由で should_preempt とパニックハンドラ用の 3 関数 (is_current_process_critical / get_current_process_name / get_current_process_id)は既に try_lock を使っていた。 ここだけ作法が違っていた。

R-34: 割り込みハンドラは、スレッドが取りうるロックを 待ってはいけない。待てるのは相手が別コアにいると 保証できるときだけで、同一コアなら必ず自分と取り合う。 try_lock で諦められない処理は、そもそも割り込みでやらない。

なお、入力 FIFO(UART_FIFO / KBD_FIFO / MOUSE_FIFO)は 同じ形の危険があるが、消費側(main.rs)が既に disable_interrupts() で囲んでいた。走査して確認済み。

resolve_relative_path が data: URI とフラグメントを壊していた

resolve_dom_paths(<img src> <script src> <link href> <a href> <video src> を書き換える)が使う resolve_relative_path の判定は「/ で始まる」か「:// を含む」 だけだった。次の 4 種が壊れる。

os_lib/web_engine/rel_path.rs へ切り出し、判定を 「最初の / より前に : があればスキーム付き」という URL の一般規則に統一した。個別のスキーム名を並べるより漏れにくい。 試験 20 本(test_rel_path.rs)で契約を固定。

R-35: 「URL/パスを解決する」関数が複数あるとき、 扱えない値の集合が一致しているかを確認する。 同じ知見が別の実装へ伝わっていなければ、直したはずの穴が 別の関数にそのまま残る。