松田研究室
FindingID: phase5-step30-profile
Status: stable / task #5.30
← Findings Index
Phase 5 · step 30 profile

Phase 5 step 30 — Instruments / Metal System Trace 分析結果

30s recording で 14,909 encoder / iter 約 40 encoder を観測。当初は STIME 70% = sync overhead と解釈したが、B-mini プロト (scatter wait_until_completed 削除) で iter 速度が < 1% しか変わらず仮説撤回。真の time breakdown は GPU compute ~70% / CPU encoding ~30%、fusion ROI は小さい。

mixedrank: midinvestigative第 3 軸phase-5step-30instrumentsmetal-system-tracem4-maxprofilingfusion-reject
Δ Wallclock
B-mini: -1% (noise floor)
Impact
30s Metal System Trace で 14,909 encoder / iter 40 encoder を観測。当初の「STIME 70% = sync overhead」解釈は B-mini プロト (scatter wait 削除、< 1% 改善) で撤回。真の breakdown は GPU compute ~70% / CPU encoding ~30%、dispatch fusion ROI は小さく Phase 4 後続 (C/D/F) 進行に戻る判断。
01

本文

Phase 5 step 30 で M4 Max 上の 30s Metal System Trace を取得 (646MB bundle)。1 iter で約 40 個の Metal encoder を作成、CPU 時間の 70% が syscall (mach_msg_trap)。当初は「dispatch sync が dominant な遅さの主因」と判断し step 31.5 軽量 fusion を推奨したが、B-mini プロト (scatter wait_until_completed 削除) で iter 速度がほぼ変わらず (< 1% 改善) → 解釈の誤りを発見。

取得
2026-04-30 08:22:11 〜 08:22:42 (30.9 sec recording)
設定
F config + L1+SSIM (λ=0.20)、500 iter で起動 (--time-limit で 30s で停止)
Trace bundle
3dgs-rs/runs/phase5-step30/profile-30s-lam0.20.trace (646MB、gitignored、local 保管)
Hardware
M4 Max、macOS 26.3.1

主要数値

指標補足
取得 iter 数~37530s ÷ 80ms/iter
総 encoder 数14,909metal-application-encoders-list table
encoders/iter~40これが想定外に多い
Trace bundle サイズ646MBfinalize 後 (raw 3.5GB → 圧縮)
GPU execution points520,546個別 GPU event (詳細すぎ、集計困難)
CPU samples (timer fired)10,7771ms 周期、Running 時のみ捕捉

補足: 事前 ps 診断 (28-C-1 sweep 中の lam0.10 process)

指標含意
%CPU47.9%単スレッド換算で 0.5 core 程度
UTIME (user time)1:13.56Rust app 自身の計算
STIME (system time)2:41.94kernel/syscall = mach_msg_trap (wait_until_completed)
STIME / (UTIME + STIME)70%CPU 時間の 7 割が GPU 同期待ち (初期解釈、後に撤回)
Wall time746slam0.10 全 10k iter
総 CPU time / Wall time31.5%残 68.5% は GPU active or 全体 idle

解釈 (初版)

確定した事実

  1. 1 iter で約 40 個の Metal encoder を作成 — 想定 (10 commit × ~3 encoder) を大幅超過。各 encoder は別々の commit() + wait_until_completed() cycle を伴う
  2. CPU 時間の 70% が syscall (STIME)mach_msg_trap 経由の wait_until_completed() が dominant、Rust user code は CPU 時間の 30% のみ
  3. wall time 全体の ~22% が syscall に消えている — 31.5% × 70% = 22%、80ms/iter のうち ~17.6ms が syscall overhead (初期推論、後に誤りと判明)

推定 (初版、後に撤回)

  • 残 78ms/iter の内訳は CLI ツール (Instruments.app GUI) なしには直接見えない
  • 14k 個の encoder と 70% syscall 率から、dispatch sync が dominant な遅さの主因 と判断
  • step 32 (MTLIndirectCommandBuffer) で 40 dispatch を 1 commit に統合 → syscall overhead 17.6ms → ~2-3ms、期待 iter 速度 80ms → 40-50ms (1.6-2× 高速化)
  • step 33-35 まで進めば 15-20ms/iter まで下がる見込

B (step 31.5 軽量 fusion) vs full step 32

step 31.5 (1 iter 1 commit にする、IndirectCommandBuffer なし、共有 cmd buffer 引数化): 工数 2-3 日、期待 iter 速度 80ms → 40-50ms (step 32 と同等の効果)、ICB なしでも cmd buffer fusion だけで主要効果は得られる、と推定。

full step 32 (ICB + 動的 dispatch chain): 工数 1 週間、期待 iter 速度は step 31.5 と同程度、ただし dynamic refine やスケール時にメリット。現状の固定 iter loop なら step 31.5 で十分、と推定 (後に B-mini で撤回)。

次の判断 (Step 7、初版)

選択肢 B (step 31.5 軽量 fusion) を推奨。理由:

  1. 期待効果が full step 32 とほぼ同じ
  2. 工数 2-3 日 vs 1 週間
  3. Phase 4 後続 D/F の sweep 時間が大幅短縮 (28-C-1 60 min → 12-15 min 想定)
  4. dev 体験の質的向上が dev velocity に効く

ただし以下は事前確認が必要: gradient check が fusion 後も全 pass する保証、ssim.rs の独立 cmd buffer use case (training context 外) を残す設計、run-time impact: H baseline (22.42 dB) を fusion 後に再走させて bit-identical 検証 (atomic 順序変化で ±ULP は許容)。

Instruments.app GUI 分析 (推奨追加 step)

CLI 抽出ではカバー仕切れない情報: CPU/GPU 同時タイムライン (どこで GPU が idle 待ちか)、mach_msg_trap の callstack (どの Rust 関数が wait してるか)、per-encoder GPU 実行時間ヒストグラム、thermal throttling 時刻と GPU clock 推移。open runs/phase5-step30/profile-30s-lam0.20.trace で Instruments.app に開いて視覚分析推奨。所要 15-30 分。

実験結果と解釈の訂正 (2026-04-30 追記)

実験: scatter wait_until_completed 削除 (B-mini プロト)

gpu_tile.rs::radix_sortbuf_shift を 16 個独立 buffer に分離 (race 回避)、中間 pass の scatter wait_until_completed を削除、最終 pass のみ残す。同 queue 内 cmd buffer は GPU 上で順次実行されるため、論理的には wait 不要。

結果: iter 速度ほぼ変わらず

下表のとおり改善幅 < 1%、noise floor (±0.3 ms) 内。unit test 7/7 全 pass。

iterpre-fusionpost-fusion
20073.3 ms72.2 ms-1.1 ms
50064.5 ms63.7 ms-0.8 ms
80060.3 ms60.4 ms+0.1 ms
100061.6 ms63.1 ms+1.5 ms

解釈の修正

過去の解釈には 2 つの誤りがあった:

誤解 1: wait_until_completed 削除 = sync overhead 削減

実際: 同 queue 内 cmd buffer は既に GPU 上で順次実行されている。wait_until_completed は CPU 側の観測ポイントを変えるだけで、GPU 待ち時間自体は短縮しない。次 cmd buffer の wait で結局 GPU 完了を待つことになる。

誤解 2: STIME 70% = 節約可能な sync overhead

実際: STIME は CPU が kernel mode で実行してる時間 (encoding, mach IPC processing)。CPU が wait_until_completed で blocked してる時間は STIME に 入らない (Blocked state)。「22% wall time = 同期 overhead」は誤った推論。

真の time breakdown (再評価)

80ms/iter の内訳:

  • ~55ms (~70%) = GPU compute ← CPU は blocked、GPU が物理的に計算
  • ~25ms (~30%) = CPU 側 encoding + buffer mapping + IPC processing

fusion で削れるのは 25ms 内のごく一部のみ。GPU compute 部分は kernel-level 最適化が必要。

結論: B-mini ROI ゼロ、A (Phase 4 後続続行) に戻る

dispatch 系の最適化は GPU compute bottleneck の状況では効かない。後続の path:

  • A に戻り Phase 4 後続 C/D/F を進める ← 採択
  • 本格 Phase 5 着手時は Shader Timeline 有効で再 profile → kernel-level hot path 特定 → 個別最適化 (atomic 削減、SIMD reduction 等)
  • step 31.5 の fusion 案は future work または step 32 (ICB) の前段としてのみ価値

コード状態

gpu_tile.rs の変更 (buf_shift 16 buffer 化 + scatter wait 部分削除) は commit 済: 正しさは保たれている (unit test 7/7 pass)、速度向上は微小だが、コードはより明示的になった (race 回避策が文書化されている)、後の最適化作業で base point として再利用可能。

Lesson

Profile 数値の解釈は実験で裏取りすること。STIME ≠ GPU 同期待ち、wait_until_completed 削除 ≠ sync overhead 削減。kernel-level の per-call timing (step 30b) が必要 → step 30b でその場で rasterize_backwards 24ms/call が dominant と判明する流れに繋がる。

© 2026 大竹律輝 — 松田研究室