対象実装: arm/v1/src/kernel/usb.rs(3017 行・34
関数)ほか 典拠: USB 2.0 §8.5 / §8.6、RNDIS 仕様 §5.1、DWC2 の HCINT
定義
ユーザから当初より「OSI レイヤーを L1 から全部単体試験して確認すべき。 下層ほどきちんと保証しなければ、上層でエラーが出ても分からない」と 指摘されていた。しかし実際に作った単体試験は L7(CSS/HTML/JS) と L4(TCP/UDP) に偏り、L1/L2 はゼロだった。
そして真因はそこにあった。「DNS のバグ」「TCP のバグ」「受信打ち切り」として 別々に追っていた 3 つの症状は、すべて L1/L2 の同一欠陥の現れだった。 TCP の輻輳制御(RFC 5681)を実装しようとしていたのは、 フレームが 1 枚も届いていない状態での作業だった。
| モジュール | 試験 | 保証内容 |
|---|---|---|
kernel/usb_rx_state.rs |
16 件 | 受信チャネルの状態遷移。NAK での再アーム、永久待機の防止、異常停止の分類 |
kernel/usb_toggle.rs |
14 件 | データトグル(USB 2.0 §8.6)。ACK のみ前進、NAK/エラーで据え置き、STALL で DATA0 復帰、複数パケットの偶奇 |
kernel/usb_rndis.rs |
12 件 | RNDIS/CDC-ECM
のフレーム抽出。DataOffset + 8、範囲外・加算オーバーフロー・14
バイト未満の拒否 |
kernel/usb_txn.rs |
12 件 | 送信トランザクションの判定。完了優先、STALL は再試行しない、NAK はエラーではない、失敗を成功扱いしない |
合計 54 件。いずれもレジスタ値・バイト列だけから結論を出す純粋関数で、 ホスト上で実行できる(実機不要)。
(1) NAK でチャネルが張り付き、受信が永久停止
HCCHAR=0x80b89040 HCINT=0x00000010 ← CHENA=1、NAK のみ
旧実装は if (hcchar & CHENA) != 0 { return; }
と無条件に関数を抜けており、
この状態から永久に復帰できなかった。ints
のチェックにも到達しないため
エラーログすら出ない。実機のこのレジスタ値をテストケースとして固定済み。
(2) NAK を「異常停止」に誤分類 CHENA が落ちた後も
HCINT=0x10(NAK のみ)で戻る経路があり、 異常扱いして
21504 回エラーログを出していた。
(3) トグル計算・RNDIS 範囲計算がインライン 検証不能だった。全 4 箇所を検証済みモジュールへ一本化(インライン計算 0 件)。
net.netbench
による実測)| 段階 | 受信フレーム数の推移 | 連続取得 |
|---|---|---|
| L1/L2 未検証 | 14, 14, 14, 14(完全停止) | 1 回目のみ |
| (1) 修正 | 17, 18, 20, 20 | ほぼ変わらず |
| (2) 修正 | 106, 108, 109, 110 | 1 回目のみ |
| (3) 一本化 | 125, 241, 300 | 3 回連続成功(各 49077 バイト、Content-Length と完全一致) |
この状態で https://www.sugi-lab.net/
がネットワーク経由でスタイル付き表示に到達した。
usb_transfer の判定を usb_txn::classify
の規則と突き合わせた: - 転送完了 → Ok ✓ - NAK →
再試行へ落ちる ✓(失敗扱いしていない) - STALL →
Err(再試行しない)✓ - チャネル停止でエラー →
Err(成功扱いしない)✓
受信側で踏んだ欠陥と同種の誤りは送信側には無かった。
usb_transfer は制御フローが複雑なため
classify() への配線は見送り、
規則の明文化と試験による保証に留めた(違反が入れば試験で検出できる)。
usb.rs は 3017 行あり、以下はまだ単体試験が無い:
is_split)—
ハブ経由の Low/Full speed 機器次はこの順で、規格 → 仕様書 → 純粋モジュール → 単体試験 → 配線 で進める。
net.netbench("https://www.sugi-lab.net/css/modern-style.css", 20):
total=22 ok=1 dns_fail=17 connect_fail=0 handshake_fail=0 truncated=4
17/20 FAILED dns response timeout
18/20 FAILED dns response timeout
19/20 FAILED dns response timeout
connect_fail=0 /
handshake_fail=0 … TCP 接続もハンドシェイクも
20 試行で一度も失敗していない。「TCP
が悪い」線は完全に消えたtruncated=4 … 受信打ち切りは残るが少数1 回目付近だけ成功し以降 DNS が通らなくなる形は、 L1/L2 修正前に観測された劣化パターンと同じ形。 USB 受信の永久停止は直ったが、DNS 応答だけが届かなくなる現象が残っている。
VLAN 対応(eth_frame 導入)の前後で - 変更前: 5 試行中
ok=3 (60%) - 変更後: 9 試行中 ok=2 (22%) と悪化して見えたが、20
試行では別の分布になった。
このネットワークは実行ごとの変動が支配的で、数試行では効果を判定できない。
VLAN 対応と境界チェックは規格上正しい修正(IEEE
802.1Q・範囲外読み防止)で 単体試験 13
件で契約を固定しているため、悪化の証拠不十分として残した。
eth_frame::dispatch
の結果(Ipv4/Arp/Unsupported/エラー)を種別ごとに数え、
「フレームは来ているが IPv4 として振り分けられていない」のか
「そもそもフレームが来ていない」のかを確定させるtruncated=4 は DNS
が通るようになってから再評価するeth_frame::dispatch の結果を種別ごとに数えた:
[NETBENCH][RES] before=6 rx_frames=130 eth(ipv4/arp/other/err)=(127, 3, 0, 0)
[NETBENCH][RES] before=7 rx_frames=131 eth(ipv4/arp/other/err)=(128, 3, 0, 0)
[NETBENCH][RES] before=8 rx_frames=131 eth(ipv4/arp/other/err)=(128, 3, 0, 0)
(この間 5/8〜8/8 はすべて dns response timeout)
other=0 / err=0 …
振り分けの取りこぼしはゼロ。 未対応 EtherType
として捨てたフレームも、長さ不良で弾いたフレームも無い。 L2
の解析は正常。ipv4 が 127→128 でほぼ止まる … DNS
応答フレームが そもそも NIC に届いていない。→ 残る問題は L2/L3 の解析ではなく、L1(USB 受信)か環境(QEMU SLIRP)。 今日修正した L1/L2 の解析経路は、この件については健全と確認できた。
次の手: 1.
送信は成功している([NET][DNSSEND] sent_ok
で確認済み)ので、 「送ったのに応答が返らない」状態。ホスト側は
nslookup で正常だった。 2. USB
受信は完全停止こそ直ったが、流量が細る現象が残る
(rx_frames が 1 回目で 130
まで伸びた後、以降ほぼ増えない)。 L1 の未保証領域(DMA
バッファ管理・チャネル割り当て・USB 列挙)を 同じ手順で潰していく。 3.
併せて -netdev user(SLIRP)以外の netdev
で同じ測定を行い、 環境要因かどうかを確定させる(Makefile に
run-vmnet-shared がある)。
受信ポーリングは Core 2 が
sleep(10)(100ms)間隔で呼び、 1 回あたり 8
フレームしか回収しない。毎秒 80 フレーム(1500B 換算で約 120KB/s)が
理論上限で、これが DNS 応答や 49KB の CSS
取得を阻害していると考えた。
回収上限 8→64、間隔 100ms→20ms に変更 → 実機で 8/8 全滅 (それまでは 1〜3 回成功していた)。ただちに元へ戻した。
[NETBENCH] 1..3/8 FAILED tcp connect timeout
[NETBENCH] 4..8/8 FAILED dns response timeout
netbench-done total=5 ok=0 dns_fail=5 connect_fail=0 handshake_fail=0 truncated=0
教訓:
「理論上限が低い」ことは「そこがボトルネック」を意味しない。
ポーリングを詰めると USB
レジスタアクセスが増え、かえって転送を阻害するとみられる。
再挑戦するなら間隔と回収数を片方ずつ変えて測ること。
計算式 frames_per_second と試験は残したが、実装は 8 / 100ms
のまま。
DWC2 の共有レジスタ・DMA バッファ・RX_IN_FLIGHT 等の
static mut は 2 つのコアから触られていた:
- Core 1: poll()(HID)… USB_LOCK を取っていた
- Core 2: poll_ethernet_data_plane_only()(ネットワーク)…
ロックを取っていなかった
両者が同じ関数 poll_usb_ethernet_data_plane() を呼ぶが、
ネットワーク側だけ排他なしで共有レジスタを同時操作していた。
poll_ethernet_data_plane_only() も USB_LOCK
で保護しただけで:
netbench-done total=8 ok=8 dns_fail=0 connect_fail=0 handshake_fail=0 truncated=0
8 試行すべて成功。DNS 失敗・TCP 接続失敗・受信打ち切りがすべてゼロ。
net.netbench)| 段階 | 結果 |
|---|---|
| L1/L2 未検証 | 受信が完全停止(14 フレームで固着) |
| NAK 処理修正 | 1〜3 回成功 |
| VLAN 対応 | 変動大(22〜60%) |
| ポーリング高速化 | 全滅(戻した) |
| USB_LOCK 追加 | 8/8 成功(100%) |
セッション前半、TCP の輻輳制御(RFC 5681)・RTO(RFC 6298)・DNS 再送を 実装しようとしていたが、実際の原因は L1 の 2 点だけだった: 1. NAK でチャネルが張り付き受信が永久停止(+ NAK の異常誤分類) 2. コア間の排他制御の欠落
下層を保証せずに上層を追いかけると、存在しないバグを追い続けることになる。
ネットワークは 5/5 成功するようになったが、 実サイト表示は「Loading Secure Page…」のままになる実行がある。 取得が速くなった分、レイアウト側が追いつかなくなった可能性があるが 未確認。次はここを切り分ける。
USB_LOCK 追加後、ネットワークは 5/5
成功するようになったが、 実サイト表示が「Loading Secure
Page…」のままになる。
当初「ロック待ちで GUI が止まった」と考えて
try_lock に変えたが、症状は変わらず。
この見立ては誤りだった。
実際のログ:
[NET] BROWSER: Load page SUCCESS. body_len=12597 ← HTML は取得済み
[WM][FRAME] present_frame=1216 ← 描画ループは動いている
https_get_binary ordinal=4 SUCCESS body_bytes=5328547 ← 5.3MB のフォント
https_get_binary ordinal=5 SUCCESS body_bytes=102065 ← Font Awesome webfont
→ 退行ではない。 以前はフォント取得が失敗していたので先へ進めていた。 通信が健全になったことで 5.3MB の Noto Sans JP を実際にダウンロード・処理 するようになり、その完了を待っている。
font-display: swap 相当)font-display: swap
を指定しているので、
仕様どおりならフォールバックで即描画すべき。まず仕様を確認すること。tick(10ms 刻み)では 1 回数 ms の処理は測れない。 毎回 0
と数えられ、合計しても出てこない (実際 hid_ticks=0
という誤った結論を一度出した)。 CNTPCT 由来の
get_system_time_us() を使うこと。
hid_calls=2246 hid_eth_us=18641424 hid_us=0
eth_calls=339 eth_us=2724875 eth_lockmiss=210
frames=13873
| 項目 | 値 |
|---|---|
| Ethernet 収穫の合計時間 | 21.3 秒 = 全体の 50% |
うち Core 1 の poll() |
18.6 秒(87%) |
| うち Core 2 の専用スレッド | 2.7 秒 |
| HID 転送そのもの | ほぼ 0 |
| 1 回の収穫 | 約 8ms |
| 1 フレームあたり | 約 1.4ms |
役割分担が実態と食い違っている。
net_service_thread(Core
2)が受信の専用スレッドのはずだが、 実際には HID 担当の
usb_poll_thread(Core 1)が受信の 87% を担っている。 Core 1
はスリープ無しのループなので、結果的に最も安定した受信ドライバに
なっている。
| 案 | 結果 |
|---|---|
| 受信ウィンドウ 8192 → 32768 | 効果なし |
TLS 受信の待ちを yield で詰める |
効果なし |
| 1 ポールの回収数 8 → 32 | 2.3 倍悪化 |
| ポーリング間隔 100ms → 50ms | 効果なし |
USB_LOCK を粘って取る(取りこぼし 210→5) |
取得時間は改善せず |
| 受信を Core 2 へ一本化(Core 1 から外す) | 200 秒で完了せず(致命的に悪化) |
外側の調整では動かない。1 フレーム 1.4ms の中身を削るしかない。
poll_usb_ethernet_data_plane の収穫 1 回で行っている: -
hc_char/hc_int/hc_tsiz の読み出し
- invalidate_dcache_range(1600 バイト) - 再アームの MMIO
書き込み 4 回 - RNDIS ヘッダ解析と nic_rx_frame
への引き渡し
このどれが 1.4ms を占めるかはまだ測っていない。
get_system_time_us() で区間ごとに分けて測ることから始める。
測らずに触ると、この表にもう 1 行増えるだけになる。
U-1: 「専用スレッドがあるから、そこが仕事をしている」と仮定しない。 実測では 87% を別のスレッドが担っていた。
U-2: 動いている構造を役割の見た目に合わせて整理しない。 一本化は理屈は通っていたが、実測では致命的に悪化した。
前節では外側ばかり触って動かなかった。記録どおり 収穫 1 回を区間に分けて測ったところ、本命が出た。
get_system_time_us で計測)sec_frame_us=11248623/13516 ← フレーム処理 11.2 秒(1 フレーム 832µs)
└ sec_ingest_us=10671800 ← うち 10.7 秒(95%)が IP/TCP 解析
sec_arm_us=2066022/14500 ← 再アーム 2.1 秒
sec_inv_us=219094 ← dcache 無効化 0.2 秒
フレーム処理が支配的で、そのほぼ全部がネットワークスタックの中だった。
parse_tcp_ipv4_packet:
let mut s = super::TCP_SOCKETS[idx].clone(); // ← ここ
...
super::TCP_SOCKETS[idx] = s; // ← 書き戻しTcpSocket は rx_buffer: Vec<u8>
を内包する。 セグメントが 1
個届くたびに受信バッファ全体を複製していた。
バッファは読み手が引き取るまで育つので、 「溜まっているほど 1
セグメントが高くつく」という二次的な悪化。
その場で書き換えれば複製は要らない(O(受信バッファ長) → O(1))。
| 箇所 | 内容 |
|---|---|
nic_take_tx_ipv4_chunk |
let e = NIC_TX_QUEUE[i]; が 1552 バイトを値コピー。64
要素で1 走査 99KB。収穫のたびに通る。参照に変更 |
tcp_recv_real |
rx_buffer.clone() してから
clear()。渡すだけなので core::mem::take
に変更 |
transmit_nic_ipv4_packet |
1536 バイトのスタックバッファ 2 個をゼロ初期化して 2 回コピー。キューのスロットへ直接組み立てるよう変更 |
修正前 修正後
sec_ingest_us 10.67 秒 → 5.02 秒 (1 フレーム 789µs → 360µs)
収穫の合計 25.5 秒 → 16.2 秒
CPU 仕事量で 2.1 倍。取得の実時間は 修正前 平均 4256tick(7 サンプル)→ 修正後 平均 3731tick(3 サンプル)。 QEMU の実時間は振れが大きいので、確かなのは区間計測の方。
成功率は 13/13・truncated=0 で変化なし。単体試験 844 件パス。
| 案 | 結果 |
|---|---|
| 送信キューへ直接組み立て | sec_ingest
変化なし(ただし操作は確実に減るので採用) |
NET_LOCK を取らずに済ませる印(AtomicBool) |
5.02 → 5.17 秒で変化なし。新しい同期機構は入れないので戻した |
U-3: 「重い関数」が分かっても、その中を区間に割るまで手を出さない。 外側(ウィンドウ・間隔・回収数・ロック取得)を 6 案試して全部外し、 区間を割った 1 回で本命に当たった。
U-4: 大きな配列や Vec
を内包する構造体の clone() / 値コピー / 添字代入を疑う。
今回の本命 3 件はすべてこの形だった。 let e = ARRAY[i];
は型を見ないと копия だと気付けない。
| 箇所 | 内容 |
|---|---|
build_tcp_ack_packet |
TCP_SOCKETS[idx].clone()。ポート・IP・シーケンス番号の
5 つを読むためだけに受信バッファごと複製。ACK
ごと=全受信セグメントで走っていた → 参照へ |
nic_take_tx_ipv4_chunk |
空きにするのに = NicTxEntry::empty() で 1552
バイトをゼロ埋め → valid を下ろすだけへ |
| 計装そのもの | get_system_time_us は除算を含み、1 パケット 6
回呼んでいた。目的を果たしたので撤去(L-4) |
fetch=2146tick sec_frame_us=776211/10374 (1 フレーム 75µs)
fetch=3252tick sec_frame_us=2174559/13188 (1 フレーム 165µs)
| 指標 | 開始時 | 最終 |
|---|---|---|
| フレーム処理 1 回 | 832µs | 75〜165µs |
sec_frame_us 合計 |
11.2 秒 | 0.78〜2.17 秒 |
hid_eth_us |
22.6 秒 | 5.1〜9.6 秒 |
fetch(実時間) |
平均 4256 tick(7 サンプル) | 2146 / 3252 tick |
成功率 13/13・truncated=0、単体試験 844 件パス、描画に回帰なし。
| 案 | 結果 |
|---|---|
take
ではなく容量を引き継ぐ(with_capacity) |
tcp_proc_us 3.66 → 36.2 秒(10
倍悪化)。読むたびに最大 64KB
を先行確保するとヒープが荒れて確保自体が重くなる。先行確保は空振りが多いと逆効果 |
U-5:
計装は熱経路ではそれ自体がコストになる。
get_system_time_us の除算を 1 パケット 6 回呼んでいた。
目的を果たしたら必ず外し、外した状態で最終値を取り直すこと。
U-6:
同じ形の欠陥は同じファイルの別の場所にもある。
TCP_SOCKETS[idx].clone() は受信処理と ACK 組み立ての 2
箇所にあった。 1 つ見つけたら、同じ型の同じ操作を全部探すこと。
QEMU では MMIO アクセスが 1 回ごとにトラップするため、 収穫ループ内の重複は素直に効く。2 箇所あった。
| 箇所 | 内容 |
|---|---|
| 収穫時 | hc_tsiz(3) を2
回読んでいた(残バイト数と Data Toggle 用
PID)。同じレジスタなので 1 回読んで使い回す。フレーム 1 個につき 1
回の往復を削減(1 ブートで 13000 回以上) |
| 再アーム時 | hc_int のクリアを2
回書いていた。Rearm
判定の直後と、その後必ず通る再アーム処理の中。NAK
は正常応答で頻繁に通る経路 |
fetch = 4913 / 4512 tick(同じ回の decode は 1114 / 1754 tick)
decode(この変更と無関係)も普段の 835 tick から倍近く伸びており、 ホスト負荷が高い回だった。前後で有意差は出せていない。
削ったのは重複そのものなので実行される命令は確実に減っているが、
「速くなった」と数字で主張はしない(spec/complexity_annotation.md
C-2)。
RX_LEN を増やして 1
転送に複数フレームを詰める案を検討したが、 RNDIS の解析が 1 転送
1 メッセージしか見ていないため、
先に解析側をループ化しないとデータを取りこぼす。 さらに QEMU の usb-net
が実際にバッチ送信するかも未確認。
受信経路は「受信が恒久的に停止する」不具合を何度も出した場所なので、
効果が不明なまま触らない。やるなら「複数メッセージが来ているか」を
数えてから。
前節で「やるなら『複数メッセージが来ているか』を数えてから」と書いた。 数えた。
frames=13968 rndis_extra=0
1 転送に 2 個目以降の RNDIS メッセージが入っていた回数は 0 件。
結論は 2 つ。
RX_LEN を増やして 1
転送に複数詰める案は効果が無い (QEMU の usb-net が 1
転送 1 フレームしか送らないため)この案は打ち切る。実機(Raspberry Pi 3B+ + 実 USB NIC)で バッチ送信するデバイスを使う場合は再検討の余地があるが、 そのときも先に数えてから。
収穫 1 回の内訳計装(sec_frame_us
等)は目的を果たしたので撤去した(L-4)。 とくに
sec_frame_us は
get_system_time_us(除算を含む)を フレームごとに 2
回呼ぶため、約 28,000 回の除算を熱経路に置いていた(U-5)。
残したのは呼び出し単位の軽い計数のみ (ETH_POLL_CALLS /
ETH_POLL_LOCK_MISS / HID_POLL_CALLS /
RX_FRAME_COUNT / eth_us /
hid_eth_us)。
| 指標 | 開始時 | 最終 |
|---|---|---|
| フレーム処理 1 枚 | 832µs | 75〜165µs |
fetch(3.7MB 画像) |
平均 4256 tick | 1878〜3757 tick |
残りの内訳はおおよそ「ネットワーク待ち 5 割・収穫 3 割・デコード 2
割」。 収穫側は測れる範囲でやり切った。次に大きく効かせるなら
デコードの縮小(DCT スケーリング)だが、zune-jpeg 0.4 に
API が無く、 自前実装は規模が見合わない。
送信再送 が 36 回の送信に対し 44〜48 回と多い。 削れるか
3 方向から調べ、いずれも改善しなかった。
seg採用=19907 seg破棄=39 RXフレーム=20198
破棄は 0.2% しかない。取りこぼしが主因ではない。
MAX_SEGMENTS を 16 → 32 に倍増。
16: seg採用=19907 seg破棄=39 送信再送=48
32: seg採用=20395 seg破棄=35 送信再送=44
誤差範囲。 メモリを倍にする理由が無いので 16 のまま。
WAIT_PER_TRY を 600ms → 200ms。
600ms: 送信待ち=3173/36 送信再送=48 seg破棄=39
200ms: 送信待ち=3201/36 送信再送=44 seg破棄=1066
時間は変わらないのに破棄セグメントが 27 倍。 早すぎる再送が相手に重複送信させ、それを捨てているだけ。 帯域を無駄にして何も得ていない。
長くしても(1.5 秒で試験済み)短くしても改善しないので、 600ms が妥当。
送信待ち の約 3200 tick は現状の構造では削れない。
失われているのはこちらから出ていく側とみられ、
受信経路・バッファ・待ち時間のどれをいじっても変わらない。
次に見るなら送信経路(arp::transmit_nic_ipv4_packet から
USB へ出るまで)。ただし本命は spec/TODO.md の
「同時接続に弱い」構造そのもの。
U-7: 片側(受信)を疑って直らないなら、反対側(送信)を見る。 今回 3 方向とも受信側・待ち側で、送信経路を一度も測っていない。
送信再送=44 seg採用=19873 seg破棄=34
RXフレーム=20140 TX成功=40068 TX失敗=0
nic tx queue FULL)… 0
件TX失敗)… 0 件こちらの装置からは 4 万フレームすべて出ている。
| 区間 | 実測 | 判定 |
|---|---|---|
| 受信の破棄 | 34/19873(0.2%) | 主因でない |
| 順序外バッファ | 16→32 で変化なし | 主因でない |
| 再送閾値 | 長くしても短くしても悪化/不変 | 妥当 |
| 送信キュー | 溢れ 0 件 | 主因でない |
| USB 送信 | 失敗 0 件 | 主因でない |
AtmOS 側のどこにも取りこぼしが無い。 失われているのは装置の外(QEMU の slirp、または経路上)。
送信再送=44 はこの環境で避けられない。
実機(Raspberry Pi 3B+ + 実 NIC)では別の数字になる可能性が高い。
送信待ち の約 3200 tick はその保険として必要。
これ以上はネットワーク側では削れない。 削るなら往復の回数そのもの(接続の使い回しは実施済みで ハンドシェイク 14 → 12)。
U-8: 「どこで失われているか」は、 全区間に数を置いて引き算するのが最短。 今回 5 区間を測って全部 0 に近く、 「自分の側では失っていない」と確定できた。 1 区間ずつ推測して直す進め方では、 ここまで来るのに何倍もかかっていた。