atmos/os_lib/web_engine/
perf.rs

1//! ページ読み込み経路の軽量プロファイラ。
2//!
3//! # なぜ作ったか
4//!
5//! 【2026-08-05】1 箇所ずつ計装しては実機で確かめ、外しては確かめ……を
6//! 繰り返していた。実機 1 回が数分かかるので、これでは終わらない。
7//! **関連する関数に一斉に計測点を置き、1 回の実行で全部見る**ための道具。
8//!
9//! # 使い方
10//!
11//! ```ignore
12//! let t = perf::start();
13//! ...測りたい処理...
14//! perf::add(perf::Slot::TlsHandshake, t);
15//! ```
16//!
17//! 集計は `perf::dump()` が 1 行で出す。
18//!
19//! # 設計
20//!
21//! - 固定スロット（`enum Slot`）と固定長配列。確保しない
22//! - 加算は `AtomicU32` 1 回。ただし `get_ticks()` を **2 回**呼ぶ
23//!   （`start` と `add`）。**熱経路では効く**
24//!   （実測: 1 パケットごとに置いたら受信待ちが 2 倍になった）。
25//!   1 パケット・1 フレーム・1 要素ごとの計測は**調査中だけ**にして、
26//!   目的を果たしたら外し、外した状態で測り直すこと
27//! - tick 単位（10ms）。それより細かい対象には使わない
28//!
29//! 計測点を増やすときは `Slot` に足して `NAMES` にも足す。
30//! 両方を 1 箇所で持つので、名前と実体がずれない。
31
32use core::sync::atomic::{AtomicU32, Ordering};
33
34/// 計測点。増やすときは `NAMES` にも同じ順で足すこと。
35#[derive(Debug, Clone, Copy, PartialEq, Eq)]
36pub enum Slot {
37    /// HTTPS 取得（接続〜本文まで）
38    HttpsGet = 0,
39    /// TLS 送信後の応答待ち（`retry_write` 経路）
40    TlsWriteWait = 1,
41    /// TLS 受信待ち
42    TlsReadWait = 2,
43    /// ディスクキャッシュの読み出し
44    CacheRead = 3,
45    /// ディスクキャッシュの書き込み
46    CacheWrite = 4,
47    /// 外部 CSS/JS の取得（`fetch_script_text`）
48    FetchScript = 5,
49    /// `@font-face` の登録
50    FontFace = 6,
51    /// フォントの解析（WOFF2 展開含む）
52    FontParse = 7,
53    /// 画像のデコード
54    ImageDecode = 8,
55    /// `sleep()` の**実経過**（指定より延びていないかを見る）
56    SleepActual = 9,
57    /// 送信待ちループ内の応答確認（`NET_LOCK` を取る）
58    PeekCheck = 10,
59    /// 送信待ちループ内のイーサネット・ポーリング
60    EthPoll = 11,
61    /// 要求送出後、応答の最初の 1 バイトを待つ時間
62    /// （旧: 無条件 `sleep(50)` が 6 箇所）
63    FirstByte = 12,
64    /// 受信ループの `sleep(1)` の実経過
65    ReadSleep = 13,
66    /// 受信ループの `tcp_recv_real` 呼び出し
67    ReadRecv = 14,
68    /// DNS 名前解決
69    DnsQuery = 15,
70    /// TCP 接続確立（SYN 送出〜Established 待ち）
71    TcpConnect = 16,
72    /// TLS ハンドシェイク
73    TlsHandshake = 17,
74    /// CSS の解析（`parse_css`）
75    CssParse = 18,
76    /// 解析キャッシュの鍵比較（124KB の文字列比較）
77    CssKeyCmp = 19,
78    /// 背景画像の描画
79    PaintBgImage = 20,
80    /// グラデーションの描画
81    PaintGradient = 21,
82    /// `<img>` の描画（object-fit 込み）
83    PaintImg = 22,
84    /// 文字列の描画
85    PaintText = 23,
86    /// 描画前の「必要な画像の収集」パス（URL を複製している）
87    DrawCollect = 24,
88    /// 要素を描く本体ループ
89    DrawElements = 25,
90}
91
92/// スロット数。`Slot` の要素数と一致させる。
93pub const SLOT_COUNT: usize = 26;
94
95/// 表示名。`Slot` と同じ順。
96const NAMES: [&str; SLOT_COUNT] = [
97    "https取得",
98    "送信待ち",
99    "受信待ち",
100    "cache読",
101    "cache書",
102    "css/js取得",
103    "fontface",
104    "font解析",
105    "img復号",
106    "sleep実測",
107    "応答確認",
108    "eth poll",
109    "初回応答待ち",
110    "受信sleep",
111    "recv呼出",
112    "DNS",
113    "TCP接続",
114    "TLS握手",
115    "CSS解析",
116    "鍵比較",
117    "背景画像",
118    "グラデ",
119    "img描画",
120    "文字描画",
121    "画像収集",
122    "要素ループ",
123];
124
125const ZERO: AtomicU32 = AtomicU32::new(0);
126static TICKS: [AtomicU32; SLOT_COUNT] = [ZERO; SLOT_COUNT];
127static CALLS: [AtomicU32; SLOT_COUNT] = [ZERO; SLOT_COUNT];
128
129/// 計測開始。戻り値をそのまま `add` へ渡す。
130#[inline]
131pub fn start() -> usize {
132    crate::kernel::timer::get_ticks()
133}
134
135/// `start()` からの経過を加算する。
136#[inline]
137pub fn add(slot: Slot, started: usize) {
138    let d = crate::kernel::timer::get_ticks().wrapping_sub(started);
139    let i = slot as usize;
140    if i < SLOT_COUNT {
141        TICKS[i].fetch_add(d as u32, Ordering::Relaxed);
142        CALLS[i].fetch_add(1, Ordering::Relaxed);
143    }
144}
145
146/// スコープを抜けるときに自動で加算するガード。
147///
148/// 引数の多い関数をラッパで包むとシグネチャの写経が必要になるので、
149/// **関数の先頭に 1 行置くだけ**で測れるようにする。
150///
151/// ```ignore
152/// fn heavy(...) {
153///     let _g = perf::Guard::new(perf::Slot::PaintText);
154///     ...
155/// }
156/// ```
157pub struct Guard {
158    slot: Slot,
159    started: usize,
160}
161
162impl Guard {
163    pub fn new(slot: Slot) -> Self {
164        Self {
165            slot,
166            started: start(),
167        }
168    }
169}
170
171impl Drop for Guard {
172    fn drop(&mut self) {
173        add(self.slot, self.started);
174    }
175}
176
177/// 集計値を (名前, tick, 回数) で取り出す（試験用にも使う）。
178pub fn snapshot() -> [(&'static str, u32, u32); SLOT_COUNT] {
179    let mut out = [("", 0u32, 0u32); SLOT_COUNT];
180    for i in 0..SLOT_COUNT {
181        out[i] = (
182            NAMES[i],
183            TICKS[i].load(Ordering::Relaxed),
184            CALLS[i].load(Ordering::Relaxed),
185        );
186    }
187    out
188}
189
190/// 全スロットを 1 行で出す。
191///
192/// 呼ぶのは節目だけ（毎フレームは出さない。`spec/logging_policy.md` L-3）。
193pub fn dump(tag: &str) {
194    let s = snapshot();
195    crate::warn!(
196        "[PERF][ALL] {} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{}",
197        tag,
198        s[0].0, s[0].1, s[0].2,
199        s[1].0, s[1].1, s[1].2,
200        s[2].0, s[2].1, s[2].2,
201        s[3].0, s[3].1, s[3].2,
202        s[4].0, s[4].1, s[4].2,
203        s[5].0, s[5].1, s[5].2,
204        s[6].0, s[6].1, s[6].2,
205        s[7].0, s[7].1, s[7].2,
206        s[8].0, s[8].1, s[8].2,
207    );
208    crate::warn!(
209        "[PERF][ALL2] {} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{}",
210        tag,
211        s[9].0, s[9].1, s[9].2,
212        s[10].0, s[10].1, s[10].2,
213        s[11].0, s[11].1, s[11].2,
214        s[12].0, s[12].1, s[12].2,
215        s[13].0, s[13].1, s[13].2,
216        s[14].0, s[14].1, s[14].2,
217    );
218    crate::warn!(
219        "[PERF][ALL3] {} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{}",
220        tag,
221        s[15].0, s[15].1, s[15].2,
222        s[16].0, s[16].1, s[16].2,
223        s[17].0, s[17].1, s[17].2,
224        s[18].0, s[18].1, s[18].2,
225        s[19].0, s[19].1, s[19].2,
226    );
227    // 【2026-08-05】`送信待ち` の内訳はほぼ `sleep` だが、
228    // これは「応答が来ないなら再送する」ための待ち。
229    // **実際に再送が起きているか**が分からないと、
230    // この待ちが要るのか捨てられるのか判断できない。
231    // 【2026-08-05】送信再送が 36 回中 44 回と多い。
232    // 送った側の問題か、受け取れていないのかを分けるため、
233    // 受信側の集計（採用／破棄セグメント、RX フレーム）も同じ行で出す。
234    // 別々に出すと突き合わせに実機をもう 1 回回すことになる。
235    crate::warn!(
236        "[PERF][ALL4] {} 送信再送={} seg採用={} seg破棄={} RXフレーム={}",
237        tag,
238        crate::kernel::tls::WRITE_RETX_COUNT.load(core::sync::atomic::Ordering::Relaxed),
239        crate::kernel::net::tcp::SEG_ACCEPTED.load(core::sync::atomic::Ordering::Relaxed),
240        crate::kernel::net::tcp::SEG_DROPPED.load(core::sync::atomic::Ordering::Relaxed),
241        crate::kernel::usb::RX_FRAME_COUNT.load(core::sync::atomic::Ordering::Relaxed),
242    );
243    crate::warn!(
244        "[PERF][PAINT] {} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{} {}={}/{}",
245        tag,
246        s[20].0, s[20].1, s[20].2,
247        s[21].0, s[21].1, s[21].2,
248        s[22].0, s[22].1, s[22].2,
249        s[23].0, s[23].1, s[23].2,
250        s[24].0, s[24].1, s[24].2,
251        s[25].0, s[25].1, s[25].2,
252    );
253    // 【2026-08-05】`[PERF][PAINT2]` は撤去した（L-13）。
254    //
255    // `draw_helpers` と `kernel/draw.rs` が持っていた 1 呼び出しごとの
256    // 計測（`TickTimer` / `AccTimer`）を外したので、この行は常に 0 を出す。
257    // 0 しか出ない行は、読む人に「描画コストが無い」と誤解させる。
258    //
259    // 撤去しても描画は 154 → 151 tick/frame で有意差なし
260    // （原始操作は元々軽く、per-packet の計測とは事情が違った）。
261}
atmos/os_lib/web_engine/perf.rs

atmos/os_lib/web_engine/
perf.rs
