対象実装:
arm/v1/src/os_lib/web_engine/、arm/v1/src/kernel/tls.rs
モジュール自体は分離されている。レンダリングエンジンに TLS は埋め込まれていない。
| 役割 | 実体 |
|---|---|
| HTTPS クライアント(curl 相当) | kernel/tls.rs: https_get /
https_get_binarykernel/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) 取得完了で結果を格納
└────────────────────────────────────────┘
/cache/browser/)へ保存し、
次回以降はネットワークを叩かない。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 回目以降なくなる)。
@font-face を差し替えて再描画。font_budget / image_budget /
FETCH_BYTE_CAP)は
並列化が完成したら撤去する。撤去まで残すのは暫定措置であることを明記。FETCH_BYTE_CAP(Content-Length で受信を中断)font_budget のサイズ上限・本数上限image_budget のサイズ上限・画素数上限web_engine/font_queue.rs …
フォント取得をスレッド+キューで非同期化。
画像(image_loader_thread +
IMAGE_QUEUE)と同じ構造。
サイズによる打ち切りをしない(R-2)。取得完了はキャッシュ経由で
次のレイアウトに反映される(R-3)。重複投入は seen
で排除(R-4)。fetch_binary_bytes のディスクキャッシュ利用。 実測で
CSS/JS・画像は使っていたのにフォントだけ使っていなかった。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
スケーリングで縮小デコードする、
デコーダにスキャンライン単位の中断点を持たせる、
プリエンプティブなスケジューリングを導入する。
いずれも打ち切りではなく「時間をかけて完遂しつつ譲る」方向で検討すること。
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 の写真が完全に取得・デコードされ、画面に表示された。
打ち切り実装を入れていたのは「待てていなかっただけ」で、 サイズ上限は不要だった。ユーザ指摘のとおり 「時間がかかってもきちんと取得し、取得できた時点で反映する」が正しい。
背景写真・ナビゲーションバー・ロゴ・見出し・サブテキスト・ボタンが 実サイトに近い状態で表示される。
「協調マルチタスクでプリエンプションが無いから止まる」と書いていたが、
プリエンプションは実装も配線もされている
(タイマ割り込み → scheduler_tick() →
need_resched → 割り込み出口の should_preempt()
→ schedule()、interrupt.rs:104)。
image.rs の同趣旨のコメントも訂正済み。
「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()
を挟む
ファーストビュー以降のセクション(研究内容・プロフィール等)を 確認しようとしたが、スクロール入力が届かない。
試して失敗した方法: 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
と同じ形のビルトイン)を用意するのが確実。
browser.scroll(px)
ビルトイン(os_lib/aura/builtins/system.rs) スクリプトから
engine.scroll() を直接叩ける。scripts/screenshot_site.ps1 の
SCREENSHOT_SCROLL=px 撮影前にスクロールする。ブラウザが
active の間はキー入力が ブラウザへ渡りターミナルに届かないため、QEMU
モニタから ESC を送って 非アクティブにしてからコマンドを打つ。SCREENSHOT_WAIT=秒 … 撮影までの待機を延ばす。
大きなリソースは非同期取得なので、待てば描画へ反映される。スクロール処理を追加した際、NETBENCH_URL
ブロックの内側に入れてしまい、
通常経路では一度も実行されない状態になっていた。 さらに
Send-MonitorKey の関数定義も同ブロック内に入り、 PowerShell
の括弧対応が崩れてスクリプト全体が構文エラーになっていた。 →
関数定義を先頭付近へ移し、スクロール処理を通常経路の撮影直前へ移動。
[System.Management.Automation.Language.Parser]::ParseFile
で構文検証して OK。
スクロール後の撮影はまだ成功していない。直近 3
回の実行はいずれも ログイン画面(Confirm Your Password /
Passwords mismatch)で止まった。
スクロール指定なしでも同じ症状が出たので、私の編集とは無関係の
取得スクリプト側のタイミング揺らぎ(本セッションで何度も観測している既知の症状)。
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)入力が
どこへ渡っているかは別途確認が必要。
[UARTIN] ログで UART バイトを直接記録した結果:
[UARTIN] byte=0x1b ← ESC 到達
[UARTIN] byte=0x62 'b' 0x72 'r' 0x6f 'o' ... ← browser.scroll(700) 全体も到達
シリアル入力経路は完全に正常。バイトは全部ゲストへ届いている。
ESC
がスキャンコード変換表から漏れていた(kernel/keyboard.rs)
' '/''/' ' はあるのに ESC(0x1B)
が無く、 シリアルから ESC を送っても変換されず捨てられていた。 →
単体試験 4 件(test_keyboard.rs の
escape_key_tests)を先に書いて
欠落を検出し、'' => Some((0x01, false)) を追加。688
件全通過。
ログイン投入の不安定さ(scripts/screenshot_site.ps1)
固定 30 秒待ちをやめ、シリアルログに Entering main loop
が出るまで 待つ Wait-ForSerial
を追加。ログイン画面で止まる症状は解消。
PowerShell の `e が Send-Keys の char
変換で落ちていた ESC を生バイト(0x1B)で
BaseStream.WriteByte するよう変更。
ESC も F1(QEMU モニタの
sendkey f1、window_mgr.rs:1454 の 0x3B)も
送ったが、scrolled dy=
は一度も出力されない。
バイトは届いているのにシェルがコマンドを実行しない。
注意: この検証手段(下部セクションのスクロール確認)の追求に 時間を使いすぎている。再現作業そのものより優先度が低い。 再開するなら、まずターミナルがどの条件で入力を受け付けるかを コードで確認してから着手すること。推測でキーを送り続けても進まない。
スクロール投入が動かない問題に時間を使いすぎていたので、 別の検証手段に切り替えた。レイアウト済みの要素一覧を直接ダンプする。
[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 回の実行で全セクションを確認できた。
エラーを握り潰さないようにしたら、原因が一本の連鎖として見えた。
[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 アイコンが代替フォントのまま/背景写真も毎回再取得
キャッシュの古いサイズ上限(約
85KB)(web_engine/cache.rs) SylFS
がエクステント方式へ移行して 1 ファイル上限が実質ボリューム
サイズまで拡大したのに、古い定数が残っていた。 Font
Awesome woff2(101088 バイト)も Noto Sans JP(5.3MB)も
この上限で弾かれていた。→ 撤去。
save_file
の結果を握り潰していた(let _ = fs.save_file(...))
キャッシュが書けていないことに誰も気づけなかった。 → Err
をログするようにしたら、上記の連鎖が一発で見えた。
非同期化の副作用でフォントが全部スキップされていた(layout.rs)
fetch_binary_bytes が「キューへ積んで即
None」を返すようになったのに、 呼び出し側がその None
を取得失敗と数えており、
MAX_CONSECUTIVE_FAILURES = 2
のサーキットブレーカーが即発動して 以降のフォントを全部諦めていた。 →
FetchOutcome::{Ready, Pending, Failed} を型で区別し、
should_count_as_failure を単体試験 3
件で固定してから修正。
SDHOST: data path probe failed (read) で SD
初期化に失敗し、 8MB の RAMDisk へフォールバックしている。 5.3MB
のフォント 1
本でほぼ使い切るため、複数リソースはキャッシュできない。
→ SD カードのデータ転送(CMD17 read)の修正が、
リソースキャッシュ全体の前提条件になっている。
spec/TODO.md にも以前から残っている課題。
注意: RAMDisk を大きくするのは対症療法。 本来は SD カードを使えるようにすべき。
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 を毎フレーム見て反映しているので、
フォントも同じ形にすればよい。
注意: これは「待てば出る」類ではない。 通知が無いので待っても永久に反映されない。 背景写真が表示できたのは、画像側には結果反映の仕組みがあるため。
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 回でも 4 回でも、レイアウト 1 回 32〜40 秒である限り ページ表示は間に合わない。通知回数の調整は対症療法であり、 攻めるべきはレイアウトそのもののコスト。
rule_index で カスケードを 2.1
倍にしたが、まだ足りない段ごとに 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 ダウンロード)に食われている分の切り分け。
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
に増えた)。
細粒度の計測には非侵襲な指標(回数カウンタ)を使うこと。
一連の修正(再帰の除去・テキストノードの全走査除去・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
まで下がった。レイアウトはもう主因ではない。
[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
にグリフのラスタライズ結果を保持する
キャッシュが存在しない。静的なものは以下のみ:
GLOBAL_VECTOR_FONT /
GLOBAL_TERMINAL_FONT(フォント本体)CUSTOM_FONTS(@font-face
で読んだフォント本体)つまり同じ文字・同じサイズでも毎フレーム輪郭から描き直している 可能性がある。
get_system_time_us
はノード単位で呼ぶと計測対象を歪めるため使わない)(フォント, 文字, サイズ)
をキーにした
ラスタキャッシュを純粋モジュールとして設計・単体試験してから配線するこの段階で「グリフ描画が原因だ」と断定しない。 キャッシュが無いことは事実だが、それが 3 秒の主因かはまだ測っていない。
[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
vector_font.rs を GLYPH_CACHE で grep
して見つからず
「キャッシュが存在しない」と書いたが誤りだった。
get_glyph(c, size_px) が (char, size) をキーに
CachedGlyph を 返す実装が既にある。8000
件でクリアする上限も付いているが、
実測でクリアは一度も発生していない(ログ 0 件)。
グリフの再ラスタライズは起きていない。
拡縮自体は毎フレーム行っているが、実測で paint の 11% しかない。 ここを直しても効果は小さい。
paint の約 89%(約 260 tick / 2.6 秒)が要素ループの 背景画像以外の部分にある。次はここを テキスト描画・矩形塗り・ボーダー/シャドウ・グラデーションに分けて測る。 まだ原因を断定しない。
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 |
<img> の拡縮が重い →
img の値が bgimg
と完全一致していた。 draw_background_image
が内部で draw_img_object_fit を呼ぶための
二重計上で、独立したコストではなかったrrect=0。 このページではその分岐に入っていない (コード上は
point_in_rounded_rect を毎ピクセル呼ぶ実装で、
角丸を多用するページでは効く可能性は残る)要素ループの後(スクロールバー描画など)は軽く、 フレームバッファへの一括転送のような重い処理も無い。 未特定の 139 tick は要素ループ内の、まだ計測していない分岐にある。
残る候補は render.rs の直接
draw_pixel_alpha 呼び出し (1212 / 1481 / 1494 / 1522
行付近)。次はここを測る。
この 5 つの仮説のうち当たったのは 1 つ(グラデーション)だけ。 コードを読んで「重そう」と思った箇所は軒並み外れた。 測ってから直す方針は正しかった。
描画 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 にする」というコメントがあり、
これが有力。ただしまだ確認していないので断定しない。
dirty を立てている箇所を特定する(推測で消さない。
消し方を誤ると画面が更新されなくなる)repaint_scope.rs
(Nothing / PaintOnly /
Relayout)で振り分ける。
この仕組みは既に作ってあるのに、まだ配線していない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
になり、 全画面再描画を誘発している可能性がある。
次にやること(順序を守る):
[PERF] 系ログを整理してから測り直す。
汚染された数字で判断しないbackdrop-filter のブラーが paint の 53%
を占めていた → 修正済み (ナビバー 179〜478 → 18〜24 tick、paint
243〜305 → 122〜151 tick)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
が空のとき早期に戻す修正自体は残してある(無害かつ正しい)。
スクリーンショットでヒーローが単色グラデーションに見えた。 順に切り分けた:
[IMG] 取得・デコード完了。1 画像 1
回。spec/logging_policy.md L-3) →
IMG_6530.jpg は 3,723,837 バイト・1024x768
で取得・デコード成功[IMG][MISS]
を追加したが出ない=命中しているstops=a=66
すなわち alpha=0x66(40%)で正しく半透明だった[BGIMGDIAG] img=1024x768 box=924x529 mode=Cover
すなわち到達して正しい寸法で描いていた画像が届く前にスクリーンショットを撮っていただけ。
3.7MB の取得に時間がかかる。SCREENSHOT_WAIT を 300
秒にしたら
写真(机の上のコーヒーカップ・手帳・万年筆)が正しく描画された。
「半透明グラデーションが毎フレーム重ね塗りされて写真を潰している」 と考えたが誤り。描画回数はグラデーション 121 回 / 画像 61 回で 確かに 2:1 だったが、写真は正しく見えている。 回数比だけを根拠に原因と決めつけていた。
切り分けの過程で足したログのうち、以下は残す(L-1/L-3):
[IMG] 取得・デコード完了(1 画像 1
回。フォント側と対称)[IMG][MISS] 背景画像がキャッシュに無い(パスごと 1 回。
従来は if let Some(img)
が黙って落ちるだけで何も出なかった)一時的な [BGIMGDIAG] / [GRADDIAG]
は目的達成につき削除(L-4)。
#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 テキストを出すこと自体は取得中の正しい挙動なので、 描画のバグではなく取得順の問題。
実ブラウザは種類ごとに優先度を持つ:
font-display: swap
なら代替で先に描ける)このサイトの CSS は font-display: swap
を指定しているので、
フォントより表示領域内の画像を先に取るのが正しい。
現状は投入順(= HTML/CSS に現れた順)でしかない。
font_queue と IMAGE_QUEUE が別々にあるのも、
優先度を付けられない一因。
次: 取得キューを 1 本化し、種類と可視性で優先度を付ける。 打ち切りはしない(R-2)。順序を変えるだけ。
「優先度で順番を入れ替える」案を書き始めたが、 並列で取って届いた順に反映する方が本質的という指摘を受けて方針変更。
font_queue / IMAGE_QUEUE とも
thread_active: bool で ワーカーが 1
本だけだった。5.3MB のフォントや重い画像を 1
つ取っている間、同じキューの後続は一切進まない。
実測: ギャラリー画像 3 枚がフォント 21MB の後ろに並び、 実行時間内に届かず alt テキストのままだった。
active_workers: usize(上限 4 本)にして、
待ち行列がある間はワーカーを増やす。
通信待ちの間はスケジューラへ譲るので、重い 1 本が他を止めない。
結果: ギャラリー写真 3 枚が表示されるようになった。
App_Store_Badge_US-UK_135x40.svg(本来 135×40)が
画面外へはみ出すほど大きく描かれていた。
原因は 2 つ:
画像到着後に再レイアウトしていなかった
poll_image_results はキャッシュへ入れて再描画するだけで、
要素の箱はプレースホルダ寸法のまま。届いた画像がそこへ
引き伸ばされる。実ブラウザは寸法未指定の画像が届くとリフローする。
ネットワーク画像の寸法を知る経路が無かった
values.rs の <img> 寸法決定は
src が / 始まり (ローカル
FS)のときしか解決できず、それ以外は既定の
400×200。
デコード完了時に register_image_natural_size で登録し、
レイアウトが拾うようにした。
結果: バッジが正寸(135×40)で描かれるようになった。
再レイアウトのために dom_needs_rebuild を立てたら
is_new_page 扱いになり image_cache
がクリアされ、 届いた画像が捨てられて alt テキストへ戻った。
同じ文書の再レイアウトではフラグを立てないよう修正。
フォント/画像が届いたときの再レイアウトで:
dom_needs_rebuild = true を立てる →
is_new_page 扱いになり image_cache
がクリアされ、 届いた画像が捨てられて無限に取り直しになる
(実測: 同じ画像が 2 回デコード、#projects が alt
テキストのまま)どちらか一方では直らない。
let is_new_page = self.dom_needs_rebuild || self.last_html != html; // DOM 組み直し用
let is_document_changed = self.last_html != html; // キャッシュ破棄用dom_needs_rebuild
でも行う(同じ文書の作り直し)スクロール位置の保持でも同じ判定を使っている(2026-08-03 の修正)。
結果: 画像は各 1 回だけデコードされ、
#projects / #gallery
の画像が表示され、色被りも解消した。
デコードを速くしようとしていたが、その前に内訳を測るべきだった。
[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 で変わらなかった。
当時は間隔(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: 計算が実測とよく一致しても、それは仮説の裏付けにならない。 その仮説から導かれる別の予測(間隔を半分にすれば倍速)を 検証して初めて確かめられる。
キャッシュが機能しておらず、毎回 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 という具体的な理由が決め手になった。
握り潰さずに理由を残しておくと、後から効く。
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:
節からテスト名を取ること。
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 のまま描かれた。
[FONT] 背景取得完了 /css/modern-style.css bytes=49077)external_css_cache と cached_stylesheet
を到着時に捨てるようにしても 直らなかった。原因は未特定。
見た目が壊れたまま残す方が害が大きいので同期へ戻した。 描画が元どおりになることを確認済み。
非同期化は「キューを差し替える」だけでは終わらない。 「初回は CSS 無しで描き、届いたら確実に当て直す」経路を 作り込む必要がある。少なくとも次の 3 点を先に決めること。
external_css_cache / cached_stylesheet /
dom_needs_rebuild の関係)R-6: 性能のための変更が見た目を壊したら、原因究明より先に戻す。 壊れたまま次の調査へ進まない。 今回は測定(レイアウト 30〜164 tick)としては成功だったが、 それは差し戻した後も記録として残せる。
「ページが素の HTML のまま描かれた」として戻したが、 これは撮影が CSS 到着前だっただけ。計装して確かめると
[CSSDIAG] 抽出 ext_len=124813 bridge_src=false
[CSSDIAG] inline_css_len=124813 cache_hit=true rules_before=2403
2403 ルールが正しく当たっており、スタイル付きで描画されることも スクリーンショットで確認できた。見た目 1 枚で原因を決めつけていた。
採用して測り直すと、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
と描画の完全復帰を確認済み。
external_css_cache /
cached_stylesheet を捨てる処理 (render.rs
に実装済み。これ自体は正しく、残してある)[NET][STATS] の
total が普段と桁違いに少ないことを機械的に見るべき)R-7: 見た目 1 枚で原因を決めつけない。 「スタイルが当たっていない」ように見えても、 当たっているのに撮影が早いだけということがある。 計装して中の状態を見てから判断する。
R-8: 依存順序を確かめてから着手する。
非同期化は「キューの優先度制御」が先に要る作業だった。 spec
の実装順序にそう書いてあったのに、後ろから手を付けた。
前節で「実装順序の 4(キューを 1 本に統合し優先度を持たせる)が 非同期化の前提条件だった」と分かったので、その最小実装を入れた。
web_engine/fetch_limit.rs[NET][STATS] total=3 になった直接の原因への対処。判定は純粋関数 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)にした。ここは安全網として置く。
非同期化にはまだ足りない。次は:
[NET][STATS] の total
が普段と桁違いに少ないことを機械的に見る)R-9: 上限値は実測で決める。 「同時接続に弱いから減らす」は方向としては正しくても、 減らしすぎると重いリソースが間に合わなくなる。 両側に失敗モードがある値は、両側を測ってから決める。
| 回 | 症状 | 対処 | 結果 |
|---|---|---|---|
| 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 破棄 |
非同期化したときに必須。同期でも害は無い |
憶測で往復しないために、先に計装を入れてから着手する。
ext_len / rules /
cache_hit を出す (1
回目の誤判定はこれで即座に解けた)[NET][STATS] の total
で機械的に判定する (3 回とも撮影して初めて気付いた)R-10: 同じ変更で 3 回失敗したら、変更をやめて計装を作る。 今回 1 回目は誤判定、2 回目と 3 回目は別の原因で、 そのたびに新しい対処を足していた。 中が見えないまま対処を積むと、直った理由も直らない理由も分からない。
[CSSTRACE] 到着 path=/css/modern-style.css 投入から=987tick ≒ 9.9 秒
[CSSTRACE] 到着による再レイアウト 到着から=626tick ≒ 6.3 秒
投入から反映まで 16 秒。同期版なら最初のレイアウトで揃う。
draw()
の中でしか行われず、 その draw() が 200 秒で 25〜50
回しか回らないため(同期版は 125 回)。| # | 疑ったこと | 実際 |
|---|---|---|
| 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 スレッドが何をしているか)。
それが分かるまで非同期化には手を付けない。
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 { ... }| 送信待ち | 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 回で原因が出た。
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)。
| 修正 | 削減 |
|---|---|
| 送信待ちを実経過で数える | 12191 → 3945 tick(約 82 秒) |
| 無条件 500ms を 6 箇所撤去 | 約 2200 → 23 tick(約 22 秒) |
合わせて約 104 秒。成功率・描画に変化なし。
送信待ちを直したあと、[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 に行き着いた。
分解して引き算が合うまで追うこと。
[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 つ。
まとめ取得を 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。
1 回の実行・1 サイトでは検証として足りないので、繰り返して確かめた。
| 回 | 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
億回台で、しかも回ごとに大きく振れていた。
正しく描画。[FQDIAG] iters=0 spawn=0 exit=0 で、
取得すべき外部リソースが無ければワーカーは起動しない。
空回りしていた頃はここでも回り続けていたはずで、 軽いページでも CPU
を食っていた。
| 修正 | 効果 |
|---|---|
ワーカーの 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 |
| 撮影ハーネスのログ読み | 差分読み。起動失敗を検出して再送 |
7 回目にして配線できた。6
回の失敗の原因は、まとめ取得ではなく
ワーカーの空回り(return
でスレッドが終わらない、R-17)だった。
空回りを直したら、同じ配線がそのまま通った。
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 回とも同じ値。
queue_batch、単体試験 11 件)tls::https_get_binary_keepalive)Content-Length で決めるConnection: close
を返したらそこで打ち切るno_batch
の印を付けて待ち行列へ必ず戻す
(印が無いと同じ便に乗り直して堂々巡りになる)まとめられるのは「同時に待ち行列へ並んでいる同一ホストのもの」だけ。 実サイトではフォント 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 箇所に集約すると誰も再試行しない」 と書いたが、その観測は置換ミスによるものだった(下記参照)。 根拠が無いので取り下げる。
空回りと接続の使い回しを片付けたあと、最大項目は
送信待ち になった。
[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
が出て初めて、削ってはいけない待ちだと分かった。
数えずに削っていれば、パケットロスト時に復旧できなくなっていた。
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 度目の iters=0 も、同じ置換ミスで
「積む側は変わらず、起こす側だけ壊れた」状態だった可能性が高い。
R-19(契機を 1
箇所に集めない)は、この観測からは導けない。
根拠が無いので取り下げる。
R-21: 文字列置換で書き換えたら、
実コードに当たったかを機械的に確かめる
(grep -c で件数を見る、コメント行を除外する)。
コメントに当たっただけでもビルドは通り、
「変えたつもり」で実測して誤った結論を出す。
今回それで存在しない因果(R-19)を 1 つ作ってしまった。
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 便」では頭打ち。
ページ上の Font Awesome アイコンがすべて空の四角になっていた。
[FONT] 解析開始 が Noto 4 本しか出ていない(FA
が 0 本)registered=false[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 件で固定した。とくに
wOF2 が先頭に来ることContent-Length が無い(chunked)なら None
を返すことを回帰として残した。
修正前: [FONT] 解析開始 … Noto 4 本のみ/未知のフォント形式 5 件
修正後: [FONT] 解析開始 … FA 7 本 + Noto 4 本/未知のフォント形式 0 件
画面のアイコンも復帰。
R-22: 「ページが出ている」「成功率が正常」は、
中身が正しいことを意味しない。 今回
total=13 ok=13 のまま、保存内容だけが壊れていた。
バイト列を扱う変更は、先頭数バイトを見る確認を入れる。
まとめ取得で取れなかったぶんを待ち行列へ積み直す処理:
// 誤: 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: 値を「その経路では必ずこうだから」と決め打ちしない。 今回は選定側の条件に依存した決め打ちで、 依存関係がコードに現れていなかった。 元の値をそのまま運ぶのが安全で、しかも短い。
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 が読めなくなる」経路が残っていた。
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 箇所が古いままなら、 「直したはずなのに再発する」ことになる。
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 つ試して、どちらも外れた。
after-resp total= が伸びない → 数 MB
の転送中は何も出ないresolved= と SUCCESS の対応を数える →
接続を使い回すと resolved= が出ない当てるのをやめ、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 段構え。
fetch_limit::claim)。正常終了時に外す(unclaim)。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
を取っていた。
Priority::Lowspin::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 種が壊れる。
data:image/png;base64,... — base64 は /
を含むため split('/') で分解され、..
に見える断片で pop() まで走る。
インライン画像が完全に壊れる。エラーは出ない。#about — /blog/#about
という存在しないパスになり、 同一ページ内リンクが 404 に見える。mailto: / tel: / javascript:
— パスへ埋め込まれる。//cdn.example.com/lib.js(プロトコル相対)—
/ 始まりの
判定に巻き込まれ、現在ホストの絶対パス扱いになる。
url_resolve::resolve_url(CSS
用)・render.rs(画像取得の URL
解決)・js/builtins/static_classlist.rs(JS の
new URL()
相当)はいずれも既にこの型の穴を塞いだ経験があった。
resolve_relative_path
だけが同じ知見を共有していなかった。os_lib/web_engine/rel_path.rs へ切り出し、判定を
「最初の / より前に :
があればスキーム付き」という URL
の一般規則に統一した。個別のスキーム名を並べるより漏れにくい。 試験 20
本(test_rel_path.rs)で契約を固定。
R-35: 「URL/パスを解決する」関数が複数あるとき、 扱えない値の集合が一致しているかを確認する。 同じ知見が別の実装へ伝わっていなければ、直したはずの穴が 別の関数にそのまま残る。