链路时延M1-M3收尾:Phase12-14基线与生产路径Δ实测、D10/E-02/D17修复、D20定位与硬化、文档整理

This commit is contained in:
2026-09-22 06:12:16 +08:00
parent ac48c6d716
commit e5733b3454
42 changed files with 18294 additions and 1168 deletions
@@ -74,12 +74,18 @@ RemoDispBus 让远端(PC 上的 DTU-RemoteLCD 客户端 / 浏览器页面)
| CMD | 名称 | 请求数据段(客户端→服务端) | 应答数据段(服务端→客户端) | 说明 |
|---|---|---|---|---|
| 0 | KEEPLIVE | 无(LEN=0) | 无(LEN=0) | 保活/心跳,服务端原样回显 |
| 1 | INIT | 无(LEN=0,查询) | `[宽u16][高u16][帧字节数u32]`(6B) | 客户端查询屏幕几何与显存大小 |
| 1 | INIT | 无(LEN=0,查询) | `[宽u16][高u16][帧字节数u32]`(**8B**) | 客户端查询屏幕几何与显存大小 |
| 2 | KEY | `[按键码u8]`(1B) | 无(LEN=0,确认) | 远端导航按键,服务端注入 UI |
| 3 | LCDMEM | `[起始偏移u32]`(4B) | `[偏移u32][1bpp位图 3200B]`(3204B) | 读取显存(画面);偏移 0 = 整帧 |
> **按键码**(`KEY` 数据段,与 `ui_port.h` 一致):`UP=0x02`、`DOWN=0x40`、`LEFT=0x10`、`RIGHT=0x08`、`ENTER=0x20`、`ESC=0x01`。
> **注意**:客户端(如 Python 参考实现)可不使用 `INIT`(直接按 160×160 处理);协议保留该命令供需查询几何的客户端使用。
>
> ⚠ **INIT 应答长度勘误(2026-09-22 M3 台架实测修复,D17)**:本表原写"6B",而字段定义
> `[宽u16][高u16][帧字节数u32]` 合计为 **8B**。旧实现按 6 发送 → u32 只剩高半字 →
> 客户端读到的"帧字节数"**恒为 0**(真机与 PC 模拟器一致复现)。现已改为发满 8B
> (`remo_send_init`),客户端按 `LEN>=8` 读 u32;若需兼容旧固件,可按 `LEN==6` 时
> 只取前 4B(宽高)。
### 1.6 屏幕位图格式(LCDMEM 数据段)
+22 -44
View File
@@ -1,39 +1,24 @@
# 存储栈 RAM 优化调研
> 版本 v1.0 日期 2026-09-21 作者 AI 辅助调研
> 版本 v1.1 日期 2026-09-21 作者 AI 辅助调研
> 数据来源:`data/ram_report_20260921.md`(.map 静态占用)+ 逐行代码核验(`nand_ftl.c` / `gd5f2gq5ue.c` / `Lib/dhara` / `Lib/FatFs/ffconf.h` / `lftpd*`)
> 定位:`RAM使用分析与优化方案.md` 的存储专项补充;优化项编号 P0/P1/P2,与总方案 §6 的 S 序号在"规划"一节对齐
> v1.1 清理(2026-09-21 同日):移除已落地的 P0-1 BBT 页缓冲收缩(−1,776B,commit `be1a30a`)与编程回读校验整体移除的实施记录(详见 GD5F Trap 05 / 错误码传播审计),以及过期逐模块基线表;仅保留未实施项与回归要求
## 1. 现状盘点(2026-09-21 基线)
## 1. 现状约束(不变,是下述全部方案的依据)
存储栈静态 RAM 全部在 **RW_IRAM1(主 SRAM 128KB)**,合计 **≈15.5 KB(占已用 82,048B 的 18.9%)**。运行期堆占用(CCM)仅 lftpd 路径串/`DIR` 约 ≤100B 瞬态,FatFs/dhara 无大块堆分配。
- 存储栈静态 RAM 全在 **RW_IRAM1(主 SRAM 128KB)**;页缓冲(nand_ftl 3×2KB + gd5f 页缓冲/位图)走 SPI1 DMA(阈值 >1024B),**DMA1/DMA2 物理不可达 CCM** → 不能直迁 CCM(唯一途径:迁移 + `gd5f_dma_buf_ok()` 运行时守卫自动回落 CPU 轮询(2026-09-21 加固),不会静默失败,代价仅每页零点几 ms CPU)
- 3×2KB 页缓冲是结构成本不可直缩:dhara journal 要求整页 checkpoint(`journal.c:196` 整页 memset);512B 扇区落 2KB 页必须整页 RMW;可动的只有 `s_copy_buf`(→ P0-2)
- CPU-only 缓冲(lftpd static ~3.6K / cfg_file 0.7K / FATFS win 0.6K / lftpd_io 0.6K)迁 CCM 零代价(→ P1-5①)
- 栈上 FIL 重复占深链:syslog 两处、cfg 存储两处、开机探针各一个局部 `FIL`(每个含 512B 私有 buf,≈552B),全压在 defaultTask 最坏链 2,776B 内(→ P1-4 靶点)
- FatFs 配置已低 RAM 取向:`FF_MAX_SS=512`、`FF_USE_LFN=0`、`FF_VOLUMES=1`、`FF_FS_LOCK=0`;`FF_FS_REENTRANT=1` 为 defaultTask/ftpTask 并发访问必需,勿动
- 教训(2026-09-21):任何比对式校验必须在**两份独立副本**间进行(U-Boot `sf test` 双缓冲形态)——旧 GC 拷贝自比对缺陷已随回读校验整体移除而消失;若未来测试构建恢复回读诊断,勿重蹈此坑
| 模块 (.o) | RW+ZI | 主要构成 | 约束 |
|---|---:|---|---|
| nand_ftl.o | 6,216 | `s_page_buf` 2,048(dhara journal checkpoint,协议要求整页)+ `s_cache_buf` 2,048(512B 扇区 RMW 写回缓存)+ `s_copy_buf` 2,048(GC 拷贝暂存)+ dhara map/journal 结构 ~120 | 页缓冲走 SPI1 DMA(>阈值 1024B),DMA 不可达 CCM |
| gd5f2gq5ue.o | 2,596 | `s_bbt_page_buf` 2,048 + `s_bbt`/`s_bbt_best` 位图 2×256 + 保留池 16 + 状态 | 同上 |
| lftpd.o | 4,768 | 9 处函数级 static:2×1024(STOR/RETR 数据块)、512×3(response/read_buffer/arg_buf)、256×3(message/name×2)+ 256(log) | 纯 CPU 访问,无 DMA |
| lftpd_io.o | 556 | `s_ftp_file`(FIL,内含 512B 私有扇区窗) | 纯 CPU |
| freertos.o 内 `default_fatfs` | ~576 | FATFS 对象(`win[512]` 共享窗 + 卷状态) | 纯 CPU |
| cfg_file.o | 724 | 配置引擎静态态 | 纯 CPU |
| ff.o + ffsystem.o | 16 | 文件系统对象指针 + 同步原语 | `FF_FS_REENTRANT=1`(defaultTask/ftpTask 并发所需,保留) |
FatFs 配置已是低 RAM 取向:`FF_MAX_SS=512`、`FF_USE_LFN=0`、`FF_VOLUMES=1`、`FF_FS_LOCK=0`。
## 2. 调研发现
- **F1 BBT 页缓冲超配 10 倍**:`s_bbt_page_buf[2048]`,但实际读写只有 `GD5F_BBT_HDR_SIZE(16)+GD5F_BBT_SIZE(256)=272B`(`gd5f2gq5ue.c:925` 读 272B、`:1010` program_load 272B)。缩到 272B 行为零变化。
- **F2 ~~GC 搬迁路径 program verify 空转~~(已随校验整体移除而消失,留档备查)**:2026-09-21 前 `dhara_nand_copy()` 回读缓冲与源同址(`s_copy_buf`),memcmp 恒真自比对(空校验);2026-09-21 编程回读校验整体移除(选项 (b),向 Linux mtd 形态靠拢)后该缺陷不复存在。教训:任何比对式校验必须在**两份独立副本**间进行(U-Boot `sf test` 双缓冲形态)——若未来在测试构建恢复回读诊断,勿重蹈此坑。
- **F3 3×2KB 页缓冲是结构成本,不可直缩**:dhara journal 要求整页 checkpoint(`journal.c:196` 整页 memset);512B 扇区落 2KB 页必须整页 RMW。可动的只有 `s_copy_buf`(改分段暂存)。
- **F4 CCM 迁移功能上安全**:`gd5f_dma_buf_ok()` 运行时守卫会把 DMA 不可达缓冲自动回落 CPU 轮询(2026-09-21 加固),把 NAND 页缓冲挪进 CCM 不会静默失败,代价只是每页零点几 ms CPU(轮询 vs DMA 卸载)。CPU-only 缓冲(lftpd/cfg/FATFS win)迁 CCM 则零代价。
- **F5 栈上 FIL 重复占深链**:syslog 两处、cfg 存储两处、开机探针各一个局部 `FIL`(每个含 512B buf,≈552B),全部压在 defaultTask 最坏链 2,776B 内——这是 `FF_FS_TINY` 的靶点(见 P1-4)。
## 3. 方案清单
## 2. 方案清单(未实施)
| # | 方案 | 省 RAM | 区域 | 风险 | 验证 |
|---|---|---:|---|---|---|
| P0-1 | `s_bbt_page_buf` 2048→272(按实际读写字节数定义) | **−1,776B** | SRAM1 | 极低(一行宏+数组维) | `@build` + 开机 BBT 加载 + `@test` |
| P0-2 | `s_copy_buf` 2048→512:GC 拷贝改分段 read→program_load(`program_load`/`read_from_cache` 支持列地址)【性质变更 2026-09-21:回读校验整体移除后,此项变为**纯 RAM 优化**(GC 拷贝暂存减半),无校验语义风险,与原"分块+修 F2"解耦】 | **−1,536B(可选,不计入当前预期)** | SRAM1 | 低(仅动拷贝机制) | 待 RAM 余量需要时再议 |
| P0-2 | `s_copy_buf` 2048→512:GC 拷贝改分段 read→program_load(`program_load`/`read_from_cache` 支持列地址);纯 RAM 优化(GC 拷贝暂存减半) | **−1,536B(可选,不计入当前预期)** | SRAM1 | 低(仅动拷贝机制) | 待 RAM 余量需要时再议 |
| P0-3 | lftpd 缓冲收紧:response 512→256、read_buffer 512→256、arg_buf 512→256、name 256→128 ×2(本卷仅 8.3 短名,路径深度浅);数据块 2×1024 与 message 不动 | **−1,024B** | SRAM1 | 低(FTP 客户端实测行长远低于新值) | `@build` + FTP 上传/下载/LIST 闭环 + `@test` |
| P1-4 | `FF_FS_TINY=1`:删每 FIL 私有的 512B buf,文件数据走 `FatFs->win` 共享窗 | 静态 **−528B**;且栈上每处 FIL 峰值 **−528B**(defaultTask 最坏链 2,776→~2,250,实测峰 2,136→~1,600) | SRAM1 + CCM 栈 | 中(所有文件 I/O 经 512B 窗 bounce,FTP 吞吐 −20~40%;LIST 与文件读交错只影响速度) | 存储套件 + FTP 吞吐实测 + 日志/配置闭环;**与 S7 缩栈捆绑**(直接支撑 defaultTask 降档) |
| P1-5 | `APP_CCM_ENABLE` 门(与 S6 同宏):①CPU-only 缓冲迁 CCM——lftpd static 3.6K + cfg_file 0.7K + FATFS win 0.6K + lftpd_io ≈ **−4.9K** 零代价;②DMA 页缓冲(nand_ftl 4.6K + gd5f 位图/页 0.8K)迁 CCM 走轮询 ≈ **−5.4K**,需实测吞吐 | **−10.3K** | SRAM1→CCM | 低①/中② | 分段实施;每步跑 `ram_report.py` + `@test` + FTP 吞吐 |
@@ -43,28 +28,21 @@ FatFs 配置已是低 RAM 取向:`FF_MAX_SS=512`、`FF_USE_LFN=0`、`FF_VOLUME
**明确不做**:移除 dhara(丢掉电一致性与坏块重映射,代价不对称);journal checkpoint 分片(违反 dhara 协议);调 `gc_ratio`(无 RAM 收益);`FF_FS_REENTRANT=0`(defaultTask+ftpTask 并发访问 FatFs 必需)。
**实施记录**:
## 3. 分阶段规划(与总方案 §6 S 序号对齐)
| # | 状态 | 日期 | 验证 |
|---|---|---|---|
| P0-1 | ✅ 已落地 | 2026-09-21 | `@build` 0/0;`@test` PASS(BBT 开机加载闭环);.map RW_IRAM1 82,048→80,272(**−1,776B**,精确命中) |
| P0-2 | ⏸ 搁置(性质已变) | 2026-09-21 | 回读校验整体移除后,此项由"校验分块+修 F2"变为 **GC 拷贝纯 RAM 优化**(`s_copy_buf` 2048→512 分段 read→load);无紧急性,待 RAM 余量需要时再议 |
| 编程回读校验整体移除 | ✅ 已落地 | 2026-09-21 | 先改编译开关 `GD5F_PROG_VERIFY`,同日按选项 (b) **整体移除**(向 Linux mtd / U-Boot / dhara 上游形态靠拢:数据路径无回读比对,编程正确性以 P_FAIL 状态位+读时 ECC+journal 读时门为准);代码/宏/开关全部移除,"实证失效"误记录同步更正(幻影编程假设已被 Trap 05 证伪,本板无实测编程失效);F2 自比对缺陷随之消失;产品构建 `@build` 0/0 + `@test` PASS |
| P0-3 / P1-4 / P1-5 | 待实施 | — | — |
## 4. 分阶段规划(与总方案 §6 S 序号对齐)
| 阶段 | 内容 | 收益(SRAM1 已用 82,048B 基础上) | 前置 |
| 阶段 | 内容 | 收益 | 前置 |
|---|---|---:|---|
| **第一步 P0**(独立小批) | P0-1(已落地)+ P0-3(P0-2 搁置,性质已变为纯拷贝优化) | **−2,800B**(P0-1 已省 1,776B) | 无 |
| **第一步**(独立小批) | P0-3(P0-2 搁置,待 RAM 余量需要时再议) | **−1,024B** | 无 |
| **第二步**(并入 S7 缩栈批) | P1-4 `FF_FS_TINY=1` → 复跑 `stack_report.py` → defaultTask 降档(最坏链 ~2,250 支撑 3,584B 配置,余量 37%)+ 其余任务按 S7 目标 | −528B 静态 + 栈档下调释放 CCM 堆 | 第一步合入 |
| **第三步**(与 S6/S8 同批) | 先 S8 堆 48K→32K(CCM 释放 ~16K),再 P1-5 ①→② 分批迁 CCM | SRAM1 再 **−10.3K**;CCM 占用 +10.3K(由 S8 腾挪覆盖) | S8 或同批评估 CCM 水位 |
**全部落地后存储栈预期**:SRAM1 常驻从 15.5KB 降至 **~1.9KB**(仅小状态量),页缓冲驻 CCM(轮询),静态合计挪入 CCM 换回 SRAM1 ≈ **−13.6KB**(P0-2 搁置(性质已变为纯拷贝优化),其 −1,536B 不计);叠加 S5(LVGL 40K→16K)后 SRAM1 余量 >65KB。
**全部落地后存储栈预期**:SRAM1 常驻降至 **~1.9KB**(现 13.7KB,其中 P0-1 已省 1,776B 不重复计;余下仅小状态量),页缓冲驻 CCM(轮询),未实施项合计换回 SRAM1 ≈ **−11.9K**(P0-2 搁置,其 −1,536B 不计);叠加 S5(LVGL 40K→16K)后 SRAM1 余量 >65KB。
## 5. 风险与回归要求
## 4. 回归与基线
- 回读校验移除(2026-09-21 落地):产品构建 `@build` 0/0 + `@test` 开机闭环(编程路径仅余 P_FAIL 状态检查);GD5F/STORAGE 测试构建各编译 0/0(套件 ECC 写读用例经读路径覆盖编程正确性);台架破坏性套件 + 掉电 resume 随下次存储改动照常执行。
- P1-4 前后各跑一次 `stack_report.py` + `ram_report.py`(AGENTS.md 门禁),FTP 吞吐留实测数字(当前基线可先记一轮 RETR/STOR 速率)。
- P1-5 的 ②(页缓冲入 CCM 走轮询)须以实测吞吐定去留:若 NAND 读吞吐降幅 >30%,则只迁 CPU-only 侧(①)。
- 本文数字均可由 `data/ram_report_20260921.md` 与上表代码行号复核;实施后重生成基线报告并回填本文状态列。
- **FTP 吞吐基线(2026-09-21 实测,4MB 文件,端到端含网络;瓶颈在存储侧,100M 网络非瓶颈)**:STOR **126.9 KB/s**(32.3s)/ RETR **321.4 KB/s**(12.7s),回传逐字节 MATCH(测试文件已自清理)→ P0-3/P1-4 前后各留一轮实测对比(P1-4 预期吞吐降幅 20~40%)
- P1-4 前后各跑一次 `stack_report.py` + `ram_report.py`(AGENTS.md 门禁)
- P1-5 的 ②(页缓冲入 CCM 走轮询)须以实测吞吐定去留:若 NAND 读吞吐降幅 >30%,则只迁 CPU-only 侧(①)
- P0-2/P2-x:待 RAM 余量需要时再议
- 下次存储改动照常执行台架破坏性套件 + 掉电 resume
- 基线数字可用 `data/ram_report_20260921.md`(P0-1 前快照)复核;实施后重生成基线报告并回填总方案
+120
View File
@@ -0,0 +1,120 @@
# M2 链路延迟实测数据(Phase 13,安静档)
本目录保存 M2(Phase 13:芯片 + 队列时延基线)的**原始实测产物**。判定阈值与解读见
[`../链路延迟测试说明.md`](../链路延迟测试说明.md) §4.2;缺陷定位过程见该文 §6.1。
## 1. 运行元数据
| 项 | 值 |
|---|---|
| 日期 | 2026-09-22(设备 RTC 显示 2026-09-21,落后 1 天,仅显示差异;主机时间戳 = 设备 + 4s) |
| 台架 | COM6 @115200;目标 192.168.1.100:8080(Phase 13 独占 socket 2) |
| 固件 | `test/test_config.h` = `TEST_SUITE_CH395F`;`test/ch395f_test.h` = `ENABLE_PHASE13_TESTS`(仅此一项) |
| 构建 | `MDK-ARM\build.bat` → **0 错误 0 警告**(测试构建与产品构建均 0/0) |
| 对端 | `.venv\Scripts\python.exe test\latency_peer.py --mode net`(纯标准库,`--wait 170`) |
| 会话顺序 | HELLO → L5_RECV → L5_SEND → L3 → L10 → L6 → L7 → DONE |
| 干扰 | 无(安静档,`ftp_stress=0`;未跑 `--ftp-stress`) |
| PASS 轮次 | **run12 / run13 / run15** 三次独立完整 PASS(`summary verdict=OK`、`=== Phase 13: 1/1 PASSED (failed=0) ===`、peer exit 0) |
复现命令(顺序不可反:先 `clear` 再起 peer,最后烧录):
```powershell
& "MDK-ARM\build.bat"
& '.venv\Scripts\python.exe' tools\serial_tool\serial_tool.py clear
& '.venv\Scripts\python.exe' test\latency_peer.py --host 192.168.1.100 --port 8080 `
--json "docs\测试说明\m2_data\m2_quiet_runNN.json" --wait 170 # 后台作业
& "MDK-ARM\download.bat"
& '.venv\Scripts\python.exe' tools\serial_tool\serial_tool.py wait-idle `
--timeout 120 --settle-ms 10000 --max-ms 110000
# 判定:Grep tools\serial_tool\state\serial.log
```
判定标记:Required `App init OK` / `Network Init` / `net init: OK` / `[LAT] report complete` /
`=== Phase 13: 1/1 PASSED`;Forbidden `HardFault` / `assert` / `[ERR]` / `[FAIL]` / `verdict=FAIL`;
peer 侧退出码 **0** = PASS(收到 `0xFF` 并打印汇总,`l7_crc.fail == 0`)。
## 2. 产物清单
| 文件 | 内容 |
|---|---|
| `m2_quiet.json` | **run15**(最终代码,规范基线)peer 端原始 JSON,含 10 帧逐帧批次明细 |
| `m2_quiet_run13.json` | **run13**(PASS 复现)peer 端原始 JSON |
| `m2_quiet_run14.json` | **run14**(PASS;但该轮 MCU 侧探针日志过载,仅 peer 侧数据有效,见 §6) |
| `m2_serial_excerpt_run15.txt` | **run15** 串口证据片段 62 行(**只含烧录重启后的会话**:从 Phase 13 横幅/`run_id` 校准行到 `1/1 PASSED` + relisten) |
| `m2_serial_excerpt_run13.txt` | run13 串口日志中 `[LAT]`/`[NET]`/Phase 13 相关 87 行(含烧录前旧固件段,需自行忽略) |
## 3. 实测结果
### 3.1 MCU 侧(`[LAT]` 报告,三次 PASS)
| 段 | run12 med(min/max, n) | run13 med(min/max, n) | **run15 med(min/max, n)** | warn / crit |
|---|---|---|---|---|
| `queue_rt_recv` | 6014µs(5365/6020, 19) | 6007µs(5392/6025, 20) | **5997µs(5513/6033, 20)** | 10ms / 100ms |
| `queue_rt_send` | 986µs(836/1204, 20) | 987µs(833/1209, 20) | **987µs(838/1209, 20)** | 10ms / 100ms |
| `chunk_wait` | 235µs(215/238, 64) | 219µs(213/377, 64) | **219µs(214/381, 64)** | 10ms / 500ms(spike) |
| `logtax_line` | 4396µs | 4396µs(4390/4414) | **4396µs(4394/4422)** | 10ms / 25ms |
| `req2first_mcu` | 310µs(296/338, 10) | 318µs(263/361, 10) | **319µs(308/338, 10)** | 20ms / 200ms |
| `fullframe_mcu` | 6021µs(5986/6103, 10) | 6052µs(5966/6078, 10) | **6028µs(5991/6066, 10)** | 50ms / 500ms |
三轮均:6 段 `verdict=OK`、`spikes=0`、`summary verdict=OK`、`1/1 PASSED`。
> run12 的 `queue_rt_recv` n=19 而非 20:对端 20×100B 中相邻两包被 TCP 合并成一次收
> (完成判定按字节 2000B),属正常合并,非丢包(三轮字节数均为 2000)。
### 3.2 PC 侧端到端(peer JSON)
| 段 | run12 med(min/max) | run13 med(min/max) | run15 med(min/max) | CRC |
|---|---|---|---|---|
| L6 端到端(op→回显) | 12.5ms(5.5/16.0) | 13.8ms(5.9/16.0) | 8.9ms(6.3/16.0) | — |
| L7 首字节 | 10.9ms(7.9/16.2) | 11.8ms(7.5/17.7) | 11.3ms(7.8/16.5) | — |
| L7 全帧 3209B | 61.1ms(54.2/61.5) | 61.7ms(59.9/70.9) | 57.9ms(52.6/72.3) | 10/0 |
## 4. 关键发现:L7 尾批固定迟到 ~44~60ms
run15 逐帧明细(10/10 帧结构完全一致):
```
frame#1: first=11.620ms batches=[1024,1024,1024,137] tail_lag=+53.8ms
frame#2: first=11.327ms batches=[1024,1024,1024,137] tail_lag=+46.5ms
frame#3: first= 8.160ms batches=[1024,1024,1024,137] tail_lag=+46.5ms
frame#4: first= 7.773ms batches=[1024,1024,1024,137] tail_lag=+44.8ms
frame#5: first= 9.858ms batches=[1024,1024,1024,137] tail_lag=+53.9ms
frame#6: first=11.900ms batches=[1024,1024,1024,137] tail_lag=+43.8ms
frame#7: first=10.465ms batches=[1024,1024,1024,137] tail_lag=+44.2ms
frame#8: first=10.615ms batches=[1024,1024,1024,137] tail_lag=+43.4ms
frame#9: first=11.328ms batches=[1024,1024,1024,137] tail_lag=+60.2ms
frame#10:first=16.522ms batches=[1024,1024,1024,137] tail_lag=+55.7ms
```
- 前 3 批各 1024B 在 **~4ms** 内到齐;第 4 批 137B(=3209−3072)稳定落在 **+43~+60ms**;
- MCU 侧把整个 3209B 交给芯片只花 **6.0ms**(`fullframe_mcu`)→ 延迟**不在 MCU 发送路径**;
- 缺口在**芯片 TCP 尾段发送 / 对端 ACK 交互**(候选:Nagle 式小段等待 + 对端延迟 ACK);
- 该尾批**主导整帧时长**(total ≈ 首字节 + 尾批延迟),是远端显示"每帧多 ~50ms"的直接来源;
- **M3 待办**:Wireshark(`tcp.port==8080`)确认尾段是被芯片扣住还是被对端 ACK 拖住,再定对策
(对端 `TCP_NODELAY` / 帧长与 chunk 对齐),**未证实前不改协议**。
## 5. 结论(回答 M2 立项问题)
1. **安静档不存在 500ms 台阶**:三轮 6 段全 OK、零尖峰、p95≈med;
2. 会话级 MCU 净成本量级 **~6ms**(`queue_rt_recv`,与 netTask 轮询节拍同量级);
3. 芯片 chunk 级不是瓶颈:`chunk_wait` med 219µs ≈ 每 chunk SPI 成本(1.61ms)的 1/7;
4. 生产链路的可见延迟主要在 **PC/线路段**(L6:MCU 侧 0.32ms vs 端到端 8.9~13.8ms)
与 **L7 尾批 ~50ms**。
## 6. 测量方法学(两条必须记住的坑)
1. **探针不得在 net 热路径逐调用打日志**(run14 实证):在 `net_wait_result` 内加
`pick/block` 两行后,日志量 40KB → 1.04MB(9,644/9,779 行 = **98.6%**),115200 下
丢行/串行错位,冲掉 `[LAT]` 段证据,`wait-idle` 永远判不出空闲;并实测把
`queue_rt_send` med 从 987µs 抬到 **7685µs(7.8×)**、`queue_rt_recv` p95 抬到 21ms。
→ 该轮 MCU 侧数据**不作基线**;诊断需求改在 `[LAT]` 段报告侧聚合。
2. **首连必失败是有意为之的正常现象**:peer 首连时常在 MCU 启动期完成握手,随后芯片
空闲超时(15~30s 无数据)RST → `WinError 10054`;peer 自动 +2s 重连后会话正常
(run12/13/15 均如此)。**另注意**:首连时若 MCU 正在烧录,attempt1 由**上一版固件**
服务(日志里那段偏高的数据不属于本轮固件),只有烧录重启后的会话才计入本轮基线。
## 7. 未纳入本目录的数据
- run1~run11 为缺陷定位过程(D11~D16 见测试说明 §6.1),其中 run10/run11 的 L7 失败、
run9 的 170s 连接拒绝均已定位并修复;
- 压力档(`--ftp-stress`,E-02 复现)与 `--mode remo`(生产 RemoDispBus 客户端)属 M3。
+277
View File
@@ -0,0 +1,277 @@
{
"mode": "net",
"host": "192.168.1.100",
"port": 8080,
"ts_start": "2026-09-21 23:09:38",
"ts_end": "2026-09-21 23:09:59",
"duration_s": 20.53,
"ops_seen": 24,
"ftp_stress": false,
"seg_l6": {
"n": 10,
"min_ms": 6.293,
"med_ms": 8.9,
"p95_ms": 15.991,
"max_ms": 15.991,
"spikes500": 0,
"echo_ok": 10,
"echo_fail": 0
},
"seg_l7_first_byte": {
"n": 10,
"min_ms": 7.773,
"med_ms": 11.327,
"p95_ms": 16.522,
"max_ms": 16.522,
"spikes500": 0
},
"seg_l7_total": {
"n": 10,
"min_ms": 52.636,
"med_ms": 57.859,
"p95_ms": 72.259,
"max_ms": 72.259,
"spikes500": 0
},
"l7_crc": {
"ok": 10,
"fail": 0,
"batches_per_frame": [
4
]
},
"l5_recv": {
"bytes": 2000,
"window_ms": 1009.1027
},
"l5_send": {
"bytes": 2000,
"window_ms": 51.5854
},
"l3_drain": {
"bytes": 65536,
"window_ms": 125.4635
},
"frames_l7": [
{
"first_ms": 11.62,
"total_ms": 65.482,
"batches": [
[
11.629,
1024
],
[
13.33,
1024
],
[
15.2,
1024
],
[
65.458,
137
]
]
},
{
"first_ms": 11.327,
"total_ms": 57.859,
"batches": [
[
11.337,
1024
],
[
13.164,
1024
],
[
14.991,
1024
],
[
57.842,
137
]
]
},
{
"first_ms": 8.16,
"total_ms": 54.708,
"batches": [
[
8.162,
1024
],
[
9.951,
1024
],
[
11.775,
1024
],
[
54.66,
137
]
]
},
{
"first_ms": 7.773,
"total_ms": 52.636,
"batches": [
[
7.782,
1024
],
[
9.552,
1024
],
[
11.351,
1024
],
[
52.618,
137
]
]
},
{
"first_ms": 9.858,
"total_ms": 63.802,
"batches": [
[
9.864,
1024
],
[
11.65,
1024
],
[
13.472,
1024
],
[
63.783,
137
]
]
},
{
"first_ms": 11.9,
"total_ms": 55.693,
"batches": [
[
11.906,
1024
],
[
13.619,
1024
],
[
15.435,
1024
],
[
55.664,
137
]
]
},
{
"first_ms": 10.465,
"total_ms": 54.676,
"batches": [
[
10.471,
1024
],
[
12.222,
1024
],
[
14.021,
1024
],
[
54.656,
137
]
]
},
{
"first_ms": 10.615,
"total_ms": 54.047,
"batches": [
[
10.621,
1024
],
[
12.356,
1024
],
[
14.187,
1024
],
[
54.028,
137
]
]
},
{
"first_ms": 11.328,
"total_ms": 71.511,
"batches": [
[
11.333,
1024
],
[
13.159,
1024
],
[
14.993,
1024
],
[
71.495,
137
]
]
},
{
"first_ms": 16.522,
"total_ms": 72.259,
"batches": [
[
16.526,
1024
],
[
18.309,
1024
],
[
20.1,
1024
],
[
72.246,
137
]
]
}
]
}
@@ -0,0 +1,277 @@
{
"mode": "net",
"host": "192.168.1.100",
"port": 8080,
"ts_start": "2026-09-21 23:01:40",
"ts_end": "2026-09-21 23:02:01",
"duration_s": 20.56,
"ops_seen": 24,
"ftp_stress": false,
"seg_l6": {
"n": 10,
"min_ms": 5.873,
"med_ms": 13.753,
"p95_ms": 15.967,
"max_ms": 15.967,
"spikes500": 0,
"echo_ok": 10,
"echo_fail": 0
},
"seg_l7_first_byte": {
"n": 10,
"min_ms": 7.463,
"med_ms": 11.829,
"p95_ms": 17.706,
"max_ms": 17.706,
"spikes500": 0
},
"seg_l7_total": {
"n": 10,
"min_ms": 59.916,
"med_ms": 61.689,
"p95_ms": 70.892,
"max_ms": 70.892,
"spikes500": 0
},
"l7_crc": {
"ok": 10,
"fail": 0,
"batches_per_frame": [
4
]
},
"l5_recv": {
"bytes": 2000,
"window_ms": 1007.7367
},
"l5_send": {
"bytes": 2000,
"window_ms": 47.0342
},
"l3_drain": {
"bytes": 65536,
"window_ms": 125.4454
},
"frames_l7": [
{
"first_ms": 7.463,
"total_ms": 61.218,
"batches": [
[
7.468,
1024
],
[
9.239,
1024
],
[
11.079,
1024
],
[
61.198,
137
]
]
},
{
"first_ms": 16.95,
"total_ms": 70.892,
"batches": [
[
16.955,
1024
],
[
18.745,
1024
],
[
20.566,
1024
],
[
70.879,
137
]
]
},
{
"first_ms": 11.829,
"total_ms": 63.888,
"batches": [
[
11.835,
1024
],
[
13.612,
1024
],
[
15.501,
1024
],
[
63.874,
137
]
]
},
{
"first_ms": 17.706,
"total_ms": 61.689,
"batches": [
[
17.711,
1024
],
[
19.527,
1024
],
[
21.336,
1024
],
[
61.678,
137
]
]
},
{
"first_ms": 10.82,
"total_ms": 61.639,
"batches": [
[
10.825,
1024
],
[
12.605,
1024
],
[
14.433,
1024
],
[
61.625,
137
]
]
},
{
"first_ms": 15.018,
"total_ms": 62.205,
"batches": [
[
15.021,
1024
],
[
16.775,
1024
],
[
18.631,
1024
],
[
62.191,
137
]
]
},
{
"first_ms": 11.55,
"total_ms": 59.916,
"batches": [
[
11.553,
1024
],
[
13.352,
1024
],
[
15.298,
1024
],
[
59.901,
137
]
]
},
{
"first_ms": 17.442,
"total_ms": 61.347,
"batches": [
[
17.447,
1024
],
[
19.216,
1024
],
[
21.037,
1024
],
[
61.333,
137
]
]
},
{
"first_ms": 10.893,
"total_ms": 61.474,
"batches": [
[
10.896,
1024
],
[
12.705,
1024
],
[
14.488,
1024
],
[
61.456,
137
]
]
},
{
"first_ms": 8.138,
"total_ms": 65.744,
"batches": [
[
8.14,
1024
],
[
9.954,
1024
],
[
11.778,
1024
],
[
65.732,
137
]
]
}
]
}
@@ -0,0 +1,277 @@
{
"mode": "net",
"host": "192.168.1.100",
"port": 8080,
"ts_start": "2026-09-21 23:06:48",
"ts_end": "2026-09-21 23:07:08",
"duration_s": 20.83,
"ops_seen": 24,
"ftp_stress": false,
"seg_l6": {
"n": 10,
"min_ms": 7.741,
"med_ms": 12.919,
"p95_ms": 22.593,
"max_ms": 22.593,
"spikes500": 0,
"echo_ok": 10,
"echo_fail": 0
},
"seg_l7_first_byte": {
"n": 10,
"min_ms": 12.286,
"med_ms": 17.669,
"p95_ms": 27.926,
"max_ms": 27.926,
"spikes500": 0
},
"seg_l7_total": {
"n": 10,
"min_ms": 61.729,
"med_ms": 69.339,
"p95_ms": 77.421,
"max_ms": 77.421,
"spikes500": 0
},
"l7_crc": {
"ok": 10,
"fail": 0,
"batches_per_frame": [
4
]
},
"l5_recv": {
"bytes": 2000,
"window_ms": 1009.6644
},
"l5_send": {
"bytes": 2000,
"window_ms": 141.24
},
"l3_drain": {
"bytes": 65536,
"window_ms": 252.7994
},
"frames_l7": [
{
"first_ms": 18.361,
"total_ms": 66.707,
"batches": [
[
18.365,
1024
],
[
20.136,
1024
],
[
21.958,
1024
],
[
66.695,
137
]
]
},
{
"first_ms": 16.538,
"total_ms": 70.094,
"batches": [
[
16.543,
1024
],
[
18.366,
1024
],
[
20.151,
1024
],
[
70.081,
137
]
]
},
{
"first_ms": 13.118,
"total_ms": 65.761,
"batches": [
[
13.122,
1024
],
[
14.926,
1024
],
[
16.699,
1024
],
[
65.748,
137
]
]
},
{
"first_ms": 14.178,
"total_ms": 61.729,
"batches": [
[
14.182,
1024
],
[
15.989,
1024
],
[
17.781,
1024
],
[
61.712,
137
]
]
},
{
"first_ms": 15.215,
"total_ms": 62.55,
"batches": [
[
15.221,
1024
],
[
17.004,
1024
],
[
18.826,
1024
],
[
62.538,
137
]
]
},
{
"first_ms": 19.429,
"total_ms": 70.141,
"batches": [
[
19.435,
1024
],
[
21.381,
1024
],
[
23.043,
1024
],
[
70.124,
137
]
]
},
{
"first_ms": 25.165,
"total_ms": 73.135,
"batches": [
[
25.17,
1024
],
[
26.913,
1024
],
[
28.72,
1024
],
[
73.114,
137
]
]
},
{
"first_ms": 17.669,
"total_ms": 65.542,
"batches": [
[
17.674,
1024
],
[
19.566,
1024
],
[
21.363,
1024
],
[
65.531,
137
]
]
},
{
"first_ms": 27.926,
"total_ms": 77.421,
"batches": [
[
27.931,
1024
],
[
29.805,
1024
],
[
31.647,
1024
],
[
77.408,
137
]
]
},
{
"first_ms": 12.286,
"total_ms": 69.339,
"batches": [
[
12.29,
1024
],
[
14.128,
1024
],
[
16.004,
1024
],
[
69.325,
137
]
]
}
]
}
@@ -0,0 +1,87 @@
[RX] 2026-09-21T23:01:37.691+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=4
[RX] 2026-09-21T23:01:37.691+08:00 [2026-09-21 23:01:33][LAT_TEST] [LAT] peer re-HELLO -> session restart
[RX] 2026-09-21T23:01:37.702+08:00 [2026-09-21 23:01:33][LAT_TEST] [LAT] peer session start
[RX] 2026-09-21T23:01:37.723+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:37.775+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:37.817+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:37.869+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:37.921+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:37.963+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.015+08:00 [2026-09-21 23:01:33][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.067+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.129+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.171+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.223+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.275+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.317+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.369+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.421+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.472+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.514+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.576+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.628+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.680+08:00 [2026-09-21 23:01:34][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:38.680+08:00 [2026-09-21 23:01:34][LAT_TEST] [LAT] seg=queue_rt_recv n=20 min=5966 med=6008 p95=6969 max=6969 us spikes=0
[RX] 2026-09-21T23:01:38.691+08:00 [2026-09-21 23:01:34][LAT_TEST] [LAT] verdict=OK seg=queue_rt_recv (med=6008ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:01:38.733+08:00 [2026-09-21 23:01:34][LAT_TEST] [LAT] seg=queue_rt_send n=20 min=835 med=988 p95=1213 max=1213 us spikes=0
[RX] 2026-09-21T23:01:38.743+08:00 [2026-09-21 23:01:34][LAT_TEST] [LAT] verdict=OK seg=queue_rt_send (med=988ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:01:58.948+08:00 [2026-09-21 23:01:54][NET] recv sock2 len=4
[RX] 2026-09-21T23:01:58.958+08:00 [2026-09-21 23:01:55][LAT_TEST] [LAT] peer session start
[RX] 2026-09-21T23:01:58.969+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.020+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.071+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.123+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.174+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.216+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.268+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.320+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.372+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.424+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.507+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.518+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.569+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.621+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.683+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.725+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.777+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.829+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.870+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.922+08:00 [2026-09-21 23:01:55][NET] recv sock2 len=100
[RX] 2026-09-21T23:01:59.922+08:00 [2026-09-21 23:01:55][LAT_TEST] [LAT] seg=queue_rt_recv n=20 min=5392 med=6007 p95=6025 max=6025 us spikes=0
[RX] 2026-09-21T23:01:59.932+08:00 [2026-09-21 23:01:55][LAT_TEST] [LAT] verdict=OK seg=queue_rt_recv (med=6007ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:01:59.985+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] seg=queue_rt_send n=20 min=833 med=987 p95=1209 max=1209 us spikes=0
[RX] 2026-09-21T23:01:59.995+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] verdict=OK seg=queue_rt_send (med=987ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:02:00.141+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] seg=chunk_wait n=64 min=213 med=219 p95=238 max=377 us spikes=0
[RX] 2026-09-21T23:02:00.152+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] verdict=OK seg=chunk_wait (med=219ms warn<=10000 crit<=500000 spikes=0/0)
[RX] 2026-09-21T23:02:00.214+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] seg=logtax_line n=10 min=4390 med=4396 p95=4414 max=4414 us spikes=0
[RX] 2026-09-21T23:02:00.224+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] verdict=OK seg=logtax_line (med=4396ms warn<=10000 crit<=25000 spikes=0/0)
[RX] 2026-09-21T23:02:00.256+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.318+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.370+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.432+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.493+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.555+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.617+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.669+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.731+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.804+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=10
[RX] 2026-09-21T23:02:00.804+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] seg=req2first_mcu n=10 min=263 med=318 p95=361 max=361 us spikes=0
[RX] 2026-09-21T23:02:00.815+08:00 [2026-09-21 23:01:56][LAT_TEST] [LAT] verdict=OK seg=req2first_mcu (med=318ms warn<=20000 crit<=200000 spikes=0/0)
[RX] 2026-09-21T23:02:00.856+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:00.929+08:00 [2026-09-21 23:01:56][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:00.991+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.063+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.115+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.187+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.239+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.311+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.362+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.424+08:00 [2026-09-21 23:01:57][NET] recv sock2 len=9
[RX] 2026-09-21T23:02:01.434+08:00 [2026-09-21 23:01:57][LAT_TEST] [LAT] seg=fullframe_mcu n=10 min=5966 med=6052 p95=6078 max=6078 us spikes=0
[RX] 2026-09-21T23:02:01.444+08:00 [2026-09-21 23:01:57][LAT_TEST] [LAT] verdict=OK seg=fullframe_mcu (med=6052ms warn<=50000 crit<=500000 spikes=0/0)
[RX] 2026-09-21T23:02:01.465+08:00 [2026-09-21 23:01:57][LAT_TEST] [LAT] summary verdict=OK
[RX] 2026-09-21T23:02:01.476+08:00 [2026-09-21 23:01:57][LAT_TEST] [LAT] report complete
[RX] 2026-09-21T23:02:01.486+08:00 [2026-09-21 23:01:57][LAT_TEST] === Phase 13: 1/1 PASSED (failed=0) ===
[RX] 2026-09-21T23:02:01.497+08:00 [2026-09-21 23:01:57][LAT_TEST] [LAT] note: CLOSED on abort -> re-listen via chip
[RX] 2026-09-21T23:02:02.100+08:00 [2026-09-21 23:01:58][NET] sock2 auto-relisten ok
[RX] 2026-09-21T23:02:53.179+08:00 [2026-09-21 23:02:49][NET] sock3 auto-relisten ok
@@ -0,0 +1,62 @@
[RX] 2026-09-21T23:09:54.768+08:00 [2026-09-21 23:09:50][LAT_TEST] === CH395F Phase 13 Tests (chip+queue latency, L3~L7/L10) ===
[RX] 2026-09-21T23:09:54.768+08:00 [2026-09-21 23:09:50][LAT_TEST] [LAT] run_id=2910 phase=13 cal core_clk=168000000 us_per_1024cyc=6
[RX] 2026-09-21T23:09:54.779+08:00 [2026-09-21 23:09:50][LAT_TEST] [LAT] waiting for peer HELLO (port 8080, latency_peer.py --mode net)
[RX] 2026-09-21T23:09:56.973+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=4
[RX] 2026-09-21T23:09:56.973+08:00 [2026-09-21 23:09:53][LAT_TEST] [LAT] peer session start
[RX] 2026-09-21T23:09:56.994+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.046+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.088+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.140+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.193+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.245+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.287+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.340+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.393+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.447+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.510+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.552+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.593+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.645+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.698+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.739+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.792+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.854+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.906+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.948+08:00 [2026-09-21 23:09:53][NET] recv sock2 len=100
[RX] 2026-09-21T23:09:57.959+08:00 [2026-09-21 23:09:53][LAT_TEST] [LAT] seg=queue_rt_recv n=20 min=5513 med=5997 p95=6033 max=6033 us spikes=0
[RX] 2026-09-21T23:09:57.969+08:00 [2026-09-21 23:09:53][LAT_TEST] [LAT] verdict=OK seg=queue_rt_recv (med=5997ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:09:58.012+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=queue_rt_send n=20 min=838 med=987 p95=1209 max=1209 us spikes=0
[RX] 2026-09-21T23:09:58.022+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=queue_rt_send (med=987ms warn<=10000 crit<=100000 spikes=0/0)
[RX] 2026-09-21T23:09:58.169+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=chunk_wait n=64 min=214 med=219 p95=238 max=381 us spikes=0
[RX] 2026-09-21T23:09:58.179+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=chunk_wait (med=219ms warn<=10000 crit<=500000 spikes=0/0)
[RX] 2026-09-21T23:09:58.243+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=logtax_line n=10 min=4394 med=4396 p95=4422 max=4422 us spikes=0
[RX] 2026-09-21T23:09:58.253+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=logtax_line (med=4396ms warn<=10000 crit<=25000 spikes=0/0)
[RX] 2026-09-21T23:09:58.285+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.338+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.400+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.462+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.525+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.587+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.640+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.692+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.744+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.806+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=10
[RX] 2026-09-21T23:09:58.806+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] seg=req2first_mcu n=10 min=308 med=319 p95=338 max=338 us spikes=0
[RX] 2026-09-21T23:09:58.817+08:00 [2026-09-21 23:09:54][LAT_TEST] [LAT] verdict=OK seg=req2first_mcu (med=319ms warn<=20000 crit<=200000 spikes=0/0)
[RX] 2026-09-21T23:09:58.859+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:58.922+08:00 [2026-09-21 23:09:54][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:58.975+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.038+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.090+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.152+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.204+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.266+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.319+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.392+08:00 [2026-09-21 23:09:55][NET] recv sock2 len=9
[RX] 2026-09-21T23:09:59.402+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] seg=fullframe_mcu n=10 min=5991 med=6028 p95=6066 max=6066 us spikes=0
[RX] 2026-09-21T23:09:59.412+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] verdict=OK seg=fullframe_mcu (med=6028ms warn<=50000 crit<=500000 spikes=0/0)
[RX] 2026-09-21T23:09:59.444+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] summary verdict=OK
[RX] 2026-09-21T23:09:59.454+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] report complete
[RX] 2026-09-21T23:09:59.454+08:00 [2026-09-21 23:09:55][LAT_TEST] === Phase 13: 1/1 PASSED (failed=0) ===
[RX] 2026-09-21T23:09:59.475+08:00 [2026-09-21 23:09:55][LAT_TEST] [LAT] note: CLOSED on abort -> re-listen via chip
[RX] 2026-09-21T23:10:00.068+08:00 [2026-09-21 23:09:56][NET] sock2 auto-relisten ok
File diff suppressed because it is too large Load Diff
File diff suppressed because it is too large Load Diff
File diff suppressed because it is too large Load Diff
File diff suppressed because it is too large Load Diff
File diff suppressed because it is too large Load Diff
File diff suppressed because it is too large Load Diff
File diff suppressed because it is too large Load Diff
@@ -0,0 +1,377 @@
# 链路延迟测试说明(CH395F 网络传输分段时延基线)
> **模块名称**:CH395F 网络链路分段时间延测试
> **文档目的**:把"一次画面更新/一次收发"拆成独立可测的段,为每段建立**正常基线 + 阈值判定**,
> 输出自动 verdict,使"延迟"从主观感觉变为"哪一段超了基线"的客观判断依据。
> **日期**:2026-09-22
> **状态**:M1(Phase 12,SPI 层基线)已实现;M2~M5 待排期
> **配套文档**:`docs/问题记录/远程显示延迟分析.md`(延迟预算与 D1~D10 候选原因)、
> `CH395F_Test_Guide.md`(套件构建模式与执行顺序)、`自动化测试流程.md`(@test 闭环)
---
## 0. 目标与设计原则
**目标**:对 CH395F 网络传输链路的每一段分别测量、分别判定,建立可重复回归的时延基线。
任一段超标即能定位到对应原因(D1~D10,见《远程显示延迟分析》)并指向对应解决方案。
| 原则 | 说明 |
|---|---|
| **同一把尺子量两端** | PC 端 peer 脚本对**模拟器**和**MCU**使用完全相同的测量流程(同一协议、同一计时点),结果直接相减,差值 = CH395F 栈的净贡献(Δ,见 §1),消除"客户端成本"这个混淆项 |
| **分段隔离 + 统计量** | 每段单独测 N 次,报 `min/med/p95/max` + **≥500ms 尖峰计数**(TCP 重传 500ms 粒度的指纹,D1 自动显形);Wireshark 仅用于需要逐段精确视图时的补充手段 |
| **非侵入、非破坏** | 新增测量代码藏在 `#ifdef TEST_LATENCY_PROBE`(仅测试构建定义)→ 产品构建零代码零开销;不改任何设备持久状态(不写 IP/卷/BBT)。但 Phase 12/13/14 独占 CH395F 或占用 :7003 → **仅限台架**,与现有 HW 层约定一致 |
| **基线锁板** | 初始阈值取自静态推算;**首块台架实测后以实测值重锁为该板基线**(更新 §4 表),后续每次回归与基线比对 |
## 1. 链路分段与测量点
| 段 | 名称 | 测什么 | 测点 | 方法 | 预期正常值* | 超标指向 |
|---|---|---|---|---|---|---|
| **L1** | SPI 字节命令 | 一条小 SPI 事务(GET_IC_VER / CHECK_EXIST / GLOB_INT,4~7B)端到端 | MCU,DWT µs | **Phase 12(M1)**,N=100/命令 | ≤60µs | SPI 走线/PCB/分频/DMA 配置 |
| **L2** | SPI DMA | `ch395f_read_recv_buf(N)` 完整 DMA 事务(含 CS 切换),N ∈ {4, 64, 1024, 2048} | MCU,DWT µs | **Phase 12(M1)**,N=100/档 | 1KB ≈ 1.56ms(5.25Mbit/s 理论)+0.1~0.3ms 固定开销 | SPI2/DMA/总线异常 |
| **L3** | 发送分块握手 | `write_send_buf(1KB)` → `SENBUF_FREE` 的等待时长(= `net_send_locked` 每 chunk 的真实等待) | MCU(netTask 上下文) | Phase 13(M2),每帧 4 chunk × 50 帧 | 1~5ms | 芯片发送路径 / **重传(D1) / 链路(D7)** |
| **L4** | 芯片→线上+PC | 数据交入芯片协议栈 → PC 首见字节 / 收齐全帧(peer 逐 `recv()` 批次打时间戳 → 字节到达曲线) | PC(peer) | Phase 13/14(M2/M3) | 首段 <10ms;**段间间隙 ≥500ms = 重传** | **D1/D4/D7**("网络延迟"直接证据) |
| **L5** | 队列往返 | 调用方视角 `net_recv(DONTWAIT)` / `net_send` 全程 = 入队 + netTask 调度 + 处理 + 通知 | MCU(调用方计时) | Phase 13(M2),N=100,**两档**:静默基线 + 压力档(并发 syslog/FTP 流量) | 静默 ≤5ms;压力档 ≤100ms | **D3(E-02 头阻塞)** / D5 调度 |
| **L6** | 请求→首字节(测试路径) | peer 发 10B 请求 → MCU 收齐并启动应答(服务端视角);与 PC 侧"发→首字节"对照,差值 = 线路 + PC 栈 | MCU + PC 双侧 | Phase 13(M2) | ≤50ms | MCU 收路径/调度 |
| **L7** | 整帧 3209B 往返 | LCDMEM 全帧:PC 发 → 收齐(含 L3+L4) | PC 为主 | Phase 13(M2) | ≤150ms;**spike(≥500ms)=0** | D1+D2+D4 综合 |
| **L8** | 生产路径帧周期 | **真实 uiTask + 真实 `ui_net_sink`**(:7003)的完整帧周期:请求拾取(10ms 拍)+ 队列 + 发送 + L4 + peer 侧编码 | MCU 探针 + PC | Phase 14(M3),N=50 帧 | 110~200ms(含 peer 100ms 节拍) | 全段(用户真实体感) |
| **L9** | 连接/重监听 | connect→ESTABLISHED;close→relisten 成功 | MCU(net_poll 观测点) | Phase 14(M3) | ≤150ms / ≤10ms | 握手/队列;**≥500ms = D10 的 `osDelay(500)` 路径** |
| **L10** | 日志税 | 一行 60 字符 `printf`(现 fputc 逐字节 @115200)耗时 | MCU | Phase 13 附带(M2) | ≈5ms(**预期值本身偏高**,作为 D6 的量化证据) | D6(信息项) |
| **L11** | uiTask 节拍 | 生产循环实测周期(`osDelay(10)` 之外多花多少 = LVGL 渲染 + 渲染中排空) | MCU 探针 | Phase 14(M3) | 10~15ms | **D5/D9** |
| **Δ** | CH395F 净贡献 | `L8(MCU) − L8(模拟器)`,同一 peer 交替跑 | PC | Phase 14 收尾(M3) | ≤80ms | 直接回答"网络延迟"占多少 |
\* 初始阈值取自《远程显示延迟分析》§1.2/§1.3 的静态推算;首块台架实测后按 §4 重锁。
## 2. 测试架构
### 2.1 文件与注册
| 文件 | 职责 | 注册 |
|---|---|---|
| `test/net_latency_test.h` | 计时/统计/报告 API + Phase 入口声明 | 头文件随工程包含路径,无需注册 |
| `test/net_latency_test.c` | DWT µs 时基 + 统计 + Phase 12 用例(M1);Phase 13/14 用例(M2/M3 追加) | **仅 `MDK-ARM/STM32F407-Demo.uvprojx`**(Test 组;模拟器 CMake 不编 `test/*.c`,与现有测试文件一致) |
| `test/latency_peer.py` | PC 端 peer(纯标准库):`--mode net`(M2)/`--mode remo`(M3),`--samples N`,`--json out.json` | 无(Python) |
| 本文档 | 规划/流程/判定表/基线 | — |
### 2.2 阶段编号(沿用 `ch395f_test.h` 互斥体系)
```
ENABLE_PHASE12_TESTS [硬] SPI 时延基线(L1/L2)—— testTask 独占 CH395F,**无需 PC**
ENABLE_PHASE13_TESTS [网] 芯片+队列时延(L3~L7/L10)—— 需 latency_peer.py --mode net (M2)
ENABLE_PHASE14_TESTS [网] 生产路径时延(L8~L11 + Δ)—— 真实 uiTask/:7003,peer --mode remo (M3)
```
- Phase 12 归 HW 组,13/14 归 NET 组 → 与现有"两层互斥 `#error`"自动兼容;
- 13 与 14 同属 NET 组可同启(13 用 testTask 私有监听端口,14 用生产 :7003,socket 不冲突);
- 全部非破坏性 → 只读级,**台架执行**。
### 2.3 时基(DWT CYCCNT)
- 工程内首个 DWT 用户(`sys_clock` 是纯 HAL tick,无 µs 能力);`lat_time_init()` 幂等使能
`CoreDebug->DEMCR | TRCENA` + `DWT->CYCCNT=0` + `DWT->CTRL | CYCCNTENA`;
- 分辨率 1/168MHz ≈ 5.95ns;换算用 `SystemCoreClock`(不写死频率);
- **32 位回绕 = 25.17ms**:M1 各段(<5ms)安全;M2/M3 的长段(整帧/重传尖峰)改用
**累积采样**(等待循环中每 ~10ms 采样一次计数差并累加),届时在 Phase 13/14 代码内实现;
- 每次运行先打一行校准线 `[LAT] cal core_clk=...`,台架可用逻辑分析仪核对时基正确性。
### 2.4 统计与报告格式
- 每段 N 次采样(静态数组,零堆):`min / med / p95 / max` + `spikes`(≥ 尖峰阈值计数);
- MCU 串口报告行(**纯 ASCII**,`verify_log.py` 可校验):
```
[LAT] run_id=<tick> phase=12
[LAT] cal core_clk=168000000 us_per_1024cyc=6
[LAT] seg=spi_cmd_getver n=100 min=10 med=10 p95=10 max=12 us spikes=0
[LAT] seg=spi_dma_1024 n=100 min=1611 med=1611 p95=1612 max=1612 us spikes=0
[LAT] verdict=OK seg=spi_dma_1024 (med=1611us warn<=3200 crit<=6400 spikes=0/0)
[LAT] summary verdict=OK
[LAT] report complete
```
- verdict 语义:`OK`(全部段达标)/ `WARN`(某段 med 超 warn 阈值,**计 PASS**,提示重锁阈值)/
`FAIL`(某段 med 超 crit 阈值或 spikes 超限 → 套件判 FAIL);
- **字段名刻意用 `crit` 而不用 `fail`**(2026-09-22 首跑实证):`verify_log.py` 默认
Forbidden 集含大小写不敏感的 `FAIL`,报告行里出现 `fail<=` 字面量会把**自己的 OK 行**
判成 Forbidden 命中;`verdict=FAIL` 行才是真正的失败信号,须被捕获;
- 校验标记(**按构建模式区分**,`Network Init` 仅 netTask 的 NET 分支打印,硬件层模式
netTask 自挂起 → 无此标记):
- 硬件层(Phase 12):Required `App init OK;net init: OK;PHY: 100M FULL;[LAT] report complete`
- NET 层(Phase 13/14):Required `App init OK;Network Init;net init: OK;[LAT] report complete`
- **Forbidden 必须覆盖默认集**(2026-09-22 首跑实证):套件 TEST_REPORT 行
`(... failed=0)` 含 "fail" 子串会被默认 `FAIL` 模式自捕获 →
`--forbidden "HardFault;assert;[ERR];[FAIL];verdict=FAIL"`
(真失败仍被捕获:TEST_CHECK 失败行含 `[FAIL]`+`[ERR]`,时延段失败含 `verdict=FAIL`)
- **M2 追加判定**(Phase 13):Required 再含 `=== Phase 13: 1/1 PASSED`;peer 侧以
**退出码 0**(收到 `0xFF` 并打印汇总)= PASS,JSON 里 `l7_crc.fail == 0` 为帧格式正确性证据。
### 2.5 PC 端 peer 与关联(M2/M3)
- `latency_peer.py`:纯标准库(socket/json/time/argparse);`--mode net` 走测试协议
(M2 已实现),`--mode remo` 模拟 DTU-RemoteLCD 客户端(M3);
输出每帧 `req2first / total / recv 批次到达时间` + 直方图 + spike 计数 + JSON 报告;
- **M2 测试协议(`--mode net`,端口 8080,服务器驱动,MCU 逐个下发操作字节)**:
| 操作 | 值 | 语义 | peer 侧动作 |
|---|---|---|---|
| HELLO | `5A A5 58 01` | 会话起始 | 连接后立即发送;MCU 识别后重置会话状态机 |
| L5_RECV | `0x01` | 对端灌入 | 20×100B,**50ms 间隔**(≈2KB/s,低于 MCU 抽干速率);测非阻塞收的队列往返 |
| L5_SEND | `0x02` | MCU 连发 | 收 2000B(20×100B 阻塞发) |
| L6 | `0x03` | 小请求/回显 | 发 10B 模式请求 → 校验 MCU 原样回显;逐样本重复 |
| L7 | `0x04` | 全帧读取 | 发 9B LCDMEM 请求 → 收 3209B 全帧(4 批),逐样本重复 |
| L3 | `0x05` | 4KB flood | 排空 16×4096B(=64KB);MCU 侧 chunk 等待由探针测 |
| DONE | `0xFF` | 会话结束 | 打印汇总并退出(exit 0 = PASS) |
- **帧格式严格照生产 RemoDispBus**(`ui_net_sink.c` `remo_handle`/`remo_send`):
`[TAG][CMD][LEN_H][LEN_L][DATA][CRC]`,**CRC = 仅对 DATA 段逐字节异或**,
整帧 = 4 + len + 1;LCDMEM 请求 = `AA 03 00 04 00 00 00 00 00`(LEN=4 即"4B 偏移"的
数据段长度,偏移须为 0),应答 = `BB 03 0C 84` + `[偏移u32=0][位图3200B]` + CRC = **3209B**;
- **peer 重试包装**:3 次会话尝试(首次预算 `--wait`,其后 ≤60s),遇连接错误/超时重建连接
并重发 HELLO;MCU 侧 abort 后进"重连等待态"(见 §3.2),两侧构成闭环;
- **尾批诊断/缓解选项(`--mode remo`,均无需抓包)**:`--ack-probe`(帧未收齐时发 1 个解析器忽略的字节,
让 TCP 段捎带 ACK)、`--ack-fast`(Windows 关闭本 socket 延迟 ACK:`SIO_TCP_SET_ACK_FREQUENCY=1`);
两者把帧尾 52ms 降到 3.9ms(结论见 `链路时延实测数据分析.md` §3.3);
- **关联**:`serial.log` 行与 peer JSON 均带**主机时间戳** → 同一时间轴直接合并,无需 NTP;
需要逐段精确视图时再并行跑 Wireshark(`tcp.port==8080`)按时间对齐。
### 2.6 MCU 侧探针(M3,`#ifdef TEST_LATENCY_PROBE`)
产品代码(`net_socket.c`/`ui_net_sink.c`/`ui_task.c`/`ui_port.c`)内各数行打点,
经静态环形缓冲(总计 <1.5KB BSS)上报;**产品构建下该宏未定义,探针代码编译消失**,
两种构建配置都必须过 `@build`(0 错 0 警)。
## 3. 执行流程
### 3.1 M1:Phase 12(SPI 层基线,**无需 PC**)
```powershell
# 0) 前置:test/test_config.h 已启用 TEST_SUITE_CH395F + ENABLE_PHASE12_TESTS
# (当前工作副本已按此配置;产品构建 = 全部注释掉)
# 1) 构建(0 错 0 警)
& "MDK-ARM\build.bat"
# 2) 一键闭环:开串口+清日志 → 烧录(reset.bat flash,Reset&Run)→ wait-idle → 标记校验
# 硬件层模式无 "Network Init" 标记(netTask 自挂起),且 TEST_REPORT 行含 "failed=0"
# → Required/Forbidden 均用下方定制集(见 §2.4)
& '.venv\Scripts\python.exe' test\run_boot_test.py `
--required "App init OK;net init: OK;PHY: 100M FULL;[LAT] report complete" `
--forbidden "HardFault;assert;[ERR];[FAIL];verdict=FAIL"
# 3) 提取 [LAT] 报告行(直接读日志文件最可靠)
& '.venv\Scripts\python.exe' tools\serial_tool\serial_tool.py log --grep "\[LAT\]"
```
台架首跑已完成(2026-09-22):7 段全部 OK、零尖峰、p95≈min(零抖动);§4.1 基线已按实测重锁。
### 3.2 M2:Phase 13(芯片+队列基线,**需 PC peer**)
```powershell
# 0) 前置:test/test_config.h 启用 TEST_SUITE_CH395F,test/ch395f_test.h 仅启用
# ENABLE_PHASE13_TESTS(Phase 13 必须独占 8080 socket,勿与其他 NET 层 Phase 同启)
& "MDK-ARM\build.bat" # 必须 0 错 0 警
# 1) 先 clear 再起 peer(顺序不可反:wait-idle 需要看到会话活跃期)
& '.venv\Scripts\python.exe' tools\serial_tool\serial_tool.py clear
& '.venv\Scripts\python.exe' test\latency_peer.py --host 192.168.1.100 --port 8080 `
--json "docs\测试说明\m2_data\m2_quiet.json" --wait 170 # 后台作业
# 2) 烧录(Reset&Run 不可省)
& "MDK-ARM\download.bat"
# 3) 等空闲:会话本身约 2s,但 peer 首连常因"芯片空闲超时 RST"失败一次并 2s 后重试
& '.venv\Scripts\python.exe' tools\serial_tool\serial_tool.py wait-idle `
--timeout 120 --settle-ms 10000 --max-ms 110000
# 4) 判定:**直接 Grep serial.log 文件**(勿用 log --grep,勿只看 wait-idle)
# Required: "App init OK" / "net init: OK" / "[LAT] report complete" / "=== Phase 13: 1/1 PASSED"
# Forbidden: HardFault / assert / [ERR] / [FAIL] / verdict=FAIL
```
- **会话顺序(run3 重排后的最终顺序)**:HELLO → L5_RECV → L5_SEND → L3 → L10 → L6 → L7 → DONE。
易失步的 RX 协议段(L6/L7)置于末位,避免失步污染前置段;L6/L7 样本数 10,L3 = 16×4KB;
- **abort 后自动进"重连等待态"**(120s):DONTWAIT 轮询 scan `5A A5 58 01` → 命中即
`p13_reinit()` + 重启会话(实测:attempt1 失败后 attempt2 在 +20s 自动接上并跑完);
期间周期自愈(10s 无 peer 且状态仍 LISTENING → 重发芯片重监听),**干净完成后停止自愈**
(否则每 10s 拆建监听器,日志永不静默、台架无法判空闲);
- **安静档判定**:`ftp_stress=0`(不加 `--ftp-stress`),即无 FTP/对时干扰的静默基线。
M3 追加:`--mode remo --port 7003`(生产 RemoDispBus 客户端)+ `--ftp-stress`(E-02 复现)。
M4(可选)将 3.1/3.2 编排为一键 `test/run_latency_test.py`(open/clear/flash/wait-idle/peer/collect/merge/verdict)。
## 4. 判定基线表
### 4.1 M1 段(Phase 12)—— **已按台架首跑实测重锁**(2026-09-22,COM6 台架)
| 段(seg) | 实测 med(首跑,n=100) | 实测 min/max | warn(med >) | crit(med >) |
|---|---|---|---|---|
| `spi_cmd_getver` | **10µs** | 10/12 | 40µs | 100µs |
| `spi_cmd_chkexist` | **15µs** | 15/16 | 40µs | 100µs |
| `spi_cmd_gint16` | **15µs** | 15/16 | 40µs | 100µs |
| `spi_dma_4` | **20µs** | 20/20 | 40µs | 100µs |
| `spi_dma_64` | **114µs** | 114/115 | 250µs | 600µs |
| `spi_dma_1024` | **1611µs** | 1611/1612 | 3200µs | 6400µs |
| `spi_dma_2048` | **3208µs** | 3208/3210 | 6400µs | 12800µs |
- 重锁规则:warn ≈ 2×med,crit ≈ 2×warn(兼顾板间/温度漂移与回归灵敏度:
SPI 时钟减半 → 超 warn;再减半 → 超 crit;DMA 超时 1s → 必超 crit);
- 首跑特征:p95 ≈ min(**零抖动**),时基校准行核对无误(168MHz,6µs/1024 周期);
- DMA 斜率实测 1.56µs/B(≈ 5.25 Mbit/s,与 SPI2 分频 8 @42MHz APB1 设计值一致),
固定开销 ≈ 14µs(CS 切换 + DMA 配置)→ **每 chunk(1KB)SPI 成本基线 = 1.61ms**。
### 4.2 M2 段(Phase 13,芯片 + 队列)—— **已按台架实测重锁**(2026-09-22,COM6 台架;run12/run13/run15 三次独立 PASS)
**MCU 侧(`[LAT]` 报告,安静档 `ftp_stress=0`)**
| 段(seg) | 测量含义 | run12 med(min/max, n) | run13 med(min/max, n) | **run15(最终代码)med(min/max, n)** | warn(med >) | crit(med >) |
|---|---|---|---|---|---|---|
| `queue_rt_recv` | L5 对端灌 100B×20@50ms,MCU 非阻塞收的队列往返 | 6014µs(5365/6020, 19) | 6007µs(5392/6025, 20) | **5997µs**(5513/6033, 20) | 10ms | 100ms |
| `queue_rt_send` | L5 MCU 阻塞发 100B×20 | 986µs(836/1204, 20) | 987µs(833/1209, 20) | **987µs**(838/1209, 20) | 10ms | 100ms |
| `chunk_wait` | L3 16×4KB,芯片 chunk 内 SENBUF 等待(探针) | 235µs(215/238, 64) | 219µs(213/377, 64) | **219µs**(214/381, 64) | 10ms | 500ms(spike) |
| `logtax_line` | 60 字符 printf @115200(本地) | 4396µs | 4396µs | **4396µs**(4394/4422) | 10ms | 25ms |
| `req2first_mcu` | L6 10B 请求到齐 → 回显发出 | 310µs(296/338, 10) | 318µs(263/361, 10) | **319µs**(308/338, 10) | 20ms | 200ms |
| `fullframe_mcu` | L7 9B 请求 → 3209B 全帧发给芯片(netTask 内 4 分块) | 6021µs(5986/6103, 10) | 6052µs(5966/6078, 10) | **6028µs**(5991/6066, 10) | 50ms | 500ms |
**PC 侧端到端(peer JSON,含线路 + Windows 栈)**
| 段 | run12 med(min/max) | run13 med(min/max) | run15 med(min/max) | 说明 |
|---|---|---|---|---|
| L6 端到端(op→收到回显) | 12.5ms(5.5/16.0) | 13.8ms(5.9/16.0) | 8.9ms(6.3/16.0) | 比 MCU 侧 `req2first_mcu` 多 ~10ms → PC/线路段 |
| L7 首字节 | 10.9ms(7.9/16.2) | 11.8ms(7.5/17.7) | 11.3ms(7.8/16.5) | 同上量级 |
| L7 全帧 3209B | 61.1ms(54.2/61.5) | 61.7ms(59.9/70.9) | 57.9ms(52.6/72.3) | 每帧固定 4 个 recv 批次 |
> **⚠ 测量方法学(run14 实证)**:探针不得在 net 热路径逐调用打日志——曾加 `[NET] wait pick/block`
> 两行后日志量 40KB → 1.04MB(9,644/9,779 行 = 98.6%),115200 下冲掉 `[LAT]` 证据行
> (段行被截断/丢失)、`wait-idle` 永远判不出空闲,且把 `queue_rt_send` med 从 **987µs 抬到
> 7685µs**(约 7.8×)、`queue_rt_recv` p95 抬到 21ms —— 即"观测行为本身改变被测对象"。
> 该轮(run14)的 MCU 侧数据**不作为基线**,只保留 peer 侧 PASS 事实。
| L7 CRC 校验 | 10/0 | 10/0 | 帧格式/CRC 正确(生产格式对齐后) |
- **结论一:安静档不存在 500ms 台阶**——三轮 6 段全部 `verdict=OK`、零尖峰、p95≈med;
会话级路径的 MCU 净成本量级为 **~6ms**(`queue_rt_recv`),与 netTask 轮询节拍同量级;
- **结论二:芯片 chunk 级不是瓶颈**——`chunk_wait` med ≈ 219µs ≈ 每 chunk SPI 成本(1.61ms)的 1/7,
说明 `SENBUF_FREE` 等待远小于 SPI 搬运本身;
- **结论三(M2 关键发现,待 M3 定性)**:L7 全帧的 **最后 137B 尾巴稳定迟到 ~50ms**——
10/10 帧的前 3 批 1024B 在 ~4ms 内到齐,第 4 批 137B 落在 +50ms(如 first=7.46ms、
尾批 61.20ms);该尾批主导整帧时长(total ≈ 61ms),MCU 侧发完 3209B 仅 6.0ms
→ 延迟不在 MCU 发送路径,而在**芯片 TCP 尾段发送/对端 ACK 交互**(候选:Nagle 式
小段等待 + 对端延迟 ACK)。M3 用 Wireshark 验证后再定对策(勿在未证实前改协议);
- 重锁规则:warn ≈ 现状 ×1.7~10(保留回归灵敏度),crit 取"明显故障"档;
`chunk_wait` 仍以 500ms spike 为 crit(D1 重传指纹)。
### 4.3 M3 段(Phase 14,生产路径 + 模拟器 Δ)—— **已按台架实测重锁**(2026-09-22,COM6 台架)
**MCU 侧(`[LAT]` 报告,真实 uiTask + `ui_net_sink` :7003)**
| 段(seg) | 测量含义 | 实测 med(min/max, n) | warn(med >) | crit(med >) |
|---|---|---|---|---|
| `ui_loop`(L11) | uiTask 生产循环实测周期(渲染+轮询+osDelay(10)) | **10986µs**(10970/21000, 120) | 25ms | 50ms |
| `prod_cycle_mcu`(L8) | LCDMEM 取 1bpp + 组帧 + net_send 4 分块(不含 10ms 拾取拍) | **7142µs**(7111/7179, 50) | 20ms | 200ms |
| `relisten`(L9) | 断线后 auto-relisten 全程(**修复后**:单次尝试 + netTask 延迟重试) | **89000µs ×3**(三次同值) | 100ms | 500ms |
> `relisten` 阈值重锁:修复前 588000µs(Trap 09 `osDelay(500)` 忙等)→ crit 500ms 即 D10 指纹;
> **D10 修复后实测 89ms**(= 30ms 重试间隔 + 约 60ms 芯片沉降),故 warn 由 50ms 放宽到 **100ms**,crit 保持 500ms
> (仍能捕获"退回阻塞重试"的回归)。修复前后对照见 `链路时延实测数据分析.md` §7.1。
**PC 侧端到端(peer `--mode remo`,与模拟器 A/B)**
| 指标 | 真机(65 帧) | 模拟器(50 帧) | Δ(真机−模拟器) | 阈值 |
|---|---|---|---|---|
| 帧周期 total | **66.0ms**(53.3/75.3) | **6.8ms**(0.6/13.1) | **+59.2ms** | ≤80ms |
| 首字节 | 13.9ms(8.5/19.1) | 6.7ms(0.5/13.0) | +7.2ms | — |
| **尾批延迟 tail lag** | **52.6ms**(43.3/61.5) | **0.0ms**(0/0.1) | **+52.6ms** | — |
| 帧 CRC / 位图非平凡 | 65/0、65/65 | 50/0、50/50 | — | 全通过 |
| 连接 / 断开重连(+INIT) | 2.6ms / 23.5~34.7ms | 10.5ms / 32.0ms | — | ≤150ms |
- **一帧预算闭合**:66.0ms ≈ 拾取调度 6.8ms + MCU 净处理 7.1ms + **芯片尾批 52.6ms**;
尾批 = 不满块的 137B(=3209−3×1024),**与负载无关**(压力档 tail 中位 52.2ms 与安静档 52.6ms 一致);
- **控制实验(都不需要抓包工具)**:① 同一客户端打模拟器 tail=0 → 非 PC 栈;② M2 `L3` 满块批量(16×4096B=64KB/125.4ms ≈2ms/KB)
无尾批惩罚 → 满 MSS 段不受影响;③ 压力档下尾批不变 → 属芯片 TX 行为,非调度拥塞;
- **根因(M3 已证实)**:芯片 **MSS=1024**、发送 FIFO=1024B → MCU 每次 1024B 写 = 一个**满 MSS 段**(立即发),
而帧尾 137B 是**次 MSS 段** → 被 Nagle 扣住等 ACK;**Windows 的对端延迟 ACK** 使该 ACK 晚到 ~50ms;
- **解法(客户端侧,实测)**:`--ack-probe`(帧未收齐即补 1 个解析器忽略的字节,捎带 ACK)或 `--ack-fast`
(Windows 每 socket `SIO_TCP_SET_ACK_FREQUENCY=1`)→ tail **52→3.9ms**、帧周期 **65.5→13.7ms**;
**设备侧无可行解**(帧长 3209 为质数、TX FIFO=MSS、CH395F 命令表无 Nagle/立即发送开关)。
**压力档(`--ftp-stress`,E-02 复现)**
| 分桶 | n | med | p95 | max | 尖峰(≥500ms) |
|---|---|---|---|---|---|
| quiet | 15 | 65.9ms | 75.8ms | 75.8ms | 0 |
| stress | 30 | 69.1ms | 75.6ms | **17717.9ms** | **1** |
- 受压首帧等待 **17.7s**(= FTP 客户端空闲时长),`QUIT` 后立即恢复 55~75ms 正常服务;
- 机制:`lftpd` 控制行用**阻塞** `net_recv(0)`,而 netTask 是全部 socket 操作的唯一执行者 → 单会话可冻结全网;
- 上限:单次 recv 受 `NET_RECV_TIMEOUT_MS`(30s) 限制,但 `read_line` 会再次阻塞 → **空闲 FTP 连接可长期占用 netTask**。
> 完整分析(时间预算拆解、三区制、缺陷量化、修复优先级)见 **`链路时延实测数据分析.md`**。
## 5. 里程碑
| 里程碑 | 内容 | 验收 | 状态 |
|---|---|---|---|
| **M1** | 计时助手(DWT µs)+ Phase 12(L1/L2 SPI 基线)+ 本文档 + uvprojx 注册 | `@build` 0/0;`@test` 出 `[LAT]` 报告;产出 L1/L2 首份基线 | **完成**(2026-09-22 台架首跑 PASS,7 段全 OK,基线已重锁) |
| **M2** | `latency_peer.py`(--mode net) + Phase 13(L3~L7/L10)+ `[LAT]` 标记进 @test | 台架首跑产出"芯片+队列"基线;可回答"500ms 台阶是否存在" | **完成**(2026-09-22 台架,run12/run13/run15 三次独立 PASS;6 段全 OK、零尖峰;顺带根治 net 层 D12 通知值缺陷;§4.2 已重锁;产出 `docs/测试说明/m2_data/`) |
| **M3** | Phase 14:`TEST_LATENCY_PROBE` 探针 + `--mode remo` + 模拟器 Δ 对照 + 压力档(E-02 复现)+ §4.2 定稿 | 完整判断依据:任一段超标 → 故障对照表 | **完成**(2026-09-22 台架:L8/L9/L11 + Δ + E-02 全部实测;D10 量化为 588ms、E-02 量化为 17.7s;产出 `m3_data/` 与 `链路时延实测数据分析.md`) |
| **M4(可选)** | `run_latency_test.py` 一键编排 | 一条命令出报告 | 待排期 |
| **M5(可选,在役设备)** | 非独占采样器:事件触发,10s 旁路打点入 syslog | 现场不动台架也能测生产链路 | 设计预留 |
## 6. 故障对照表(哪段超标 → 查什么)
| 现象(段超标) | 首要怀疑 | 动作 |
|---|---|---|
| L1/L2 超 fail | SPI 走线/PCB/SPI2 分频或 DMA 配置 | 对照 `docs/问题记录/CH395F_Trap_Records.md`;逻辑分析仪抓 SCK/CS |
| L3 spike ≥500ms | **D1 重传 / D7 链路** | Wireshark `tcp.analysis.retransmission`;查 PHY 协商/网线/Wi-Fi |
| L3 基线(非 spike)抬高 | 芯片发送路径 / 中断响应 | 对照 CH395F 手册 §5.17/5.18;`GET_CMD_STATUS` 逐段核对 |
| L5 压力档爆表 | **D3(E-02 头阻塞)** | 定位触发源(阻塞 recv 的 FTP/对时)→ 方案 S6 |
| L5/L6 静默档抬高 | D5 调度(任务抢占/节拍) | 查任务优先级与 osDelay;`stack_report.py` 核对栈水位 |
| L6/L7 整体抬高且 L1~L5 正常 | 线路+PC 段(L4) | Wireshark 段间间隙;`Δ` 对照定位 MCU 侧净贡献 |
| **L7 尾批固定迟到 ~50ms**(M2/M3 实测) | **已定性(无需抓包)**:芯片 MSS=1024 → 帧长 3209=3×1024+**137**,末段是次 MSS 段被 Nagle 扣住,等对端 ACK;**Windows 延迟 ACK** 把这一等推迟 ~50ms | **客户端侧解法已实测**(见 `链路时延实测数据分析.md` §3.3):帧未收齐时补发 1 字节捎带 ACK(`--ack-probe`)或关本 socket 延迟 ACK(`--ack-fast`)→ tail **52→3.9ms**、帧周期 **65.5→13.7ms**;**设备侧无解**(帧长为质数、TX FIFO=MSS、CH395F 无 Nagle 开关),不必再投入 |
| **L5 出现重复投递**(收到 > 发送) | **D11**:芯片 TCP RX 饱和下重复递交 + 过度 ACK | 降低灌入速率/加抽干;见 §6 下方 D11 行 |
| **会话在 L6/L7 无征兆失步**(结果错位/挂死) | **D12**:net 层任务通知值语义(清除掩码必须全 1 + 以返回值判定;32 位整体作结果) | 见 §6 下方 D12/D12-a 行;核对 `net_wait_result` 与 `net_process_messages` 的通知打包 |
| **L7 一直超时 / peer 报 `l7_crc.fail`** | **D15**:测试帧与生产 RemoDispBus 格式不一致 / peer 超读吃掉操作字节 | 见 §6 下方 D15 行;对照 `ui_net_sink.c` 的 `remo_send`/`remo_handle` |
| **会话跑完一段后无限循环、peer 空等 300s** | **D16**:Phase 13 状态机迁移目标错(L7 曾回跳 L3) | 见 §6 下方 D16 行;最终顺序 L5→L3→L10→L6→L7→DONE |
| **`[LAT]` 段行缺失/截断、wait-idle 判不出空闲** | **D12-b**:探针在 net 热路径逐调用打日志(日志洪水) | 见 §6 下方 D12-b 行;删除热路径日志 |
| **`relisten` 段 FAIL、每次断线固定 ~588ms** | **D10**:`net_relisten_locked` 的 Trap 09 重试含 `osDelay(500)`(netTask 忙等) | **已修复**:单次尝试 + netTask 延迟重试(间隔 30ms/上限 2s)→ 实测 **89ms 且不阻塞**;另:客户端 600ms 内重连被拒的问题同时消除 |
| **远端显示整帧卡住十几秒后自恢复** | **E-02**:`lftpd` 阻塞 `net_recv(0)` 占用 netTask | **已修复**:控制行/数据读改分片有界读(`net_recv_to` 5ms 片 + 每片让出 1ms,总预算仍 30s)→ 受压帧 **17.7s → 74.7ms(max 106.8ms,零尖峰)** |
| **INIT 应答帧字节数字段恒为 0** | **D17**:`remo_send_init` 只发出 8B 数据段的前 6B(u32 被截半) | **已修复**:改发 8B(字段定义本就是 `[W u16][H u16][FB u32]`)→ peer 读到 **framebytes=3200**;协议文档已同步勘误 |
| **同一 FTP 会话内第二个数据连接失败(425)** | **D20**(已定位未修,见 `链路时延实测数据分析.md` §7.4) | 准确条件 = **每次开机后的第一个 FTP 会话**在其第 2 个数据连接失败(之后会话 4/4 通过);日志签名 = 数据连接建立后 ~10ms 芯片把新连接拆掉(`DISCONNECTED (chip tcp=0x00)`)→ `accept aborted` → 425。属芯片"同一 Socket 快速复用"竞态;已回退两次不稳定修法,保留安全硬化(陈旧 DISCONNECT 甄别 + 2 字节状态缓冲越界修复)。复现:`test/ftp_regression.py`;后续优先做数据 Socket 轮换,现场可用客户端重试规避 |
| **`[LAT]` 多段数值雷同 / 全 0 却 verdict=OK** | **D18/D19**(测试工装):多站点共用全局探针窗口跨段污染;漏调 `lat_time_init()` → DWT 恒 0 假绿 | 均已修复:`lat_probe_add_seg()` 按段名过滤 + 补时基初始化 + `med==0` 判无效 |
| **连接建立后 15~30s 无流量即被 RST** | **D13**:芯片空闲超时(MCU 尚未就绪) | 见 §6 下方 D13 行;客户端须容忍并重连 |
| **peer 重连后 MCU 状态滞留、新连接字节被吞** | **D14**:芯片静默回收 Socket(无 DISCONNECT 中断) | 见 §6 下方 D14 行;用 `net_resync_listen`/`net_relisten` 自愈 |
| L8 超而 L7 正常 | 生产路径附加成本(uiTask 节拍/LVGL/日志) | 对照 L10/L11;方案 P0-b/S7/S8 |
| L9 relisten ≥500ms | **D10 `osDelay(500)` 重试路径** | 方案 S6(非阻塞重试) |
| Δ 显著 >80ms | CH395F 栈净开销异常 | 回到 L1~L9 逐段排查 |
### 6.1 M2 台架实证缺陷与修复(D11~D14)
| 编号 | 现象(台架实证) | 根因 | 修复/状态 |
|---|---|---|---|
| **D11** | L5 灌入 5000B 时对端实收 11884B(+138%)并触发过度 ACK → 对端 RST | 芯片 TCP RX 缓冲饱和下重复递交(retransmit 再投递) | 灌入降到 20×100B@50ms + MCU 侧冗余字节守卫(`> 2000 + 2×256` 即 abort)+ L10 后 DONTWAIT 抽干;**未根治(芯片行为),靠应用侧限速规避** |
| **D12** | L7 段 MCU 侧挂死 35s / 结果整段错位(run3~run11) | **net 层结果回传(任务通知值)语义**:`xTaskNotifyWait(0, 0, &v, ...)` 的**清除掩码为 0 = 根本不清值**(FreeRTOS 以位掩码 `ulNotifiedValue &= ~mask` 清值)→ 上一次调用的结果残留,被后续每次零等待重读成"本次结果" → 表现为"结果错位一格"或永久等待 | **已修复(最小改动)**:`net_wait_result()` 两段式 + **清除掩码全 1(读取即消费)** + **以 `xTaskNotifyWait` 返回值 `pdTRUE/pdFALSE` 判定是否已落地**。通知值 **32 位整体仍是结果**(不切分位域)。三次 PASS 验证 |
| **D12-a** | ——(修复过程中自查发现的同类陷阱,务必记住) | ① 若把序列号压进通知值高 16 位,单次结果上限被压到 **32767**,而 `TEST_BUF_SIZE=32768`(Phase 6/8/9)会溢出成 **负数(假错误)**;② 若用 `v != 0` 判定"通知是否已落地",合法的 **0 结果**(`recv` 返回 0 = 对端关闭)会被误判成"无通知"→ 进入阻塞等待 → **永久挂死** | 二者均已避开:不做位域切分;只用返回值判定。**后续改这条路径前必须复核这两点** |
| **D12-b** | 探针日志把测量对象改坏(run14) | 在 `net_wait_result` 内逐调用打 `pick/block` 日志 → 日志量 40KB→1.04MB(98.6% 是这两行)→ 115200 下丢行、`[LAT]` 证据被截断、`wait-idle` 判不出空闲,且 `queue_rt_send` med **987µs→7685µs(7.8×)**、`queue_rt_recv` p95→21ms | **已修复**:删除 net 热路径的逐调用日志(诊断改为在 `[LAT]` 段报告侧聚合)。**规则:热路径禁止逐调用打点** |
| **D13** | 连接建立后 15~30s 无流量即被 RST(`WinError 10054`) | 芯片空闲超时:MCU 尚在启动/忙,握手已在芯片侧完成但无数据 → 芯片 RST | 测试侧:peer 3 次重试包装(run12/13/15 均首连失败、+2s 重连成功);**生产含义**:E-02 类 30s netTask 冻结会让已连客户端被芯片 RST → 触发重连风暴(与 D11/D3 叠加)→ 客户端须容忍重连 |
| **D14** | peer 重连后 MCU 协议状态错乱、新连接 HELLO 被旧会话吞掉(run7 attempt3) | 芯片在 peer FIN 后**静默回收** Socket 回监听且**不发 DISCONNECT 中断** → MCU 侧 `state` 滞留 ESTABLISHED | **已修复(两层)**:① 新增只读 `net_sock_state()` + `net_resync_listen()`(仅修 MCU 侧状态,不发芯片命令——run8 实证发 close 会摧毁芯片侧健康监听器 → 连接永拒 170s);② 新增 `net_relisten()`(无条件芯片侧重监听,含 Trap 09 重试——run9 实证一次性 `net_listen` 落 Trap 09 窗口失败且被静默忽略 → 监听器永久丢失);abort 后按状态分派 + 10s 周期自愈(**干净完成后停止自愈**,否则每 10s 拆建监听器、台架永不判空闲) |
| **D15** | L7 段从未完成:MCU 报 `L7 peer timeout` / peer 收 3210B 且 `l7_crc.fail=1`(run10) | 测试侧两处:① 测试 L7 帧与生产 RemoDispBus 格式不一致(响应 LEN 应为 3204 而非 3200、缺 4B 偏移字段、CRC 应只覆盖数据段、且多发 4B 垃圾;请求 LEN 应为 4);② peer `recv(4096)` **超读**,把下一个操作字节 `0x04` 当帧体吃掉 → 长度 3210 → 校验失败 → peer 关闭 | **已修复**:MCU 建帧/校验与 peer 请求/校验全部对齐生产(`remo_send`/`remo_handle` 语义);peer 改 `recv(min(4096, 剩余))` 有界读;离线自检(正确帧通过、错误 LEN/短帧/坏位图/坏 CRC 全拒) |
| **D16** | 会话跑完 L7 后**永不结束**、L3→L10→L6→L7 无限循环、peer 空等 300s(run11) | Phase 13 状态机 L7 段的迁移目标是 `P13_ST_L3`(run3 重排前的旧顺序遗留)→ 永不下发 `0xFF`(DONE) | **已修复**:L7 → `P13_ST_DONE`;并在该处加注释说明最终顺序为 L5→L3→L10→L6→L7→DONE(防再次回跳) |
## 7. 约束核对(AGENTS.md)
- 每里程碑结束 `@build`(0 错 0 警)+ `@test` 硬件闭环;
- 新 `.c` 注册:`test/*.c` 仅 MCU 端编译 → **只注册 `MDK-ARM/STM32F407-Demo.uvprojx`**(Test 组;
模拟器 CMake 不含 test 文件,与 `ch395f_test_task.c` 等现状一致);
- 新增 C 字符串字面量**纯 ASCII**(`[LAT]` 报告行均为英文),中文只写注释;
- 自研测试代码**零 C 库堆**:样本/缓冲全部静态(M1 新增 BSS ≈ 1.1KB),改前后跑 `scripts/ram_report.py` 留证;
- `testTask` 栈 2048 words:用例函数只用几十字节局部变量;
- 套件互斥宏体系不动:Phase 12 挂 HW 组,13/14 挂 NET 组,`#error` 自动防两层同启;
- 非破坏性:不改 IP/卷/BBT;HW 层阶段独占 CH395F(网络中断)→ 文档标注"台架专用";
- M3 触碰生产代码的探针全部在 `#ifdef TEST_LATENCY_PROBE` 内,产品构建编译消失,两种构建都须过 `@build`。
## 8. 变更记录
| 2026-09-22 | **M2 实现**:`test/latency_peer.py`(`--mode net` 服务器驱动协议 + 重试包装 + JSON 报告);`test/net_latency_test.{h,c}` Phase 13 状态机(HELLO/L5_RECV/L5_SEND/L3/L10/L6/L7/DONE,含 abort 重连等待态与周期自愈);`test/ch395f_test.h` 增 `ENABLE_PHASE13_TESTS`;`test/net_test_task.c` 监听循环在 Phase 13 活动期跳过 `net_accept`(避免与协议消息争抢 netTask 队列)。**net 层(生产代码)修复**:`net_wait_result` 两段式 + 全 1 清除掩码 + 按返回值判定(D12)、`net_sock_state`/`net_resync_listen`/`net_relisten`(D14) |
| 2026-09-22 | **M2 台架调试与判定**(COM6,run1~run15):run1 发现 **D11**(RX 饱和重复投递);run2 修 WOULDBLOCK 误判 EOF;run3~run11 定位 **D12**(`xTaskNotifyWait` 清除掩码 0 = 不清值 → 陈旧结果被重读,L7 挂死或结果错位)、**D13**(芯片空闲 RST)、**D14**(静默回收失步);run10 修 **D15**(L7 帧格式 + peer 超读);run11 修 **D16**(L7→DONE 跳转);run12/run13 两次独立完整 PASS;run14 暴露 **D12-b**(热路径探针日志洪水:9800 行/98.6%,并实测把 `queue_rt_send` 抬高 7.8×)→ 删日志;**run15(最终代码)第三次完整 PASS**(6 段全 OK、零尖峰、`1/1 PASSED`、peer exit 0、wait-idle 15.5s 判空闲),§4.2 按实测重锁 |
| 2026-09-22 | **M2 交付物**:`docs/测试说明/m2_data/`(`m2_quiet.json`=run15 最终代码、`m2_quiet_run13.json`=run13、`m2_quiet_run14.json`=run14(仅 peer 侧有效,MCU 侧因日志洪水不作基线)、`m2_serial_excerpt_run13.txt`=串口 `[LAT]/[NET]` 证据片段、`README.md`=数据说明与逐帧明细);修复 `App/cfg_file.c` BOM 丢失(Edit 剥 BOM → ARMCC 按 CP936 解码中文字面量报 `#870-D`,`@build` 因此首轮 4 警告);生产构建与测试构建均 `@build` 0/0 |
| 2026-09-22 | **M3 实现**:`test/net_latency_test.{h,c}` Phase 14 状态机(ui_loop → prod_cycle_mcu → relisten 三个探针窗口 + `lat_tmark_t`/`lat_mark` 跨 >25ms 安全计时 + `lat_probe_add_seg` 按段名过滤防跨段污染);生产代码探针(`ui_task.c` L11 循环周期、`ui_net_sink.c` LCDMEM 处理净成本、`net_socket.c` relisten 全程,全部在 `#ifdef TEST_LATENCY_PROBE` 内);`test/latency_peer.py` 增 `--mode remo`(生产 RemoDispBus 客户端:INIT/LCDMEM/重连多轮/有界读/JSON 报告/`--ftp-stress` 分桶);`test/ch395f_test.h` 切到 `ENABLE_PHASE14_TESTS` |
| 2026-09-22 | **M3 台架实测**(COM6,run16~run19):修 **D18**(多站点探针跨段污染 → prod/relisten 读出 ui_loop 值)与 **D19**(Phase 14 漏调 `lat_time_init()` → 三段全 0 假绿,并加 `med==0` 判无效);修正运行顺序(**先烧录后起 peer**,否则首帧由旧固件应答);测得 **L11=10986µs、L8(MCU)=7142µs、L9 relisten=588000µs×3(D10 确认)**;peer 侧真机 65 帧 cycle med **66.0ms**、tail **52.6ms**,模拟器 50 帧 cycle med **6.8ms**、tail **0.0ms** → **Δ=59.2ms**;压力档 **E-02 量化 17.7s**(quiet/stress 分桶);新发现 **D17**(INIT 应答 u32 截半 → framebytes 恒 0) |
| 2026-09-22 | **M3 交付物**:新增 **`docs/测试说明/链路时延实测数据分析.md`**(M1+M2+M3 汇总分析:全段基线总表、一帧时间预算拆解、三条对照实验归因、两种数据区制、缺陷量化清单 D10~D19、修复优先级建议);`docs/测试说明/m3_data/`(`m3_dev_quiet.json`/`m3_dev_stress.json`/`m3_sim_quiet.json`);本文档 §4.3 重锁 M3 段、§5 M3 完成、§6 新增 D10/E-02/D17/D18/D19 行 |
| 2026-09-22 | **D20 调查(未完全修复,已定位)**:量化复现条件 = **每次开机后的第一个 FTP 会话**在其第 2 个数据连接返回 425(steady-state 会话 4/4 全通过);设备日志签名 = 数据连接 accept 后约 10~20ms 芯片把新连接拆掉(`sock4 DISCONNECTED, releasing (chip tcp=0x00)` → `data socket closed, accept aborted` → `cmd_stor accept failed` → 425),机制属芯片"同一 Socket 关闭→重开"快速复用竞态(与 D10/Trap 09 同族)。尝试并回退两种修法(① 传输后不关数据连接+复用监听器 → **破坏 FTP EOF 语义**,客户端等不到 EOF 整会话挂死;② 新增 `net_shutdown`(发 FIN 优雅断开)+ 等 auto_relisten 复用 + relisten 兜底 → 部分会话通过但不稳定)。**保留纯增益硬化**:`handle_disconnect_event` 在 ESTABLISHED 态回读芯片 TCP 状态、仍 ESTABLISHED 则丢弃陈旧 DISCONNECT;修复 `net_socket.c` 两处 `ch395f_get_socket_status` **只给 1 字节缓冲**(该 API 输出 2 字节)导致的栈越界 1 字节(`ch395f.h` 补显式告警)。新增复现/回归脚本 `test/ftp_regression.py`(单会话 7 次数据连接 + 1KB/32KB 往返校验)。后续:数据 Socket 轮换、或客户端遇 425 重试。`@build` 测试/产品两构建均 0/0 |
| 2026-09-22 | **尾批解法实装到生产客户端**(`DTU-RemtoeLCD\remo_disp_server.py`):`connect()` 后自动关闭本 socket 延迟确认(Windows:`ctypes` 直调 `WSAIoctl(SIO_TCP_SET_ACK_FREQUENCY=1)`,因 Python `socket.ioctl()` 白名单不接受该码),失败则退化为"入站轻推"(帧中停顿 ≥5ms 补发 1 个 `0x00` 捎带 ACK;`NUDGE_POLL_S=5ms`/`NUDGE_INTERVAL=20ms`/上限 64 次)。用该客户端自身 `connect()+fetch_screen()` 实测:帧耗时 **68.8ms → 20.7ms(Windows 关延迟确认)/ 29.4ms(轻推兜底)**;Web 服务冒烟 HTTP 200 正常。README 增补"延迟确认抑制"章节;分析文档 §3.3 同步记录 |
| 2026-09-22 | **L7/生产帧 ~52ms 尾批定性 + 客户端侧解法(不用抓包工具)**:机理 = 芯片 MSS=1024、发送 FIFO=1024B,MCU 每次 1024B 写为满 MSS 段(立即发送),帧尾 137B(3209=3×1024+137)为**次 MSS 段**被 Nagle 扣住等 ACK,而 Windows 的**延迟 ACK** 使该 ACK 晚到 ~50ms。三组带内实验定性:① 帧未收齐时补发 1 字节(`--ack-probe`,新增)→ tail 52→**3.9ms**;② Windows 每 socket `SIO_TCP_SET_ACK_FREQUENCY=1`(`--ack-fast`,新增,ctypes 调 `WSAIoctl`,不发任何字节)→ tail **3.9ms**(一锤定音:根因在对端延迟 ACK);③ 对照(模拟器 tail=0、满块批量无惩罚)不变。帧周期实测 **65.5→13.7ms**。**设备侧无解**(帧长 3209 为质数、TX FIFO=MSS、手册命令表无 Nagle/立即发送开关)→ 结论与数据写入 `链路时延实测数据分析.md` §3.3,数据文件 `m3_data/m3_tail_ack{probe,fast}.json` |
| 2026-09-22 | **M3 缺陷修复与复验**(当日完成 D10/E-02/D17):**D10** `net_relisten_locked` 去掉 `osDelay(500)` 忙等 → 单次尝试 + `netTask` 每轮延迟重试(`net_relisten_try`/`net_relisten_retry_tick`,间隔 30ms/上限 2s,含防饥饿与防 fd 残留)→ relisten **588ms → 89ms** 且不再冻结 netTask,`[LAT]` 段由 FAIL 转 **OK**(阈值按实测重锁 warn 100ms);**E-02** `lftpd` 控制行/数据读改**分片有界读**(新增 `net_recv_to` + `net_msg_t.timeout_ms`;5ms 片 + 每片 `vTaskDelay(1)` 让出 CPU,总预算仍 30s)→ 受压帧 **17718ms → 74.7ms(max 106.8ms,零尖峰)**;**D17** `remo_send_init` 由 len=6 改 **8** → INIT 应答 `framebytes` **0 → 3200**,协议文档同步勘误。修复后安静档无回归(65.7ms vs 66.0ms)。另经 git 回退版 A/B 双跑确认 FTP 行为完全一致(并记录既有缺陷 **D20**:同一会话第二个数据连接恒 425);修复过程暴露"Copy-Item 还原保留旧 mtime → Keil 跳过重编译"的工作流陷阱,已写入 `链路时延实测数据分析.md` §7.2。`@build` 测试/产品两构建均 0/0 |
| 2026-09-22 | 创建:完整规划(分段/架构/流程/基线/里程碑);**M1 实现**(`test/net_latency_test.h/.c`:DWT µs 时基 + 统计报告 + Phase 12 SPI 字节命令/DMA 时延基线;`ch395f_test.h` 增 `ENABLE_PHASE12_TESTS`;uvprojx Test 组注册) |
| 2026-09-22 | **M1 台架首跑**(COM6):7 段全 OK、零尖峰、p95≈min;`spi_dma_1024` med=1611µs(每 chunk SPI 成本基线)。按实测重锁 §4.1 阈值(代码 `LAT_P12_CMD_*`/`a_p12_dma_warn/fail` 同步更新);修复报告行 `fail<=` → `crit<=`(防默认 Forbidden 自捕获);确定硬件层/NET 层两套 Required 标记集(硬件层无 `Network Init`)+ 测试构建 Forbidden 定制集(`TEST_REPORT` 行 `failed=0` 会自捕获默认 `FAIL` 模式);`test_parse_ip` 守卫精确到 Phase 2/5(仅 Phase 12 构建的 #177-D 实证)。`@test` 复跑 PASS |
@@ -0,0 +1,344 @@
# 链路时延实测数据分析(M1 + M2 + M3 汇总)
> 本文是**测量数据的汇总分析**:把 M1(SPI)、M2(芯片+队列)、M3(生产路径 + 模拟器 Δ + 压力档)
> 三轮台架实测数据放在一起,回答一个工程问题——**远端显示"每帧要多久、慢在哪一段、能不能改"**。
>
> - 测试规划/流程/判定阈值:`链路延迟测试说明.md`(本文 §6 的阈值与之一致)
> - 原始数据:`m2_data/`、`m3_data/`(JSON + 串口证据片段),本文所有数字均可回溯到这些文件
> - 台架:COM6 @115200,STM32F407ZGTx @168MHz + CH395F(SPI2 分频 8),2026-09-22,安静档无外部干扰
> - 代码版本:M3 = Phase 14 构建(`TEST_SUITE_CH395F` + `ENABLE_PHASE14_TESTS`),`@build` 测试/产品两构建均 0 错误 0 警告
---
## 1. 一句话结论
**远端显示的一帧(3209B 全帧)端到端实测中位 66.0ms,其中约 52.6ms(79%)是帧尾那 137B 小段的等待**;
MCU 侧真实处理只占 7.1ms,任务拾取/调度约 6.8ms。同一客户端、同一台 PC 打 PC 模拟器只要 6.8ms(Δ = 59.2ms,且模拟器**完全没有**这个尾批延迟)。
→ **根因已确认(§3.3,无需抓包即可判定):芯片按 Nagle 扣住帧尾的次 MSS 段(MSS=1024,帧长 3209=3×1024+137),
等对端 ACK;Windows 的延迟 ACK 把这一等推迟了 ~50ms。**
**解法在客户端一侧**(帧未收齐时补发一个字节以捎带 ACK,或关闭本 socket 的延迟 ACK):实测 tail **52→3.9ms**、帧周期 **65.5→13.7ms(≈4.8×)**,**协议与设备代码都不需要改**。
另有两个**生产级缺陷**被本轮量化,并已于当日**修复 + 台架复验**(详见 §7):
- **D10**:断线自动重监听固定 **588ms**(Trap 09 的 `osDelay(500)` 忙等,期间 netTask 完全冻结)→ 修复后 **89ms 且不阻塞**;
- **E-02**:一条**空闲的 FTP 控制连接**让 netTask 阻塞 **17.7s**(远端显示整帧无响应)→ 修复后受压帧 **med 74.7ms / max 106.8ms,零尖峰**;
- **D17**:`INIT` 应答把 `帧字节数u32` 截成 6B 发出 → 客户端读到的帧字节数**恒为 0** → 修复后**正确返回 3200**。
修复后安静档无性能回归(帧周期 65.7ms vs 修复前 66.0ms,尾批 50.6ms vs 52.6ms)。
---
## 2. 全段基线总表(台架实测)
| 段 | 含义 | 实测(med) | min/max | n | 阈值 warn/crit | 判定 |
|---|---|---|---|---|---|---|
| **L1** `spi_cmd_*` | SPI 字节命令(3 条) | 10 / 15 / 15µs | 10~16µs | 100 | 40/100µs | OK |
| **L2** `spi_dma_*` | SPI DMA 读(4/64/1024/2048B) | 20 / 114 / **1611** / 3208µs | ±2µs | 100 | 见 §4.1 | OK |
| **L3** `chunk_wait` | 写发送缓冲 → `SENBUF_FREE`(每 chunk) | **219µs** | 213/381µs | 64 | 10ms/500ms | OK |
| **L5** `queue_rt_recv` | 调用方 `net_recv(DONTWAIT)` 队列全程 | **5997µs** | 5513/6033µs | 20 | 10ms/100ms | OK |
| **L5** `queue_rt_send` | 调用方 `net_send` 队列全程 | **987µs** | 838/1209µs | 20 | 10ms/100ms | OK |
| **L6** `req2first_mcu` | 10B 请求到齐 → 回显发出(MCU 侧) | **319µs** | 308/338µs | 10 | 20ms/200ms | OK |
| **L7** `fullframe_mcu` | 9B 请求 → 3209B 全帧交给芯片 | **6028µs** | 5991/6066µs | 10 | 50ms/500ms | OK |
| **L8** `prod_cycle_mcu` | **生产路径**:LCDMEM 取帧+组帧+net_send(MCU 净成本) | **7142µs** | 7111/7179µs | 50 | 20ms/200ms | OK |
| **L10** `logtax_line` | 一行 60 字符 `printf` @115200 | **4396µs** | 4394/4422µs | 10 | 10ms/25ms | OK(D6 量化) |
| **L11** `ui_loop` | uiTask 生产循环实测周期 | **10986µs** | 10970/21000µs | 120 | 25ms/50ms | OK |
| **L9** `relisten` | 断线后自动重监听耗时(MCU 侧) | **588000µs** | 588000µs ×3 | 3 | 50ms/500ms | **FAIL(D10)** |
| **L4/L8** peer cycle | 生产客户端完整帧周期(发→收齐 3209B) | **66.0ms** | 53.3/77.4ms | 65 | — | 见 §3 |
| **Δ** | `peer cycle(设备) − peer cycle(模拟器)` | **59.2ms** | — | 65/50 | ≤80ms | 见 §4 |
数据来源:L1/L2 = `链路延迟测试说明.md` §4.1;其余 MCU 侧 = M2 run15 / M3 run18 串口 `[LAT]` 行
(`m2_data/m2_serial_excerpt_run15.txt`、`m3_data/` 各 JSON);peer 侧 = `m3_data/*.json`。
---
## 3. 生产路径一帧的时间预算(M3 核心结果)
同一客户端(`latency_peer.py --mode remo`,100ms 节拍)对**真机 :7003** 与**PC 模拟器 :7003** 各跑一轮:
| 指标 | 真机(65 帧) | 模拟器(50 帧) | 差值 |
|---|---|---|---|
| 帧周期 total(发请求 → 收齐 3209B) | **66.0ms**(53.3/75.3,max 77.4) | **6.8ms**(0.6/13.1,max 15.7) | **+59.2ms** |
| 首字节 first byte | 13.9ms(8.5/19.1) | 6.7ms(0.5/13.0) | +7.2ms |
| **尾批延迟 tail lag**(末批 → 首批) | **52.6ms**(43.3/61.5) | **0.0ms**(0/0.1) | **+52.6ms** |
| recv 批次数/帧 | 5(8B 头 + 1016 + 1024 + 1024 + **137**) | 2 | — |
| CRC / 位图非平凡 | 65/0、65/65 | 50/0、50/50 | — |
**真机 66.0ms 的构成**(三段相加 ≈ 66.5,闭合):
```
[T+0] 客户端发 9B LCDMEM 请求
[T+6.8ms] 实测推算:uiTask 10ms 轮询拾取 + netTask 调度(≈ L11 的一半)
[T+13.9ms] 首字节到达 = 6.8 + MCU 净处理 7.1ms(prod_cycle_mcu:取 1bpp + 组帧 + net_send 4 分块)
[T+66.0ms] 全帧收齐 —— 最后的 137B 尾巴比前三批(1024B×3,前 4ms 内到齐)晚 52.6ms
```
- 前三批 1024B 在**首字节后约 4ms 内**全部到齐;
- 第 4 批只有 **137B = 3209 − 3×1024**(不满块),固定迟到 43~62ms;
- 该延迟**与负载无关**:压力档下 tail_lag 中位 52.2ms(安静档 52.6ms),说明不是调度/队列拥塞,而是**发送侧对不满块尾段的固定惩罚**。
### 3.1 交叉对照实验(三条独立证据 → 归因)
| 对照 | 观测 | 说明 |
|---|---|---|
| ① 同一客户端 → 模拟器 | tail = **0.0ms**,cycle 6.8ms | 客户端栈、Windows、请求格式全部相同 → 尾批**不是 PC 侧**造成 |
| ② M2 `L3` 批量排空(16×4096B,全满块) | 65536B / **125.4ms**(≈2ms/KB) | 16 个满块若各带 50ms 尾巴应 ≥800ms → **满块无此惩罚** |
| ③ 压力档(FTP 头阻塞)下的 L7/生产帧 | tail 仍 43~62ms | 尾批**不受 netTask 拥塞影响** → 属芯片 TX 行为 |
**归因结论(已用带内实验证实,无需抓包)**:3209B 被分块发送后,芯片 TCP 侧对"最后一个不满块的小段"按
**Nagle 规则扣住**(有未确认数据时不发次 MSS 小段),**对端(Windows)的延迟 ACK** 把"解除扣住"的时点推迟了约 50ms
→ 见 §3.3 的三组判别实验(最终由"对端立即 ACK"实验一锤定音:不发任何数据也能把尾批从 52ms 降到 3.9ms)。
### 3.3 尾批 ~52ms:不装 Wireshark 的定性与解法(M3 追加实验)
**机理**(已确认):驱动把芯片 **MSS 设为 1024**(`CH395F_TCP_MSS`),发送 FIFO = 2×512B = 1024B
→ MCU 每次 1024B 写恰好是**一个满 MSS 段**(Nagle 允许满段立即发送);帧长 3209B = 3×1024 + **137B**,
最后这 137B 是**次 MSS 段** → 芯片按 Nagle 扣住,等前一数据被 ACK;Windows 的延迟 ACK 使这个 ACK 晚到 ~50ms。
**判别实验(全部只用现有工具,不需要抓包)**:
| # | 实验 | 做法 | tail_lag(med) | 帧周期(med) | 结论 |
|---|---|---|---|---|---|
| 0 | 基线 | 串行"请求→等整帧→睡 100ms" | **52.0ms** | 65.5ms | 现象复现 |
| 1 | **带内 ACK 探针** `--ack-probe` | 帧未收齐时立刻发 **1 个解析器会忽略的字节**(0x00,非 TAG 0xAA)→ 该 TCP 段**捎带**对已收数据的 ACK | **3.9ms** | **13.7ms** | 扣住**可被对端 ACK 解除** ⇒ 等 ACK(Nagle 式),非芯片固定定时器 |
| 2 | **对端立即 ACK** `--ack-fast` | Windows 每 socket 关延迟 ACK:`SIO_TCP_SET_ACK_FREQUENCY=1`(ctypes 调 `WSAIoctl`,**不发任何探测字节**) | **3.9ms** | **20.7ms** | **根因 = 对端延迟 ACK**(去掉它,尾批自行消失) |
| 3 | 对照:模拟器(同 peer/同 Windows) | — | 0.0ms | 6.8ms | 芯片侧才有该扣住行为 |
| 4 | 对照:满块批量(M2 L3,16×4096B) | — | 无累积惩罚(64KB/125ms) | — | **满 MSS 段不受影响** |
> 实验 1/2 已固化为 peer 选项:`--ack-probe`(可移植:任何 OS/客户端只要在帧未收齐时发一个字节即可)、
> `--ack-fast`(仅 Windows,无需改协议)。原始数据:`m3_data/m3_tail_ackprobe.json`、`m3_data/m3_tail_ackfast.json`。
**可用解法(按推荐度)**:
| 方案 | 做法 | 实测效果 | 代价 / 约束 |
|---|---|---|---|
| **① 客户端"补一个段"** | 帧未收齐时发 1 字节(无效字节即可)或 `KEEPLIVE`,或干脆把**下一个请求提前发** | tail **52→3.9ms**,帧周期 **65→13.7ms**(≈4.8×) | 纯客户端改动,**协议不需变**;无需任何抓包/系统设置 |
| **② Windows 关延迟 ACK** | 每 socket `SIO_TCP_SET_ACK_FREQUENCY=1`(或注册表 `TcpAckFrequency=1`) | tail **52→3.9ms** | 仅 Windows 客户端;注册表方式需管理员+重启 |
| **③ 客户端固定节拍(不串行等待)** | 请求按固定 100ms 节拍发,响应按序收(下一个请求的段天然捎带 ACK) | 尾批同样被提前解除,且显示帧率由 ~6fps 提到 ~10fps | 客户端需按序配对响应 |
| **④ 设备侧** | 无可行解(见下) | — | — |
**生产客户端已实装(2026-09-22)**:`DTU-RemtoeLCD\remo_disp_server.py`(远程显示工具,Web UI + exe 打包)
把上述解法做成两条**自动择一**的路径,连接时打印生效模式:
| 路径 | 触发条件 | 实现 | 实测帧耗时(客户端自身代码,100ms 节拍) |
|---|---|---|---|
| **A. 关延迟确认** | Windows(默认) | `ctypes` 直调 `WS2_32!WSAIoctl(SIO_TCP_SET_ACK_FREQUENCY=1)`——Python `socket.ioctl()` 有控制码白名单,不接受该码 | **20.7ms**(改善前 68.8ms,**3.3×**) |
| **B. 入站"轻推"兜底** | 非 Windows / A 失败 | 收帧途中帧已开始但停顿 ≥5ms → 补发 1 个 `0x00`(装置状态机只认帧头 `0xBB`,丢弃该字节)→ 该段捎带 ACK | **29.4ms**(2.3×) |
> 剩余 ~20ms = 客户端 Python 逐字节解析 3209B + 首字节等待(9~18ms)+ 尾块 ~4ms;
> 该工具的刷新线程为"拉一帧 + 等 100ms",故整体显示帧率由 ~6fps 提升到 ~9fps。
> 两条路径**都不需要改协议、不需要改装置固件**;`connect()` 会打印 `[connect] 延迟确认抑制: ...` 便于现场确认。
**为什么设备侧无解**(避免后续重复投入):
- 帧长 **3209 是质数**,无论 MSS / 分块怎么取,最后一个 TCP 段必然 < MSS(除非补字节改线格式);
- **发送 FIFO = MSS = 1024B**(`NET_SEND_CHUNK_MAX`),单次写不可能超过 MSS ⇒ 无法用"一次写整帧"绕过;
- 手册命令表(`docs/芯片手册/CH395F.md` §5)**没有** Nagle / 立即发送 / TCP_NODELAY 类开关(只有
`CMD_SET_TCP_MSS`、收发缓冲、重传与 keepalive 参数;且手册 §9.2.8 明确"MSS 越小以太网小包越多")。
### 3.4 两种数据区制(对容量规划的启示)
| 区制 | 实测 | 主导成本 | 适用 |
|---|---|---|---|
| **小帧交互**(≤1 chunk 附近) | 3209B → 66ms | **固定尾批惩罚 ~52ms** | LCDMEM 整帧轮询 |
| **批量流式**(多满块) | 4KB/7.8ms、64KB/125ms ≈ 2ms/KB | **SPI DMA(L2 = 1.61ms/KB)** | 大文件/FTP 传数据 |
→ 小帧交互的 52ms 尾批**已定位并给出客户端侧解法**(§3.3:实测可降到 3.9ms);
批量流式仍受 SPI DMA 约束(≈2ms/KB),两者是独立的两条优化线。
---
## 4. 队列与调度:静默档不存在台阶
- **L5 队列往返**:收 5997µs / 发 987µs —— 与 netTask 10ms 轮询节拍同量级,属**调度周期**而非排队拥塞;
`queue_rt_send` 的 987µs ≈ L2 的 1 个 chunk(1611µs)量级,说明发送路径没有额外排队。
- **L3 chunk 级**:219µs ≈ 每 chunk SPI 成本(1611µs)的 1/7 → **芯片 TX 缓冲不是瓶颈**,SPI 搬运才是。
- **L11 uiTask 周期**:10986µs(= osDelay(10) + 渲染开销 ≈ 1ms);窗口内出现 1 次 21ms(开机菜单构建)。
→ **LVGL 渲染只占约 1ms/帧**,uiTask 不是延迟来源。
- **M2 三次完整 PASS(run12/13/15)六段全 OK、零尖峰**:安静档下"500ms 台阶"现象**不存在**;
台阶只在特定条件下出现(见 §5)。
---
## 5. 压力档:两个"秒级冻结"缺陷(E-02 与 D10)
### 5.1 E-02:一条空闲 FTP 控制连接冻结全网 17.7s
`--mode remo --ftp-stress`(第 15 帧起让 FTP 停留在"已 USER、未 PASS"的半登录态):
| 分桶 | n | med | p95 | max | 尖峰(≥500ms) |
|---|---|---|---|---|---|
| quiet(0~14 帧) | 15 | 65.9ms | 75.8ms | 75.8ms | 0 |
| stress(15~44 帧) | 30 | 69.1ms | 75.6ms | **17717.9ms** | **1** |
- 症状:**第 15 帧(受压后第一帧)等待 17.7s 才拿到应答**,期间远端显示完全无响应;
- 恢复:FTP 侧发出 `QUIT` 后**立即恢复** 55~75ms 正常服务;
- 机制:`lftpd` 的 `read_line` 走**阻塞** `net_recv(0)`,而 netTask 是全部 socket 操作的唯一执行者
→ 该阻塞期间**所有**任务的 net 消息(含 uiTask 的 LCDMEM 应答)排队等待;
- 边界:单次 `net_recv` 受 `NET_RECV_TIMEOUT_MS`(30s)限制,但 `read_line` 会再次进入阻塞
→ **只要客户端连接后不发完整行,netTask 就被长期占用**(实测 17.7s = 客户端空闲时长);
- 生产含义:现场一个半开 FTP 连接 / 一次网络抖动中的 FTP 会话,即可让远端显示"整帧不动"十几秒,
与《远程显示延迟分析》里的 D3(E-02 头阻塞)指纹完全一致,**本轮首次给出定量证据**。
### 5.2 D10:断线重监听固定 588ms(Trap 09 `osDelay(500)`)
peer 侧三次"断开 → 1.5s → 重连"(`--reconnect-rounds 3`):
| 通道 | 实测 |
|---|---|
| peer 侧:断开后重连 + INIT | 23.5 / 27.4 / 33.7ms(另两轮 23.2 / 34.7ms) |
| **MCU 侧:auto-relisten 全程** | **588000µs × 3(三次全部 588ms)** → `verdict=FAIL` |
- 588ms ≈ `net_relisten_locked()` 的 Trap 09 重试:**首次 `open` 必失败 → `close` → `osDelay(500)` → 重开成功**;
- 这 500ms 是**真·忙等**(`osDelay` 在 netTask 里)→ 期间同样**全网冻结**;
- 客户端可见影响:**断开后 600ms 内重连会被拒**(监听器尚未恢复);M2 调试期"170s 连接被拒"即该路径失败一次后的连锁表现;
- 判定说明:`relisten` 段 FAIL 是**结论**(阈值 500ms 就是 D10 指纹),不是测试故障。
---
## 6. 缺陷清单与量化(实测汇总)
| 编号 | 缺陷 | 实测证据 | 状态 |
|---|---|---|---|
| **D10** | 重监听走 `osDelay(500)` 阻塞重试 | relisten **588ms ×3**(M3) | **已修复并验证**(588ms → **89ms**,非阻塞;§7.1) |
| **D11** | 芯片 TCP RX 饱和下重复投递(+138%) | M2 run1:发 5000B 实收 11884B + RST | 应用侧限速规避 |
| **D12** | net 层 `xTaskNotifyWait` **清除掩码 0 = 不清值** → 陈旧结果被重读 | M2 run3~11:L7 挂死 35s / 结果整段错位 | **已修复**(全 1 掩码 + 按返回值判定 + 32 位整体结果) |
| **D12-a** | 位域切分与 `v!=0` 判定两个同类陷阱 | code review:32768 溢出为负、0 结果误判挂死 | 已避开并写入注释 |
| **D12-b** | net 热路径逐调用日志 → 观测改变被测对象 | M2 run14:日志 40KB→1.04MB(98.6%),`queue_rt_send` 987µs→**7685µs** | **已修复**(删热路径日志) |
| **D13** | 芯片空闲超时 RST(MCU 未就绪) | M2/M3 每轮首连均 10054,+2s 重连成功 | 客户端须容忍重连 |
| **D14** | 芯片静默回收 socket → MCU 状态滞留 | M2 run7~9 | **已修复**(`net_sock_state`/`net_resync_listen`/`net_relisten`) |
| **D15** | 测试 L7 帧与生产格式不一致 + peer 超读 | M2 run10:收 3210B、CRC fail | **已修复**(对齐 `remo_send`/`remo_handle` + 有界读) |
| **D16** | Phase 13 L7 → 回跳 L3 造成无限循环 | M2 run11:永不下发 0xFF,peer 空等 300s | **已修复** |
| **D17** | **INIT 应答把 u32 截成 6B → 帧字节数字段恒 0** | M3:真机与模拟器均 `framebytes=0`(应为 3200) | **已修复并验证**(发满 8B → `framebytes=3200`;§7.1) |
| **D18** | **多打点站点共用全局探针窗口 → 跨段污染** | M3 run17:prod/relisten 都读出 ui_loop 的 ~11ms 值 | **已修复**(`lat_probe_add_seg` 按段名过滤) |
| **D19** | **Phase 14 漏调 `lat_time_init()` → 全 0 假绿** | M3 run16:三段全 0 却 `verdict=OK` | **已修复**(补初始化 + med==0 判无效) |
| **D20** | **FTP 同一会话的第 2 个数据连接失败(425)** | 复现条件已量化:**每次开机后的第一个 FTP 会话**在该会话第 2 个数据连接处失败(之后的会话 4/4 全通过);设备日志签名 = 数据连接 accept 后约 10~20ms 出现 `DISCONNECTED, releasing (chip tcp=0x00)` → `data socket closed, accept aborted` → 425 | **已定位未修**(详见 §7.4):属芯片"同一 Socket 快速复用(关闭→重开)"的时序竞态;两次修法(优雅断开+复用监听器 / relisten 兜底)都不稳定已回退;**保留安全硬化**(陈旧 DISCONNECT 甄别 + 两处 1 字节栈越界修复);复现脚本 `test/ftp_regression.py` |
| **E-02** | 空闲 FTP 控制连接冻结 netTask(头阻塞) | M3:受压帧 **17718ms**(`QUIT` 即恢复) | **已修复并验证**(→ **74.7ms** med / 106.8ms max,零尖峰;§7.1) |
> D17/D18/D19 为本轮 M3 自查发现(D18/D19 属测试工装缺陷,会导致"绿而无效"的数据);
> D20 为修复过程中的 A/B 对照**顺带发现**的既有缺陷(已用 git 回退版固件双跑确认与本次改动无关)。
---
## 7. 缺陷修复与验证(2026-09-22,修复当日台架复测)
### 7.1 三项已修复缺陷的前后对照
| 缺陷 | 修复内容 | 修复前实测 | **修复后实测** | 判定依据 |
|---|---|---|---|---|
| **D10** | `net_relisten_locked` 去掉 `osDelay(500)` 忙等 → 单次尝试 + `netTask` 每轮延迟重试(间隔 30ms,上限 2s) | relisten **588 000µs ×3**(且 netTask 冻结 500ms) | **89 000µs(89ms)**,`verdict=OK`,期间其他任务不受阻 | `[LAT] seg=relisten` + 日志 `relisten retry ok` |
| **E-02** | `lftpd` 控制行/数据读改**分片有界读**(`net_recv_to` 5ms 片 + 每次让出 1ms,总预算仍 30s) | 受压帧 **17 718ms**,≥500ms 尖峰 1 次 | **med 74.7ms / p95 90.8ms / max 106.8ms,尖峰 0** | `m3_dev_stress_fixed.json`(30 受压帧) |
| **D17** | `remo_send_init` 由 `len=6` 改 `len=8`(字段定义本就是 `[W u16][H u16][FB u32]`) | `framebytes=0`(u32 被截半) | **`framebytes=3200`,`payload_len=8`** | peer JSON `init.geom` |
**修复后安静档(无回归)**:`ui_loop` 10986µs、`prod_cycle_mcu` 7140µs、帧周期 med **65.7ms**、尾批 **50.6ms**、
CRC 65/0、`=== Phase 14: 1/1 PASSED ===` —— 与修复前(66.0ms / 52.6ms)在噪声内一致 ⇒ **修复未引入性能回归**。
**关键实现要点(供后续维护)**:
1. **D10 重试必须防饥饿**:调用方(accept/recv 路径每 10ms 一次)只登记一次重试,实际重试由 netTask 轮询到点执行;
若让调用方每次立即重试并重置时刻,会永不重试。重试间隔 100ms→30ms 后恢复时间 147ms→89ms(芯片沉降约 60ms)。
2. **E-02 分片长度 = 其他任务的最坏等待**:100ms 片下受压帧仍 ~750ms(多片排队),收到 **5ms** 后才降到 ~75ms。
3. **分片循环必须显式让出 CPU**:某片可能因 `net_poll` 自身耗时而在首轮即返回超时 → 本任务(Normal)立即重排队
会形成忙循环并**饿死 BelowNormal 的 uiTask**(实测 2.4~3.4s 周期尖刺);加 `vTaskDelay(1)` 后尖刺归零。
### 7.2 关键教训(工程流程)
修复过程中出现一次**"改了代码但没进固件"**:A/B 对照用 `git checkout` 回退后再用 `Copy-Item` 还原,
`Copy-Item` 保留了**旧 mtime**,比回退版编出的 `.o` 更旧 → Keil 判定"源比目标旧"→ **未重新编译**,
固件里仍是回退版(表现为"改了却没效果")。此后必须在还原后 **touch 源文件**(或核对编译日志里出现该文件)。
排障路径(可复用):在改动处加临时日志 → 若无输出,即可判定"代码没进二进制",先用特征字符串在 `.axf` 里验证。
### 7.4 D20 调查记录(FTP 数据连接 425,未完全修复)
**现象与准确复现条件**(2026-09-22 台架,多轮统计):
| 会话(同一固件、不重启) | 结果 |
|---|---|
| 开机后第 1 个 FTP 会话 | **失败在会话内第 2 个数据连接**:`LIST/NLST` 成功 → 随后的 `STOR` 返回 **425 Can't open data connection**;控制连接随后被对端关闭(客户端见 EOF) |
| 第 2 个及之后的会话(稳态) | **全部 11/11 通过**(含 1KB 与 32KB 的 STOR/RETR 往返、连续 7 次数据连接) |
即:**不是"每会话第 2 个数据连接必失败",而是"每次开机后的第一个会话"才会命中**(此前把两次 A/B 都在开机首会话做的,误判为确定性缺陷)。
**设备日志签名**(首会话失败时):
```
CMD PASV → sock4 standalone accept(数据连接建立)
CMD STOR
sock4 DISCONNECTED, releasing (chip tcp=0x00) ← 建立后 ~10ms 芯片把新连接拆掉
[ERR] data socket closed, accept aborted → cmd_stor accept failed → 425
sock4 auto-relisten ok / relisten retry ok ← 监听器随后自行恢复
```
**机理(已定位)**:FTP 数据通道每次传输结束都要 `net_close`(对端以 EOF 判"传完"),随后下一次 PASV 又要在**同一芯片 Socket**上 `net_socket/bind/listen` 重开;在开机首个会话的时序下,上一条连接的 teardown 与本次重开交叠,芯片在新连接建立后立刻将其拆除(读到 chip TCP = CLOSED)。与 D10(Trap 09 沉降)、D14(静默回收)同属"单连接 Socket 复用"家族。
**试过但未采用的修法**(均已回退,保留结论备查):
| 尝试 | 结果 |
|---|---|
| 传输结束**不关**数据连接(保留监听器供复用) | **破坏 FTP 语义**:服务端不发 FIN 客户端就等不到 EOF,整会话挂死 → 必须关闭数据连接 |
| 新增 `net_shutdown()`(发 FIN 优雅断开)+ 复用监听器(等 auto_relisten 回 LISTEN,最多 1s;兜底改走 `net_relisten()`) | 部分会话 11/11,但**不稳定**(3 会话中仍有 1 次 425,且后续会话出现控制连接连不上)→ 回退 |
**保留的安全硬化**(与 D20 同源事件竞态,纯增益):
1. `handle_disconnect_event`:ESTABLISHED 状态下收到 DISCONNECT 时**回读芯片 TCP 状态**,仍为 `CH395F_TCP_ESTABLISHED` 判为陈旧事件丢弃(防"上一条连接的迟到 teardown 误杀新连接");
2. `net_socket.c` 两处 `ch395f_get_socket_status` 调用**只给了 1 字节缓冲**(该 API 输出 2 字节:`[0]`Socket 状态、`[1]`TCP 状态)→ 栈越界 1 字节;已改为 2 字节缓冲(`ch395f.h` 补显式告警)。
**后续建议**(按性价比):
1. **数据 Socket 轮换**:不要总是复用最低空闲 fd(现固定为 sock4),让连续两次数据连接落在不同芯片 Socket 上(需 net 层支持"分配偏好/最小索引",或 lftpd 保留一个 spare 监听器占位)→ 直接绕开"同一 Socket 快速复用"竞态;
2. **客户端重试**:425 属 RFC 959 的瞬态 4xx,控制器/上位机在数据连接失败后重试一次即可规避(现场最省事的规避手段);
3. **寄存器级定位**:在首会话复现窗口内打印 `CMD_GET_SOCKET_STATUS_SN`(2 字节)与 SINT 序列,确认芯片在 teardown/reopen 交叠时的内部状态迁移;
4. 复现脚本:`test/ftp_regression.py --host <ip>`(单会话内 7 次数据连接 + 1KB/32KB 往返内容校验,退出码 = 是否全通过)。
### 7.5 建议的后续项(按性价比)
1. **尾批 ~52ms(占一帧 77%)—— 已定性并给出解法(§3.3)**:客户端在帧未收齐时补发一个字节
(`--ack-probe`)或关闭本 socket 的延迟 ACK(`--ack-fast`),实测 **65.5ms → 13.7 / 20.7ms**,协议与设备代码均不改。
若客户端无法改动(第三方 App),退路是**协议补位**(把应答补齐为 1024 的整数倍,使尾段变为满 MSS 段),
但需客户端同步改解析(多出的补位字节须被跳过),优先级低于客户端侧解法。
2. **D20(FTP 数据连接 425)**:见 §7.4 —— 已定位为"开机首会话 + 芯片同 Socket 快速复用"竞态;优先做**数据 Socket 轮换**,
现场可用**客户端重试**规避。
3. **日志税**:一行 `printf` 4.4ms(L10);热路径同步日志会直接污染测量与时延(D12-b 实测 7.8×)→ 热路径禁止日志。
4. **任务模型**:L11 显示 uiTask 渲染仅 ~1ms/帧、L5 队列往返 ~6ms 属轮询节拍
⇒ **调优先级/栈不会改善体感**;预算应花在上面第 1、2 项。
---
## 8. 复现与数据文件清单
```powershell
# M3(生产路径,需要设备已烧 Phase 14 固件)
& "MDK-ARM\build.bat" # 0 错 0 警(Phase 14 构建)
& '.venv\Scripts\python.exe' tools\serial_tool\serial_tool.py clear
& "MDK-ARM\download.bat" # 先烧录,再起 peer(顺序不可反!)
& '.venv\Scripts\python.exe' test\latency_peer.py --mode remo --host 192.168.1.100 --port 7003 `
--samples 65 --cadence-ms 100 --reconnect-rounds 3 --wait 120 `
--json "docs\测试说明\m3_data\m3_dev_quiet.json"
# 压力档(E-02)
& '.venv\Scripts\python.exe' test\latency_peer.py --mode remo --host 192.168.1.100 --port 7003 `
--samples 45 --stress-from 15 --ftp-stress --json "docs\测试说明\m3_data\m3_dev_stress.json"
# 模拟器基线(Δ 的对照端)
& "simulator\build_sim.bat"; .\simulator\build\Debug\lvgl_sim.exe # 等 7003 就绪
& '.venv\Scripts\python.exe' test\latency_peer.py --mode remo --host 127.0.0.1 --port 7003 `
--samples 50 --json "docs\测试说明\m3_data\m3_sim_quiet.json"
# 尾批定性/解法(都不需要抓包工具)
& '.venv\Scripts\python.exe' test\latency_peer.py --mode remo --host 192.168.1.100 --port 7003 `
--samples 30 --ack-probe --json "docs\测试说明\m3_data\m3_tail_ackprobe.json" # 带内补 ACK
& '.venv\Scripts\python.exe' test\latency_peer.py --mode remo --host 192.168.1.100 --port 7003 `
--samples 30 --ack-fast --json "docs\测试说明\m3_data\m3_tail_ackfast.json" # 关延迟 ACK
```
| 数据文件 | 内容 |
|---|---|
| `m3_data/m3_dev_quiet.json` | 真机 65 帧生产周期(**修复前**基线) |
| `m3_data/m3_dev_stress.json` | E-02 压力档(**修复前**:17.7s 尖峰) |
| `m3_data/m3_dev_quiet_fixed.json` | 真机 65 帧(**修复后**:帧周期 65.7ms、relisten 已 OK、INIT framebytes=3200) |
| `m3_data/m3_dev_stress_fixed.json` | E-02 压力档(**修复后**:med 74.7ms / max 106.8ms,零尖峰) |
| `m3_data/m3_sim_quiet.json` | 模拟器基线 50 帧(Δ 对照,tail=0) |
| `m3_data/m3_tail_ackprobe.json` | 尾批实验 ①:帧未收齐即回 1 字节(捎带 ACK)→ tail 3.9ms |
| `m3_data/m3_tail_ackfast.json` | 尾批实验 ②:Windows 立即 ACK(不发探测字节)→ tail 3.9ms |
| `m2_data/m2_quiet.json`(run15)等 | M2 芯片+队列基线与串口证据 |
| `m2_data/README.md` | M2 数据说明(含逐帧尾批明细、方法学教训) |
**复现注意**(M3 实测踩到的坑,务必遵守):
1. **先烧录、后起 peer**——否则 peer 会连到**上一版固件**的 :7003(实测:首帧由旧固件应答后被复位 RST);
2. peer 首连常因芯片空闲超时被 RST(10054),`--wait` 重试是**正常路径**;
3. 探针三段窗口是**串行全局窗口**,多打点站点必须用 `lat_probe_add_seg()` 按段名过滤;
4. `[LAT]`/peer JSON 都带主机时间戳,可直接合并;设备 RTC 比主机慢约 4s(显示差异,非测量误差);
5. **还原被回退的源文件后必须 touch**(`Copy-Item` 保留旧 mtime,Keil 会因此跳过重编译 → "改了却没效果",见 §7.2)。
File diff suppressed because one or more lines are too long
File diff suppressed because it is too large Load Diff
File diff suppressed because one or more lines are too long
@@ -0,0 +1,436 @@
# 远程显示(RemoDispBus)延迟分析报告
> **模块名称**:远程显示链路(`ui_net_sink` → `net_socket` → CH395F → DTU-RemoteLCD)
> **文档目的**:针对"远端 LCD 连 MCU 有明显延迟感、连 PC 模拟器没有"这一现象,做**静态全链路分析**:
> 拆解延迟预算、列出候选原因(按可能性排序并给出代码级证据)、给出可执行的排查流程与逐因对策。
> **日期**:2026-09-22
> **状态**:**只读分析,未修改任何代码**;本文所有行号基于当前工作副本,改动后需复核。
> **对照实验事实**:同一份共享服务端 `Drivers/BSP/UI/ui_net_sink.c` + 同一个 DTU-RemoteLCD 客户端,
> 连模拟器(Winsock)流畅、连 MCU(CH395F)有明显延迟 → 差异全部落在 `net_*` 的 **MCU 后端**,
> 协议与客户端实现可视为已排除。
---
## 0. 摘要
**这不是"网线慢",而是 MCU 侧 CH395F 通道上的结构性开销 + 芯片重传粒度放大。**
"模拟器没有延迟"这个对照实验的证明力有限:它只证明了**协议与客户端没问题**,
**没有**证明链路/芯片层没问题——因为模拟器根本不走 CH395F、不走 SPI、不走 netMsgQueue、
不走 FreeRTOS 调度,Winsock 一次 `send()` 就把 3209 字节交给 PC 协议栈连续发出。
### 原因排序
| # | 原因 | 量级 | 可能性 | 关键证据 |
|---|---|---|---|---|
| **D1** | CH395F TCP 重传周期 **500ms** —— 一次丢包 = 整帧多等半秒 | **500ms ~ 4s** | 高 | `net_socket.c:143-144`(8 次 × 500ms,总窗口 4s);客户端注释自证"整帧分 4 块耗时 **0.5~3 秒**属正常"(`remo_disp_server.py:165-174`),0.5/1.0/1.5s 台阶正是 500ms 整数倍 |
| **D2** | 整帧 3209B + CH395F **1KB 发送 FIFO 停止等待** —— 每帧固定 4 次串行分块握手 | 15~30ms 基线,弱网放大 | 高(基线) | `NET_SEND_CHUNK_MAX = CH395F_SEND_BUF_SIZE_BYTES = 1KB`(`net_socket.c:916-921`、`ch395f.h:119-129`);`net_send_locked` 每块写完必须等 `SENBUF_FREE`(`:955-985`) |
| **D3** | **netMsgQueue 头阻塞**(既有审计 **E-02**):lftpd/对时的阻塞 recv 在 netTask 上下文空转 | **最长 30s 全网停摆** | 高(间歇性秒级卡顿的首要嫌疑) | `net_socket.c:357` 一次只取一条消息 + `:1019-1067` 阻塞 recv 在 netTask 内空转;触发源 `lftpd_inet.c:106-109`、`time_sync.c:84`(均 `flags=0`) |
| **D4** | PC 端 TCP **延迟确认(40~200ms)** 与"每段等 ACK"的停止等待发送端交互 | 40~200ms/块 | 中高 | 客户端注释已记录;CH395F 发送缓冲仅 1×MSS,无法让 2 段同飞骗过延迟确认 |
| **D5** | uiTask 节拍:10ms 循环 + **每拍只 recv 一次 64B** + step 在 poll **之前** | 10~30ms + 多等一拍 100ms | 中 | `ui_task.c:91-95`;`ui_net_sink.c:441`(`RM_RX_BUF = 64`,`:38`) |
| **D6** | 阻塞式日志在关键路径:`fputc` 逐字节 `HAL_UART_Transmit` @115200 | **每行 ~5ms**(阻塞调用任务) | 中(确定的基线税) | `Src/usart.c:479-484`;`net_socket.c:1025` 每次收数据都 `DBG_INFO` 一行;`dbg_cfg.h:28/40` `DBG_ENABLE` + 时间戳均开 |
| **D7** | 物理链路:双工不匹配 / 网线 / Wi-Fi / ARP | 不可预估,直接喂给 D1 | 中 | `net_task.c:100` **强制** 100M 全双工;若交换机自协商 → 双工不匹配是丢包经典成因 |
| **D8** | 客户端固定成本:100ms 拉取节拍(**按键后不立即取帧**)+ 1bpp→PNG→base64→WebSocket | 100ms + 数 ms | 确定的基线 | `remo_disp_server.py:588-647`(`_refresh_stop.wait(0.1)`);`:736-741` `on_key` 只发键不触发取帧 |
| **D9** | LVGL 全量渲染(`LV_DEF_REFR_PERIOD=20ms`、`RENDER_MODE_FULL`)+ 每次 flush 整帧 memcpy,uiTask 为 **BelowNormal** 易被抢占 | 单次渲染数 ms~数十 ms | 中低(待实测) | `ui_port.c:126-127/80-86`;`lv_conf.h:11/22`;任务优先级见 `AGENTS.md` 任务表 |
| **D10** | 断线重连路径含 `osDelay(500)`(netTask 上下文,最多 3 次) | 0.5 ~ 1.5s | 中(仅断线/重连时) | `net_socket.c:1098-1105` |
### 一句话行动建议
先做 §3 的 **Step 1(客户端三点打点)+ Step 2(Wireshark 抓包)**,半天内不改固件即可定性;
随后落 **P0 两项一行级改动**:`set_retrans_period(500) → 200`(治 D1 症状)+
删 `net_socket.c:1025` 的 per-recv 日志(治 D6)。根治方向是 **差量/RLE + 帧版本号**(治 D2,连带把 D1 的影响面压到几乎为零)。
---
## 1. 链路与延迟预算
### 1.1 一次"按键 → 看到画面"的完整旅程
```mermaid
sequenceDiagram
participant B as 浏览器
participant F as Flask/SocketIO<br/>refresh_loop
participant C as CH395F
participant N as netTask
participant U as uiTask
B->>F: 按键 (socketio "key")
F->>C: KEY 帧 10B(on_key 不触发取帧)
Note over F: D8 最多等 100ms 才轮到下一次 fetch_screen
F->>C: LCDMEM 请求 10B
C-->>N: RECV 中断 → net_poll
Note over N: D3 netMsgQueue 头阻塞窗口
U->>N: net_recv(64B)(队列 + TaskNotify)
Note over U: D5 最多 10ms 相位 + LVGL 渲染占时
N-->>U: 按键注入 UI
Note over U: D9 下一拍才渲染(step 在 poll 之前)
U->>N: net_send 3209B
loop D2 4 次串行分块
N->>C: WRITE_SEND_BUF ≤1KB(SPI DMA ≈1.6ms/KB)
C-->>N: SENBUF_FREE 中断
end
Note over C: D1 丢一段 → 重传 +500ms(D7 供包)
C-->>F: 4 × 1024B 段
Note over F: D4 Windows 延迟确认 40~200ms
F->>B: PNG → base64 → socketio → canvas
```
### 1.2 各段耗时(健康值 vs 异常值)
| 段 | 位置 | 健康耗时 | 异常时的耗时 | 备注 |
|---|---|---|---|---|
| 客户端拉取节拍 | `remo_disp_server.py:647` | ≤100ms | ≤100ms(固定) | 按键后不提前取帧 |
| 线路 RTT(请求) | 以太网 | ~0.1ms | 1~50ms(Wi-Fi) | — |
| CH395F → netTask 事件 | `net_task.c:212-214` | ≤1ms | 数秒(D3) | 主循环 `osDelay(1)` |
| uiTask 拾取请求 | `ui_task.c:91-95` | ≤10ms | 数十 ms(D5/D9) | 每拍只 recv 一次 |
| 队列往返(每次 `net_*`) | `net_socket.c:1190-1290` | ~1-2ms | 数秒(D3) | 投递 + TaskNotify,2 次任务切换 |
| 收数据日志 | `net_socket.c:1025` → `Src/usart.c:479` | ~5ms | ~5ms(固定税) | 阻塞在 netTask 内 |
| 取帧 + 组帧 | `ui_net_sink.c:223-226` | ~0.1ms(2×3200B memcpy) | — | 见 D2-方案⑤ |
| 4 次分块发送 | `net_socket.c:955-985` | 15~25ms | **每 chunk 上限 1s**(`NET_SEND_TIMEOUT_MS`)→ 4s | SPI 5.25Mbit/s ≈1.6ms/KB |
| 分段传输 + ACK | 线路 + PC | ~0.5ms | **500ms/1s/1.5s 台阶**(D1)、40~200ms/块(D4) | 决定性判据 |
| PNG + base64 + WS + canvas | `remo_disp_server.py:510-617` | 数 ms | 数 ms(固定) | 双端相同 |
| **合计(典型)** | | **≈130~170ms** | **0.5s ~ 30s** | 模拟器合计 ≈105~115ms |
### 1.3 关键量化常量
| 常量 | 值 | 来源 |
|---|---|---|
| 屏幕 / 帧大小 | 160×160 **1bpp** = 3200 B | `ui_net_sink.c:33-35` |
| LCDMEM 应答 wire 长度 | 4(头) + 4(偏移) + 3200(位图) + 1(CRC) = **3209 B** | `ui_net_sink.c:226` + `remo_send` |
| TCP MSS | 1024 | `ch395f.h:119`、`net_socket.c:140` |
| CH395F 每 socket 发送缓冲 | 2 块 × 512B = **1KB** | `ch395f.h:122-128` |
| `NET_SEND_CHUNK_MAX` | **1KB**(受发送缓冲与 DMA 载荷 2048 双重钳制) | `net_socket.c:916-921` |
| LCDMEM 一帧分块数 / 分段数 | **4**(1024×3 + 137) | 3209 ÷ 1024 |
| CH395F 内部 RAM | 48 块 × 512B = 24KB,**8 socket 均分 6 块** | `net_socket.c:196-202` |
| TCP 重传 | **8 次 × 500ms = 4s 窗口** | `net_socket.c:143-144`;手册 §5.17/§5.18 默认 12 次/500ms |
| SPI2 速率 | APB1 42MHz ÷ 8 ≈ **5.25 Mbit/s** → 1KB ≈ **1.6ms** | `Src/spi.c:84`、`.ioc APB1CLKDivider=DIV4`;分频 8 为 PCB 约束(`AGENTS.md`) |
| 发送等待超时 | 1s(`NET_SEND_TIMEOUT_MS`) | `net_config.h:32-34` |
| 接收超时 | 30s(`NET_RECV_TIMEOUT_MS`) | `net_config.h:36-38` |
| 调试串口 | USART1 115200,**逐字节阻塞发送** | `Src/usart.c:479-484` |
| LVGL 刷新周期 / 色深 | 20ms / 1bpp(`RENDER_MODE_FULL`) | `lv_conf.h:11/22`、`ui_port.c:126-127` |
---
## 2. 原因清单(机制 / 证据 / 判据 / 对策)
### D1 CH395F TCP 重传周期 500ms —— 秒级延迟的放大器 ★首要嫌疑
- **机制**:CH395F 的 TCP 重传是**固定周期**(非指数退避的 RTT 自适应)。工程显式设为
`ch395f_set_retrans_count(8)` + `ch395f_set_retrans_period(500)`
(`Drivers/BSP/NET/net_socket.c:142-144`)。任何一段 1024 字节数据在链路上丢失,
就要等满 500ms 才重发;两段的代价是 1s,依此类推,最坏 4s 后判发送失败。
一帧 LCDMEM 应答是 4 个段 → 丢包概率随段数线性上升。
- **证据**:客户端源码已把这一现象写进注释——
"整帧 LCDMEM(3209 字节) 分 4 块到达耗时 **0.5~3 秒以上属正常现象**"
(`../DTU-RemtoeLCD/remo_disp_server.py:165-174`,客户端为**与本仓库同级**的独立工程)。
观测到的延迟若呈 0.5/1.0/1.5s 台阶,
就是 500ms 粒度的指纹。
- **判据**:Wireshark `tcp.port==7003 && tcp.analysis.retransmission`,看是否有重传、
以及相邻重传的间隔是否 ≈500ms。
- **对策**:见 §4-S1(调小重传周期)+ §4-S2(把一帧压到 1~2 段,从根本上减少需要重传的数据)。
### D2 整帧 3209B × 1KB 发送 FIFO 停止等待
- **机制**:CH395F 发送缓冲只有 2 块 = 1KB(`ch395f.h:122-128`),且手册明确
"**单片机向 Socket 发送缓冲区写入一次数据后,必须等到产生 `SINT_STAT_SENBUF_FREE`
中断后才可以写入下一次数据**"(`docs/芯片手册/CH395F.md:568/623`)。
`net_send_locked` 因此把 3209B 切成 4 块,每块"SPI 写 → 置 `send_ready=0` → 死循环
`net_poll()` 等中断"(`net_socket.c:955-985`)。期间 **netTask 全程占用**,
既不能处理其它队列消息,也不能处理其它 socket 事件。
- **叠加成本**:每次 `WRITE_SEND_BUF` 是 1KB SPI DMA(≈1.6ms @5.25Mbit/s,
`ch395f.c:1117-1147`,内部忙等 `s_spi2_dma_done`,`ch395f.c:89-135`);
组帧路径还有两次 3200B `memcpy`(`ui_net_sink.c:223` 取帧 + `:114` 组帧)。
- **基线代价**:约 15~25ms/帧;**常驻带宽 ≈32KB/s**(客户端 10Hz 拉取,画面没变也照发)。
- **判据**:§3-Step4 实验 A(把应答临时改成 100B,延迟若立刻正常 → 确诊本项)。
- **对策**:§4-S2(差量/RLE + 版本号 + 由拉改推)、§4-S4(提高发送块配额与 MSS)、
§4-S5(少拷一次,顺带省 3.2KB RAM)。
### D3 netMsgQueue 头阻塞(= 既有审计 **E-02**)
- **机制**:所有跨任务 `net_*` 操作都排队到 netTask 串行执行
(`net_socket.c:1190-1337` 投递 + `xTaskNotifyWait` 阻塞等回执),
而 `net_process_messages` **一次只取一条消息并处理到底**(`:357`)。
只要有任何一个消费者发起 `flags=0` 的阻塞 recv,netTask 就会在
`net_recv_locked` 的等待循环里空转最长 **30s**(`:1019-1067`,
`NET_RECV_TIMEOUT_MS=30000`),此时 **uiTask 每 10ms 的轮询、accept、其它服务的收发全部排在队里**。
- **触发源**:`lftpd_inet.c:106-109`(FTP 控制连接 `read_line` 阻塞 recv——
**FTP 客户端连上后空闲 >30s 即触发,属常见工况**)、`time_sync.c:84`。
`ui_net_sink` 自己是正确的 `NET_MSG_DONTWAIT` 模式,所以它既是受害者也不是触发者。
- **特征**:**间歇性整屏冻结数秒~数十秒**,与"是否在动 FTP/对时"相关。
- **判据**:卡顿发生时检查是否有 FTP 会话挂着(或临时停掉 ftpTask/timeSyncTask 做对照,§3-Step4-C)。
- **对策**:§4-S6(阻塞 recv 改 DONTWAIT 分片 + 调用方重投;超时按服务分档)。
### D4 PC 端 TCP 延迟确认(Delayed ACK)
- **机制**:Windows 对**满 MSS** 段默认延迟确认(最多 200ms,通常 40~200ms,等待捎带)。
它每收到 2 个满 MSS 段才立即 ACK。而 CH395F 发送缓冲只有 1×MSS,
**无法把两个段同时放上线**,于是每一段都成了"新的第一段" → 每一段都吃满延迟确认。
- **判据**:Wireshark `tcp.analysis.ack_rtt`;或看 4 个 1024 段之间的间隔是否 ≈40~200ms
(正常应 <1ms)。
- **对策**:§4-S2(一帧压到 1 段后自然免疫);必要时客户端机器关延迟确认
(注册表 `TcpDelayedAcknowledge=0`,机器级副作用需评估),或参考客户端跑 Linux + `TCP_QUICKACK`。
### D5 uiTask 节拍与"每拍只收一次 64B"
- **机制**:主循环顺序是 `ui_port_step(10)` → `ui_net_sink_poll()` → `osDelay(10)`
(`App/task/ui_task.c:91-95`)。两个后果:
1. **按键注入晚一拍**:KEY 是在 poll 阶段注入的,而 LVGL 的 `lv_timer_handler()`
已经在本轮开头跑完 → 按键要到下一轮(≤10ms 后)才被读到并渲染。
2. **每轮只做一次 `net_recv`,上限 64B**(`ui_net_sink.c:441`,`RM_RX_BUF=64`):
排空不彻底,突发多帧时跨多拍才吃完。
- **判据**:uiTask 循环打点(实测循环周期);§3-Step4-D(把 poll 挪到 step 之前对照)。
- **对策**:§4-S7(poll 前置 + while 排空)。
### D6 阻塞式日志躺在关键路径上
- **机制**:`fputc` = `HAL_UART_Transmit(&huart1, &ch, 1, HAL_MAX_DELAY)`
(`Src/usart.c:479-484`),逐字节阻塞;`DBG_ENABLE` 与 `APP_TIMESTAMP_ENABLE` 均开
(`dbg_cfg.h:28/40`),带时间戳一行 ≈55~70 字符 → **约 5ms 阻塞在调用任务内**。
`net_recv_locked` **每次收到数据都打印一行**
`DBG_INFO("recv sock%d len=%d", ...)`(`net_socket.c:1025`)→ 每帧固定给 netTask 加 ~5ms,
且这段时间 CH395F 完全没人轮询。
- **判据**:临时注释该行后复测(这本身也是 P0 快改项之一)。
- **对策**:§4-P0-b(删/降级该行)+ §4-S8(`fputc` 改环形缓冲 + TX 中断/DMA)。
### D7 物理链路与协商("网络延迟"最字面的一种)
- **机制**:`net_stack_bring_up` **强制** `ch395f_set_phy(CH395F_PHY_100M_FULL)`
(`App/task/net_task.c:100`)。若交换机/网卡端口处于自协商,会出现**双工不匹配**
(一端强制全双工、一端半双工)→ 冲突与静默丢包 → 直接喂给 D1,表现为"莫名秒级卡顿"。
另外 PC 在 Wi-Fi 上会引入抖动与丢包;ARP 表项失效也会造成首包停顿
(CH395F 默认 ARP 重传 3 次 × 1s,手册 §5.42)。
- **判据**:
1. 开机日志核对 `PHY: 100M FULL`(`net_task.c:117-122`)——若显示 `10M HALF`/`DISCONNECT`,本项即确诊;
2. 抓包看重传分布;
3. 用 `ch395f_get_unreach_ipp()`(`ch395f.c:1326-1331`)看是否有解析不到的目标 IP;
4. **拓扑对照**:PC 有线直连设备、不经交换机、远离 Wi-Fi,再测。
- **对策**:§4-S3。
### D8 客户端固定成本(双端相同,但决定"下限")
- **机制**:刷新线程"取帧 → 编码 → 推送 → `wait(0.1)`"串行
(`remo_disp_server.py:588-647`),因此**有效刷新率 = 1 / (fetch 耗时 + 100ms)**;
若 fetch = 0.5s,刷新率直接掉到 2fps,"延迟感"主要来自这里。
`on_key` 只 `send_key`、**不触发取帧**(`:736-741`)→ 按键平均多等 50ms、最多 100ms。
1bpp → PIL PNG → base64 → SocketIO → 浏览器解码,是一串纯 CPU 开销(3200B 帧其实不需要 PNG)。
- **判据**:§3-Step1 打点即可分离出"客户端等待"与"网络等待";§3-Step4-B 用裸 TCP 客户端对照。
- **对策**:§4-S9。
### D9 LVGL 全量渲染与任务优先级
- **机制**:`RENDER_MODE_FULL`(`ui_port.c:126-127`)+ `LV_DEF_REFR_PERIOD=20ms`
(`lv_conf.h:22`)→ 任何 invalidate 都重画整屏 160×160;flush 回调无条件整帧
`memcpy` 3200B(`ui_port.c:80-86`)。uiTask 优先级 **BelowNormal**(`AGENTS.md` 任务表),
而 defaultTask(Normal,syslog 唯一写者,写 NAND)与 netTask/ftpTask/timeSyncTask(Normal)
都会抢占它 → `ui_net_sink_poll()` 的实际调用间隔可能远大于 10ms。
- **判据**:uiTask 循环打点统计实际周期分布;待机页(时钟每秒刷新)与菜单页对比。
- **对策**:§4-S7;若实测渲染是瓶颈,再考虑降低刷新率/按需 invalidate(改前先核 RAM)。
### D10 断线重连路径含 netTask 内 `osDelay(500)`
- **机制**:`net_relisten_locked` 里 `ch395f_open_socket` 失败时
`ch395f_close_socket()` + `osDelay(500)`,最多重试 3 次(`net_socket.c:1098-1105`)。
这**在 netTask 上下文**执行 → 期间全网停摆 0.5~1.5s。
客户端侧连续 5 次拉取失败会主动断开重连(`remo_disp_server.py:597-644`),
于是"卡顿 → 判失败 → 重连 → 更卡"可能互相放大。
- **判据**:日志中 `sock0 LISTEN TIMEOUT` / `open socket` 失败 / 客户端 `device_disconnected`。
- **对策**:§4-S6(改非阻塞重试)。
### 相关既有缺陷(会掩盖/放大延迟,建议一并处理)
| 编号 | 位置 | 与延迟的关系 |
|---|---|---|
| **E-02** | `错误码传播审计.md` §3.2 | 即本文 D3,已立案 |
| **E-04** | `ui_net_sink.c:117` | `remo_send` 丢弃 `net_send` 返回值 → 弱网**短写静默截断**(net 层只打 `short send`,`:990`),客户端 CRC 不过 → 断连 → 触发 D10 → 观感是"卡完直接黑屏/卡住" |
| **E-33/E-34** | `ch395f.c:89-135/181-210` | DMA 失败 void 化无错误通道;字节级命令 `HAL_MAX_DELAY` → 一次 SPI 故障可能让 netTask 永久挂死(无看门狗) |
---
## 3. 排查流程
### Step 0 —— 先分类(决定后面查哪一支)
| 观测现象 | 首要指向 | 跳到 |
|---|---|---|
| 每帧都**稳定**慢 ≈150~300ms | 结构性基线(D2/D5/D6/D8/D9) | Step 1 + Step 4-A |
| **间歇**卡,且 ≈500ms 的整数倍 | **D1** 丢包重传 | Step 2 + Step 4-A |
| **间歇**整屏冻结数秒~数十秒 | **D3** 队列头阻塞 / D10 重连 | Step 3 + Step 4-C |
| 只在开 FTP / 对时后卡 | D3 + 单连接 socket 争用 | Step 4-C |
| 换网口/换线/换 PC 就好 | D7 | Step 2 + 拓扑对照 |
### Step 1 —— 客户端三点打点(成本最低,最先做)
在 `../DTU-RemtoeLCD/remo_disp_server.py::fetch_screen` 记录 **t0 请求发出 / t1 收到首字节 /
t2 整帧收齐**,每帧输出一行:`req2first=..ms total=..ms bytes=..`。
判读规则(最有决定性的一步):
| 结果 | 结论 | 下一步 |
|---|---|---|
| `req2first` 大(>50ms) | 设备迟迟不开口:uiTask 拾取慢 / 队列头阻塞 / CH395F 收包慢 | Step 3、Step 4-C/D |
| `req2first` 小但 `total` 大 | 尾块传输慢:1KB 分块 + 重传 + 对端 ACK | Step 2 |
| `total` 落在 500/1000/1500ms | **D1 确诊** | §4-P0-a |
| `total` 稳定 ≈20~40ms 但观感仍慢 | 瓶颈在客户端 100ms 节拍/编码(D8) | §4-S9 |
### Step 2 —— PC 抓包 `tcp.port == 7003`
| 过滤器 / 观察项 | 判读 | 对应 |
|---|---|---|
| `tcp.analysis.retransmission` | 有重传 & 间隔 ≈500ms → **D1** | S1 / S3 |
| 4 个 1024B 段的间隔 | 正常 <1ms;≈40~200ms → 被对端 ACK 门控(D4) | S2 / S9 |
| 请求 → 响应首包间隔 | >50ms → 设备侧调度慢(D3/D5/D6) | Step 3 / Step 4 |
| `tcp.analysis.zero_window` / `window_full` | CH395F 接收窗口仅 2KB 被打满 | 收路径核查 |
| `tcp.analysis.out_of_order` / `dupack` | 链路丢包/乱序 | S3 |
| 客户端 `sendall` 是否阻塞 | 请求发不出去 = 设备窗口小/未读 | 收路径核查 |
### Step 3 —— MCU 侧打点(serial_tool 抓开机+运行日志)
> ⚠️ **先关掉 `net_socket.c:1025` 的 per-recv 日志再打点**,否则 ~5ms/行的阻塞日志
> 就在被测路径上,会自欺欺人(见 D6)。
> ⚠️ 按 `AGENTS.md` 铁律:**新增字符串字面量必须纯 ASCII**。
```powershell
& '.venv\Scripts\python.exe' tools/serial_tool/serial_tool.py open
& '.venv\Scripts\python.exe' tools/serial_tool/serial_tool.py clear
# 烧录/复位(采集必须先于烧录)
& '.venv\Scripts\python.exe' tools/serial_tool/serial_tool.py wait-idle --timeout 90 --settle-ms 8000 --max-ms 45000
```
打点位置与建议指标(用 `HAL_GetTick()` 或 DWT CYCCNT):
| 位置 | 指标 |
|---|---|
| `net_send_locked`(`net_socket.c:938`) | 每 chunk 等待 ms + 整次总 ms + `sent/len`(已有 `short send` 日志可先看) |
| `ui_net_sink_poll`(`ui_net_sink.c:406`) | `net_recv` 返回 → `net_send` 返回的 ms |
| `ui_task` 循环(`ui_task.c:91`) | 实测循环周期(`osDelay(10)` 之外多花了多少)→ 反推 D5/D9 |
| `net_process_messages`(`net_socket.c:357`) | 单条消息处理耗时 + 队列积压深度 → **直接量化 D3** |
| 开机日志 | `PHY: 100M FULL` 是否成立(D7) |
### Step 4 —— 四个隔离实验(二分定位)
| # | 实验 | 做法 | 结论 |
|---|---|---|---|
| **A** | **缩小响应**(★最有决定性) | 临时让 `CMD_LCDMEM` 只回 ~100B(而非 3204B) | 延迟立刻正常 → 确诊 D2(及被 D1/D4 放大);仍慢 → 瓶颈在请求/调度路径(D3/D5/D6) |
| **B** | **裸 TCP 客户端** | 30 行 Python:直连 7003,循环发 LCDMEM 并计时往返(不走 Flask/WebSocket/PNG) | 变快 → D8;不变 → 设备侧 |
| **C** | **关掉 FTP/对时** | 临时只保留 :7003 服务 | 变快 → **D3**(E-02 头阻塞)/ 单连接 socket 争用 |
| **D** | **poll 前置** | `ui_task.c` 循环改成先 `ui_net_sink_poll()` 再 `ui_port_step(10)` | 变快 → D5 |
> 实验 A/B/D 是**临时验证手段**;正式修法以 §4 为准,勿把临时改动提交。
---
## 4. 解决方案
### P0 —— 一行级、低风险、先做(需 `@build` 0 错误 0 警告)
| 编号 | 改动 | 治 | 预期 / 代价 |
|---|---|---|---|
| **P0-a** | `net_socket.c:144` `ch395f_set_retrans_period(500)` → **`200`** | D1 症状 | 单次丢包代价 500ms→200ms(体感卡顿降一档)。代价:总窗口 8×200=1.6s,链路真断时判失败更快(对远显是有利的)。手册 §5.18 允许 ≤1000ms,**最小值未标注,需台架确认 200 被接受**(可用 `GET_CMD_STATUS` 校验) |
| **P0-b** | 删除/降级 `net_socket.c:1025` 的 per-recv `DBG_INFO` | D6 | 每帧省 ~5ms netTask 阻塞;顺带减少 syslog 噪声与 NAND 写入 |
### S1 —— 重传与超时参数分档
- `NET_SEND_TIMEOUT_MS=1000` / `NET_RECV_TIMEOUT_MS=30000`(`net_config.h:32-38`)
目前是**全局一刀切**:对远显,30s 阻塞是灾难;对 FTP,1s 发送超时可能偏紧。
建议按服务分离(`ui_net_sink` 用短超时 + 非阻塞,FTP 保留长超时)。
### S2 —— 差量 / RLE + 帧版本号 + 由拉改推(**根治,收益最大**)
| 手段 | 做法 | 效果 |
|---|---|---|
| **差量 + RLE** | `ui_flush_cb`(`ui_port.c:80-86`)中与上一帧比对,记录变化矩形/行程;协议新增 `CMD_LCDMEM_DIFF`(保留旧 `LCDMEM` 全帧以兼容) | 1bpp 菜单典型变化 **<100B** → 单段一帧 → 延迟 ≈ 一个 RTT;D1 丢包影响面从 4 段降到 1 段 |
| **帧版本号** | 设备维护 `frame_seq`,客户端请求带上自己看到的 seq;未变则回 `NOCHANGE`(~10B) | 稳态带宽从 **32KB/s → ≈0**,把通道留给"真变化帧" |
| **由拉改推** | flush 后设备主动推 UNSOL 帧,客户端不必等 100ms 节拍 | 按键响应从"≤100ms + 取帧"降到"一个 RTT" |
| 兼容 | 新命令走同一帧格式与 CRC;旧客户端仍可用 `LCDMEM` 全帧 | 双端共用 `ui_net_sink.c` 不变 |
### S3 —— 物理链路与协商
1. 核对开机日志 `PHY: 100M FULL`(`net_task.c:117-122`)。
2. 二选一:交换机端口也**强制 100M 全双工**(与 `net_task.c:100` 对齐),
或让 CH395F 走自协商(需评估既有约束后改动)。
3. 换网线 / 换交换机端口 / **PC 有线直连**做对照;PC 不要在 Wi-Fi 上测。
4. 用 `ch395f_get_unreach_ipp()` 观测不可达 IP(ARP 侧线索)。
### S4 —— 提高发送块配额与 MSS
- 现状:48 块 × 512B 均分给 8 个 socket(`net_socket.c:196-202`),**实际只用到 3 个**
(:21 FTP / :8888 对时 / :7003 远显)。
- 改法:按**实际使用数**分配,例如 3 个 socket 各 16 块(接收 3KB + 发送 3KB),
MSS 提到 1460 → 3209B 从 4 chunk/4 段降到 **1~2 chunk/段**。
- **约束**:
- `NET_SEND_CHUNK_MAX` 仍受 SPI DMA 载荷 2048B 二次钳制(`net_socket.c:916-921`),
单块实际 ≤2048B;
- **Trap 20 铁律**:单次写长度 **必须 ≤ 发送缓冲**,否则写穿 FIFO 静默丢数据
(`docs/问题记录/CH395F_Trap_Records.md` Trap 20);
- `net_init` 的分配是按 `i * blocks_per_socket` 硬算 8 个(`:196-202`),改分配策略需同步
`net_bind` 里的重复分配路径(`:518-521`);
- 改前先读 `docs/问题记录/CH395F_Trap_Records.md`,改后跑 CH395F 测试套件 Phase 8(100KB 吞吐)。
### S5 —— 去掉一次 3200B 拷贝(顺带省 RAM)
`g_tx[3209]`(`ui_net_sink.c:40`)与 `g_lcdmem_data[3204]`(`:41`)各占一份,
LCDMEM 路径是"帧缓冲 → `g_lcdmem_data+4` → `g_tx+4`"两次 memcpy。
让 `g_tx` 直接承接位图(取帧直接写到 `g_tx + 8`)可省一次 3200B 拷贝 + **约 3.2KB 常驻 RAM**
(该缓冲已被 `docs/内存管理/RAM使用分析与优化方案.md` §1 列为 6.4KB 常驻大户)。
**注意**:改 RAM 占用前先按 `AGENTS.md` 跑 `scripts/ram_report.py` 核算。
### S6 —— 消除 netTask 头阻塞(= 修 E-02,顺带修 D10)
1. `lftpd_inet.c:106-109`、`time_sync.c:84` 的 `flags=0` 阻塞 recv →
**`NET_MSG_DONTWAIT` 分片 + 调用方重投 + 总超时**(`ui_net_sink` 已是正确范式)。
2. `net_relisten_locked` 的 `osDelay(500)`(`net_socket.c:1104`)改为**非阻塞重试**
(置状态位,交主循环下轮重试),别在 netTask 里睡。
3. 顺带修 **E-04**:`ui_net_sink.c:117` 校验 `net_send` 返回值 `== len`,
短写则 `DBG_ERROR` + `net_close(g_client)` 触发客户端重连补帧(让截断可观测、可自愈)。
### S7 —— uiTask 节拍与收包排空
- `ui_task.c:91-95` 改为**先 `ui_net_sink_poll()` 再 `ui_port_step(10)`**(省掉按键的一整拍)。
- `ui_net_sink_poll` 内改成 **while 排空**:一轮里连续 `net_recv` 直到 `WOULDBLOCK`,
而不是每轮只收一次 64B;必要时把 `RM_RX_BUF`(`ui_net_sink.c:38`)与请求帧长对齐。
- 若 Step 3 实测渲染是瓶颈:降低 `LV_DEF_REFR_PERIOD` 的无效刷新、按需 `invalidate`,
或把 sink 轮询从渲染中解耦(渲染前后各排空一次收包)。
**改栈/缓冲前先核 RAM 与 `scripts/stack_report.py`。**
### S8 —— 日志改非阻塞
`Src/usart.c:479-484` 的 `fputc` 从"逐字节阻塞 `HAL_UART_Transmit`"改为
**环形缓冲 + TX 中断/DMA 发送**(关键路径上只写环形缓冲)。
收益:所有任务的日志成本从 ~5ms/行降到 µs 级;风险:需处理缓冲溢出丢弃策略与
`HardFault` 路径的同步冲刷。
### S9 —— 客户端侧(DTU-RemoteLCD)
1. **按键后立即取帧**:`on_key`(`:736-741`)里发完键直接触发一次 `fetch_screen`,
不等 100ms tick(省平均 50ms、最多 100ms)。
2. **不传 PNG**:直接把 1bpp 位图(或差量)发给前端,用 canvas 绘制,
省掉 PIL 编码 + base64 + 浏览器 PNG 解码。
3. **自适应节拍**:把固定 `wait(0.1)` 改为"上一帧耗时补偿"式调度,避免慢帧叠加。
4. **关闭 Windows 延迟确认**(可选,机器级副作用需评估):
`TcpDelayedAcknowledge=0`;或参考客户端跑 Linux + `TCP_QUICKACK`。
5. **拓扑纪律**:验证用 PC 一律**有线**、与设备同交换机或直连。
---
## 5. 相关文档
| 主题 | 位置 |
|---|---|
| RemoDispBus 协议与接收设计 | `docs/UI 设计/RemoDispBus协议与接收设计说明.md` |
| UI 设计架构(离屏渲染 + 推流) | `docs/UI 设计/UI_设计架构.md` |
| BSD Socket API 与双端后端 | `docs/BSD_Socket_API_使用指南.md` |
| CH395F 陷阱史(Trap 20 发送分块等) | `docs/问题记录/CH395F_Trap_Records.md` |
| 错误码传播审计(**E-02 / E-04 / E-33 / E-34**) | `docs/问题记录/错误码传播审计.md` |
| CH395F 测试套件(吞吐 Phase 8) | `docs/测试说明/CH395F_Test_Guide.md` |
| RAM 预算(`ui_net_sink` 6.4KB 常驻) | `docs/内存管理/RAM使用分析与优化方案.md` |
| 串口助手(抓日志排查) | `docs/测试说明/串口助手使用指南.md` |
| 远端显示客户端(**与本仓库同级的独立工程**,目录名含历史拼写 `Remtoe`) | `../DTU-RemtoeLCD/remo_disp_server.py`、`remo_disp_ui.html` |
| 芯片手册(§5.17/§5.18 重传、§5.42 ARP、SENBUF_FREE 语义) | `docs/芯片手册/CH395F.md` |
---
## 6. 变更记录
| 日期 | 变更 |
|---|---|
| 2026-09-22 | 创建:远程显示延迟静态全链路分析。拆解一帧旅程与延迟预算(典型 ≈130~170ms,异常 0.5s~30s);列 D1~D10 十项候选原因并给代码级证据与判据(首要嫌疑 = CH395F 重传周期 500ms `net_socket.c:143-144`,其次 = 3209B 整帧 × 1KB 发送 FIFO 停止等待);给出 Step 0~4 排查流程(分类 → 客户端三点打点 → Wireshark → MCU 打点 → 四个隔离实验)与逐因对策(P0 两项一行级改动 + S1~S9);关联既有审计 E-02/E-04/E-33/E-34。**未修改任何代码。** |
-9
View File
@@ -45,15 +45,6 @@
> 上图:**左 = 生产者(set)· 中 = 事件组 `sys_evtHandle` · 右 = 消费者(wait)**;任务卡与事件位对齐同一行,`bit1 → ftpTask` 的额外依赖用 **All 汇合点**(`osFlagsWaitAll`)表达。
> 源码 `tools/arch_diagram/gen_barrier_svg.py`(改数据重跑即可),PNG 预览本地渲染、不入库。
### 为什么用 Event Flags 而非全局变量
| 维度 | 全局标志 `g_net_ready` | Event Flags |
|------|----------------------|-------------|
| 等待方式 | 忙等轮询(浪费 tick) | 阻塞等待(零占用) |
| 多依赖组合 | 不支持 | `osFlagsWaitAll` / `osFlagsWaitAny` |
| 类型/作用域 | 裸 `volatile`,易误用 | 内核对象,API 受控 |
| 清空语义 | 手动维护 | 默认**消费**(唤醒即清);**就绪位必须 `osFlagsNoClear`**,只有命令位才用消费语义 |
| 调试可见性 | 不可观测 | 可在 IDE 观测事件组值 |
---
## 3. 方案设计
+54 -106
View File
@@ -1,38 +1,25 @@
# 项目审计改进清单
# 项目审计改进清单(待办)
- **审计日期**:2026-09-15(**2026-09-18 补充**:《项目审查与优化建议报告》新增 P0-1,当日修复)
- **范围**:全部项目自有代码(App/、Drivers/BSP/、Src/ USER CODE、MDK-ARM/、test/、tools/、scripts/、.opencode/、docs/ 一致性);第三方库(Lib/、Middlewares/、CMSIS/HAL、lftpd 内部、LVGL)仅查项目侧误用
- **方法**:静态逐文件走读 + pre-commit 全库基线(cppcheck/规范/乱码,全绿)+ 三份 trap 文档交叉核对
- **严重度**:P0 = 确认功能 bug | P1 = 疑似 bug 或健壮性风险 | P2 = 改进 | P3 = 卫生
- **置信度**:high = 代码级确证 | medium = 依赖外部条件(手册/硬件/产品定义)
- **删改**:2026-09-21 —— 已完成条目删除,仅保留待办;已修项见文末「已完成(勿重复报)」;各保留条目均于 2026-09-21 对照源码复核现态
## 结论总览
| 级别 | 数量 | 说明 |
| 级别 | 剩余 | 说明 |
|---|---|---|
| P0 | 1 | ✅ P0-1 已修复(2026-09-18):配置引擎临时缓冲走 C 库 `malloc`,而 MicroLIB C 堆仅 512 B → 真机配置加载/保存必然失败(模拟器走宿主堆,双端表现分裂) |
| P1 | 10 | 6 项已修复(P1-2/3/4/5/6,2026-09-15;P1-9,2026-09-16);4 项未修:P1-1 ADC / P1-7 MAC 顺序 / P1-8 重建恢复 / P1-10 测试固件 RAM 溢出 |
| P2 | 16 | 健壮性/错误传播/文档失真 |
| P3 | 13 | 卫生项,可随其他修改顺手处理 |
| P0 | 0 | P0-1 已修复(2026-09-18),仅剩真机 `@test` 验证(见「待验证」) |
| P1 | 4 | P1-1 ADC / P1-7 MAC 顺序 / P1-8 重建恢复 / P1-10 测试固件构建验证 |
| P2 | 13 | 健壮性/错误传播/文档失真:P2-1/2/3/4/5/7/8/9/10/11/12/13/15 |
| P3 | 11 | 卫生项:P3-1~8/11/12/13,可随其他修改顺手处理 |
**Top 3(建议优先)**:
1. **P1-1 ADC 采样数据路径在产品构建中死亡** —— 上电后仅采 1 次即永久停止,DTU 核心采集路径实际不工作(若产品定义为持续采集,应升 P0)。
2. **P1-2 墙钟 49.7 天回绕** —— 无人值守部署数月后时间回跳,日志时间戳/RTC 全乱,且自检代码是死的、无法发现。✅ 2026-09-15 已修复(30 天惰性再基准化 + 错误契约 + 哨兵修正)
3. **P1-3/P1-5 配置并发与缺失轮询需一并修** —— UI 保存在 uiTask 直接调 cfg_file,与 netTask 的 load/poll 共享无保护静态态;补上缺失的 `cfg_file_poll` 前必须先做任务串行化,否则会放大竞态。✅ 2026-09-15 已修复(配置引擎属主 = defaultTask,P1-3/P1-5 同一变更落地)
---
## P0
### P0-1 配置引擎临时缓冲用 C 库 malloc(MicroLIB C 堆仅 512 B)→ 真机配置加载/保存必然失败 ✅ 已修复(2026-09-18)
- **位置**:`App/cfg_file.c` 修复前 `:485`(读缓冲 4,097B)/ `:522`(模板输出 5,120B)/ `:1038`(外科保存 Pass1 副本 ≤4,097B)/ `:1050`(保存输出 5,120B);根因参数在 `MDK-ARM/startup_stm32f407xx.s:43` `Heap_Size EQU 0x200`
- **证据**(静态三重,可独立复核):① `.map`(2026-09-16)`0x2001e878 - 0x00000200 Zero RW HEAP` 且 `__heap_limit = 0x2001ea78` → **C 库堆总量 = 0x200 = 512 B**;② 交叉引用 `cfg_file.o(i.s_load_file)` / `(i.s_write_template)` / `(i.cfg_file_save)` `refers to malloc.o(i.malloc)`,请求量 4,097 / 5,120 B,且全仓库无 `pvPortMalloc` retarget;③ `.lnp` 带 `--library_type=microlib`,MicroLIB 堆为固定区不可外扩。调用链:`Src/freertos.c:234 net_cfg_load()` → `Drivers/BSP/NETCFG/net_cfg.c:146 cfg_file_load()` → `s_load_file()` → `malloc`。
- **影响**:真机上配置文件**读不进也写不出**——上电加载回落工厂默认(192.168.1.100/24)、首启出厂模板生成失败、UI 保存与外科保存全部失败;日志签名 `read: malloc 4097B FAIL` / `template: malloc 5120B FAIL` / `load: file read FAIL, factory defaults kept`。**PC 模拟器走宿主 CRT 堆(MB 级)完全正常** → 双端行为分裂,双端 0 错 0 警也照不出来(`--cfgtest` PASS 亦不能证伪)。`test/verify_log.py` Forbidden 含 `FAIL`,一次 `@test` 即可捕获。
- **修复**(2026-09-18 实际实施):① `cfg_file_store` 后端新增 `cfg_store_alloc` / `cfg_store_free` / `cfg_store_heap_free` 三件套——MCU 端 = `pvPortMalloc`/`vPortFree`(取 FreeRTOS 堆 49,152B,与 `lftpd_io.c` 既有模式一致),模拟器端 = `malloc`/`free`;共享核心 `cfg_file.c` 内 C 库分配符号清零,双端仍可同源编译;② 新增编译期堆峰值预算 `CFG_HEAP_BUDGET = 10,240B`(typedef 负数组实现,ARMCC 5 C99 无 `_Static_assert`)——放大 `CFG_FILE_MAX_LEN`/`CFG_OUT_MAX` 会先编译失败,而不是退化为真机运行期失败;③ 四条失败路径(加载读失败 / 模板写失败 / 保存分配失败 / 保存写盘失败)补 `syslog_post(SYSLOG_SELFTEST, …)`,失败进自检记录页而非只留一行串口;`load: OK` 行附带 `heap free` 实测值;④ 文件头"属主任务"注释 netTask → defaultTask(P1-3 遗留漂移)。
- **未采用方案**:静态缓冲(4,097 + 5,120 = 9,217B,当时 SRAM1 仅余 4,488B 放不下,须先做 CCM 迁移);调大 MicroLIB `Heap_Size`/加 `--heap`(只是把"必然失败"变成"够大就侥幸",且该堆无碎片与水位观测)。**流式读写(免整文件驻留内存,+≈1.2KB 即可彻底摆脱暂态堆)列为后续改进项**,见《项目审查与优化建议报告》§4.4.1。
- **验证**:MCU `@build` 0 错 0 警;map 复核 `malloc.o` 不再参与链接、`Removing startup_stm32f407xx.o(HEAP), (512 bytes)` → 静态区 126,584 → **126,064 B**(余 4,488 → **5,008 B**),并新增 `cfg_file.o → cfg_file_store_mcu.o(cfg_store_alloc) → heap_4.o(pvPortMalloc)`;模拟器重建 0 警 + `lvgl_sim.exe --cfgtest` **PASS**(加载 523B → 外部编辑沉降重载 → 外科保存注释/值无损)。**待补**:真机 `@test` 一次,确认 `load: OK` 出现且 Forbidden `FAIL` 零命中。
- **附带发现(工具链陷阱)**:`App/cfg_file.c` 带 UTF-8 BOM(内含中文文档头字符串字面量);编辑工具剥掉 BOM 后 ARMCC 按 CP936 解码 → `s_doc_header` 报 4 条 `#870-D invalid multibyte character sequence`。已按 HEAD 的 BOM 状态复原。**改含中文字面量的文件后必须核对 BOM 未被剥**(`@build` 的 #870-D 是唯一暴露点)。
- **置信度**:high(失败机制 = 链接图 + 工具链堆尺寸双重静态确证;真机正向确认待 `@test`)。
2. **P1-8 网络重建失败无恢复** —— 一次 PHY/芯片抖动 → 网络永久不可用,运行日志无任何痕迹,现场无法定位。
3. **P1-10 CH395F 测试固件构建闭环** —— 预算基线已重建、测试缓冲已瘦身(产品镜像余量 4.4KB → ~49KB),剩 7 配置构建实测 + `@test`。
---
@@ -45,41 +32,6 @@
- **修复建议**:周期 CONVST 重触发(定时器或任务)+ 数据消费任务;若基线版本有意不实现采集,应删除启动调用并以 `APP_ADC_ENABLE` 真实门控。
- **置信度**:high(代码级确证);P0/P1 定级取决于产品定义(需确认,见"待确认")。
### P1-2 墙钟 49.7 天回绕 + 时钟自检死代码 ✅ 已修复(2026-09-15)
- **位置**:`App/util/sys_clock.c`
- **证据**:`sys_clock_get()` 以 `(HAL_GetTick() - s_base_tick) / 1000` 计秒——32 位 tick 49.7 天回绕,无周期基准刷新;`sys_clock_init()` 恒返回 0,`app_main` 中"时钟芯片异常"自检分支永不可达。
- **影响**:连续运行 49.7 天后墙钟整体回退,`/log` 时间戳、FatFS 文件时间、RTC 同步基准全部错乱;时钟芯片真实故障也永远不会被自检发现。
- **修复**(2026-09-15 实际实施):`sys_clock_get` 内 **30 天惰性再基准化**(自我参照、零 I2C、亚秒余数结转、无损;不周期重读 RTC——重锚会吸收 RTC 漂移);`sys_clock_init` 检查 `sd2506_get_time` 返回值 + 写回复验,失败降级为编译期默认时间基准并返回 -1(自检复活);顺带修正"未初始化"哨兵判断对正 int64 永不成立的缺陷。详见 `docs/系统墙钟时间维护说明.md` §3/§6/§7/§9/§12。构建时新发现:本机 ARMCC 按 CP936 解读无 BOM 源文件,字符串字面量含奇数个汉字会吞掉结束引号致编译失败(本次 13 汉字日志串触发)→ 日志串改 ASCII 并沉淀为 AGENTS.md 编码铁律。
- **置信度**:high。
### P1-3 UI 保存路径与 netTask 的 cfg_file 跨任务竞态 ✅ 已修复(2026-09-15)
- **位置**:`Drivers/BSP/UI/ui_page_net_cfg.c:312`(`nc_key_cb` 在 **uiTask 上下文**直接调 `net_cfg_save()` → `cfg_file_save()`)
- **证据**:cfg_file 引擎为单任务静态态设计(解析表/模板缓冲无跨任务保护);netTask(优先级 Normal > uiTask BelowNormal)可在 uiTask 保存中途抢占,执行 reconfig 的 `net_cfg_load` 或(补齐 P1-5 后)周期 `cfg_file_poll`。
- **影响**:第二次保存落入 reconfig 启动窗口(约前 100ms 的读文件+解析)时,两任务读写同一静态解析态 → 配置内容损坏/丢失。当前窗口小(需用户恰好在重建初期再按保存);**补齐 P1-5 的 poll 后窗口变为常态化**(poll 每 ~4s 一次 vs 保存耗时数百 ms 至秒级)。
- **修复**(2026-09-15 实际实施,属主 = **defaultTask**):① UI 保存改跨任务交接——`net_cfg_save_request()`(uiTask:置"待保存"单字节标志 + `SYS_EVT_CFG_SAVE` 事件唤醒,微秒级、不触碰引擎)→ defaultTask `net_cfg_save_run()` 执行写盘,成功触发"立即应用"(`SYS_EVT_NET_RECONFIG` → netTask 重建);交接状态 ENTER/WAIT/OK/ERR 供保存行显示,写盘期间的新请求重位置位不丢失;② `net_stack_bring_up` 不再调 `net_cfg_load`——加载移入 defaultTask 的 `STORAGE_READY` 屏障之前(屏障语义 = 卷挂载 + 配置就绪),netTask 只读 RAM 副本;③ 引擎全部调用(load/save/poll)收敛 defaultTask 单任务串行 → 静态态无交错可能,竞态在结构上消除(不加锁:锁只会把"写坏"换成"网络心跳卡死")。模拟器主循环兼任属主(回调模式,零 CMSIS 依赖)。`@build` 0 错 0 警 + UI 五步门禁全绿。
- **置信度**:medium(引擎静态态共享 + 抢占窗口确证;触发需特定时序)。
### P1-4 lftpd 写路径对 net_send 返回 0 死循环 ✅ 已修复(2026-09-15)
- **位置**:`Drivers/BSP/NET/lftpd/lftpd_inet.c`(`lftpd_inet_write` / `write_string`)
- **证据**:循环体 `p += n; remaining -= n;` 无 `n == 0` 分支;`net_send` 超时(`NET_SEND_TIMEOUT_MS=1000`)且未写入任何字节时返回 0。
- **影响**:对端停滞/链路劣化 → ftpTask 在写循环中空转永不返回 → FTP 整体死亡,只能重启。
- **修复**(2026-09-15 实际实施):`lftpd_inet_write` / `lftpd_inet_write_string` 循环均改为 `n <= 0` → 返回 -1(零进展超时 = 对端未消费数据,判为致命);拆除走调用方既有路径:`send_file` 收到 <0 → 关文件报错 → 命令层回 450(会话保留);`handle_control_channel` 欢迎语路径非零即拆连接;未检查返回值的响应最迟由下一次 `read_line`(≤ `NET_RECV_TIMEOUT_MS`)或代次变化终止会话——任务不再死锁。`@build` 0 错 0 警。
- **置信度**:high。
### P1-5 MCU 端缺失 cfg_file_poll(文档承诺的自动重载不存在)✅ 已修复(2026-09-15)
- **位置**:`App/task/net_task.c`(主循环);对照 `simulator/main.c`(唯一调用点)
- **证据**:`cfg_file_poll()` 仅 PC 模拟器调用;`App/net_cfg.c:157` 注释、`docs/网络配置说明.md:82`、`docs/项目架构总览.md:152` 均承诺"FTP 外部修改 4s 沉降后自动重载,无需重启"。
- **影响**:真机上经 FTP 修改 `/config.ini` 必须重启才生效——文档承诺的功能在 MCU 端缺失。
- **修复**(2026-09-15 实际实施):defaultTask 主循环加 **2s 周期** `cfg_file_poll()`(与模拟器同节拍;4s 沉降去抖 → 检出后重载 + 变更回调 → `SYS_EVT_NET_RECONFIG` → netTask 重建网络,免重启生效)——与 P1-3 同一变更落地:poll 与 UI 保存同在 defaultTask 串行执行,互不交错。
- **置信度**:high。
### P1-6 netTask 双重创建 ✅ 已修复(2026-09-15)
- **位置**:`Src/freertos.c:162`(CubeMX 区无条件创建)+ `:176`(USER CODE,`#ifdef ENABLE_NET_LAYER_TESTS` 再创建一次)
- **证据**:NET 层测试构建下两个 netTask 并发轮询同一 SPI/消息队列;硬件层测试模式下 netTask 仍被创建且持续 `net_poll`,与"testTask 独占 CH395F"的设计矛盾。
- **修复**(2026-09-15 实际实施,基础线程策略):① 删除 `freertos.c` USER CODE 区冗余的 netTask 创建(生成区实例 = 唯一基础线程,全构建存在);② `net_task_func` 入口加 `ENABLE_HW_LAYER_TESTS` 自挂起守卫(不 bring_up、不轮询、不广播 NET_READY)→ 硬件层模式 testTask 独占 CH395F,设计承诺成真。彻底方案(`.ioc` 移除 + 条件创建)经用户拍板未采用:网络线程是基础线程、恒创建,测试模式仅"不运行"(硬件层测试构建仍占 4KB 栈,接受该成本)。
- **验证**:产品 / CH395F-HW(Phase2) 构建 0 错 0 警;守卫零 RAM 增量(126592B = 基线 126584B + 8B `g_test_stats`);A/B 对照(HEAD vs 修复后)确证 NET 层配置的两处缺陷(P1-9/P1-10)均为存量、与本次变更无关。
- **置信度**:high。
### P1-7 MAC 写入顺序违反 trap 文档
- **位置**:`Drivers/BSP/NET/net_socket.c` `net_init()`:`ch395f_init()` → `ch395f_set_mac_addr()`
- **证据**:`docs/问题记录/CH395F_Trap_Records.md` 规定初始化顺序 SET_MAC → SET_IP → INIT_CH395 → SET_PHY;现码把 MAC 放在 INIT 之后。
@@ -94,20 +46,12 @@
- **修复建议**:失败写 syslog 自检记录 + LED 指示 + 周期重试(如 30s 一次),不得自驻留。
- **置信度**:high。
### P1-9 NET 层测试固件编译断裂(s_rx_buf 使用先于声明)✅ 已修复(2026-09-16)
- **位置**:`test/net_test_task.c:60`(`phase6_run` 内引用)vs `:431`(声明)
- **证据**:`s_rx_buf`/`s_tx_buf`(各 32KB)声明在文件后段,`phase6_run` 在 60 行先使用 → ARMCC `#20: identifier "s_rx_buf" is undefined`;文件诞生即此顺序(2026-08 `88160a5`),NET 层配置逾两周不可编译;A/B 对照(HEAD vs P1-6 修复后)报错相同,与 P1-6 变更无关。
- **影响**:全部 NET 层测试构建(Phase 6~11)无法编译;P1-6 的 NET 模式运行验证与 CH395F NET 套件回归被阻塞。
- **修复**(2026-09-16 实际实施):① 两个 static 声明与其依赖的 Phase 8 方向配置块(`PHASE8_DIR_*` / `PHASE8_DIRECTION` / `PHASE8_FILE_SIZE`)整体前移到文件首部(`TEST_BUF_SIZE` 之后、Phase 6 首次使用之前)——方向配置与声明的相对顺序不变,各方向(ECHO/SEND/RECV)的缓冲门控语义不变;② 顺带修复同类伴随缺陷:`phase9_run` 亦使用 `s_rx_buf` 而原声明条件遗漏 Phase 9(PHASE9-only 配置仍会 `#20` 断裂)→ `s_rx_buf` 条件补 `defined(ENABLE_PHASE9_TESTS)`,文件头注释同步更正。
- **验证**(2026-09-16,7 配置构建复验,ARMCC V5.06u7 增量构建):① 产品构建 0 错 0 警,ZI=125952B 与审计基线完全一致(产品配置零静态增量);② PHASE7-only 0 错 0 警且链接成功(该配置无 32KB 静态缓冲,全链绿色);③ PHASE6 / PHASE9 / PHASE10 / PHASE8-ECHO / PHASE8-SEND / PHASE8-RECV 六配置 `net_test_task.c` 编译阶段均 0 错 0 警(#20 消除;ECHO 声明双缓冲、SEND 仅 `s_tx_buf`、RECV 仅 `s_rx_buf`,方向门控逐一实测正确);③ 中各配置链接阶段报 `L6406E/L6407E` scatter 溢出——即修复建议预判的 P1-10 暴露(32KB 缓冲超出 4.4KB 静态余量),与本次修复无关,留待 P1-10 处置。
- **置信度**:high(构建实测复现;修复后 7 配置构建复验通过)。
### P1-10 测试固件静态 RAM 预算溢出(128KB scatter vs 产品镜像 123.6KB)
### P1-10 测试固件静态 RAM 预算溢出(基线已重建、测试缓冲已瘦身,剩构建实测闭环)
- **位置**:`MDK-ARM/STM32F407-Demo/STM32F407-Demo.sct`(`RW_IRAM1 0x20000000 0x00020000` = 128KB;芯片 192KB 的上部 64KB 有意未映射,克隆芯片兼容性考量)
- **证据**:产品构建静态镜像 = RW 632B + ZI 125952B = **123.6KB / 128KB**(余量仅 4.4KB);HW 全阶段固件的 PHASE5 三缓冲(3×4093B ≈ 12.3KB)→ 超 8.7KB(`L6406E` 实测复现);NET 固件的 32KB `s_rx_buf` → 超约 28KB。产品镜像自 2026-09 起 UI 功能增长(runlog/selftest 页、配置引擎、日志引擎等)已吃掉静态预算。
- **影响**:CH395F 套件(HW 全阶段 / NET 层)均不可构建,对应 @test 闭环中断;`docs/内存管理/` 旧表数字与实际失真,预算基线需重建。
- **修复建议**:先全量实测静态/堆建立新基线(`scripts/ram_report.py` + FreeRTOS 堆统计);再按序选择:测试缓冲瘦身(PHASE5 分块、`TEST_BUF_SIZE` 下调)、产品镜像压缩(UI 缓冲/任务栈,含 P2-13 testTask 门控省 4KB);**不建议**扩 scatter 到 192KB(破坏既有克隆芯片兼容决策)。
- **置信度**:high(构建实测 + scatter 文件交叉核对)。
- **历史**(2026-09-15 审计 / 09-16 复现):产品构建静态镜像曾 = 123.6KB/128KB(余量仅 4.4KB);HW 全阶段固件的 PHASE5 三缓冲(3×4093B)→ 超 8.7KB(`L6406E` 实测);NET 固件的 32KB `s_rx_buf` → 超约 28KB;`docs/内存管理/` 旧表数字与实际失真。
- **进展**(2026-09-21,已复核):① 预算基线重建(`docs/内存管理/RAM使用分析与优化方案.md` v1.2):FreeRTOS 堆迁 CCM(RW_CCM 49,184/65,536 B),任务栈(合计 38,912B)改由 CCM 堆分配、不再占主 SRAM;产品构建 RW_IRAM1 = **82,048/131,072 B(62.6%,余 ~49KB)**;② NET 层测试 32KB `s_rx_buf`/`s_tx_buf` 已移除,改小局部缓冲(`rx_buf[300]`/`rx_buf[64]`);③ STORAGE 套件固件 2026-09-20/21 实测可构建可运行(含 deep call chain、破坏性 GD5F 运行)。
- **剩余**:① CH395F 套件(`TEST_SUITE_CH395F`,HW 全阶段 / NET 层 7 配置)实际构建确认链接通过——PHASE5 三静态缓冲 3×4093B 仍在,理论余量足够但未实测;② `@test` 闭环;③ **不建议**扩 scatter 到 192KB(破坏既有克隆芯片兼容决策)。
- **置信度**:high(基线数据来自 2026-09-21 map;测试固件构建未复验)。
---
@@ -115,22 +59,19 @@
| # | 位置 | 问题 | 修复建议 | 置信度 |
|---|---|---|---|---|
| P2-1 | `App/cfg_file.c` | 受管键行 >127 字符时外科保存产生重复键行(值静默截断,旧行残留) | 行长超限时拒绝保存并报错,或整卷重写 | high |
| P2-2 | `Drivers/BSP/CH395F/ch395f.c` | DMA 超时/abort 后不向调用方传播错误(调用方当成功继续 → 静默数据损坏) | 超时路径置错误标志并经返回值/查询接口上报 | high |
| P2-3 | `Drivers/BSP/GD5F2GQ5UE/gd5f2gq5ue.c` `gd5f_bbt_save` | 丢弃 program_load/program_exec 返回值:编程失败仍推进 BBT 版本号并报成功 | 检查返回值,失败不推进版本 | high |
| P2-1 | `App/cfg_file.c` | 受管键行 >127 字符时外科保存产生重复键行(值静默截断,旧行残留;Pass1 匹配仍受 `CFG_LINE_TEST_MAX=127` 限制) | 行长超限时拒绝保存并报错,或整卷重写 | high |
| P2-2 | `Drivers/BSP/CH395F/ch395f.c` | `ch395f_spi_dma_transfer` 为 void:DMA 超时/abort 后不向调用方传播错误(调用方当成功继续 → 静默数据损坏) | 超时路径置错误标志并经返回值/查询接口上报 | high |
| P2-3 | `Drivers/BSP/GD5F2GQ5UE/gd5f2gq5ue.c` `gd5f_bbt_save` | 丢弃 program_load/program_exec/wait_busy 返回值:编程失败仍推进 BBT 版本号并报成功 | 检查返回值,失败不推进版本 | high |
| P2-4 | `Drivers/BSP/GD5F2GQ5UE/nand_ftl.c` `dhara_nand_read` | 忽略 `gd5f_read_from_cache` 返回值(DMA 超时 → 返回成功 + 垃圾数据) | 检查返回值并向上报错 | high |
| P2-5 | `Drivers/BSP/SD2506/sd2506.c` | 负温度解码 `(int8_t)(val \| 0xF0)` → 所有负温读成 -1 | `-(int8_t)(val & 0x7F)` | high |
| P2-6 | `Drivers/BSP/SD2506/sd2506.c` `sd2506_init` | 未使能 WRTC 即写 CTR1(ARST),上电写保护可能静默丢弃配置 | 先开 WRTC 再写 CTR1(或按手册确认写保护默认态) | medium |
| P2-5 | `Drivers/BSP/SD2506/sd2506.c` | 负温度解码 `(int8_t)(val \| 0xF0)` → 所有负温读成错误值(符号-绝对值编码未取补码) | `-(int8_t)(val & 0x7F)` | high |
| P2-7 | `Drivers/BSP/NET/net_select.c` `check_socket_readable` | LISTENING 视为恒可读 → 单连接模式下对监听 socket select(readfds) 永久立即返回(当前无调用方,潜在地雷) | LISTENING 仅在写集合/异常集合计数可读,或明确文档化 | high |
| P2-8 | `App/time_sync.c` + `Drivers/BSP/NET/net_config.h` | `NET_RECV_TIMEOUT_MS=30000`:静默对端使同步任务卡 30s 才恢复 | 同步收包单独用短超时(如 3s),与通用收发超时分离 | high |
| P2-9 | `App/log/sys_log_mcu.c` | 挂载时 mkdir 失败 → `s_fs_ready` 不置位,drain 永久 no-op 无重试 | 周期重试挂载/建目录 | medium |
| P2-8 | `App/time_sync.c` + `Drivers/BSP/NET/net_config.h` | `NET_RECV_TIMEOUT_MS=30000`;且 `time_sync.c:84` 的 `net_recv` 现传 timeout=0(**无限等待**)——静默对端使同步任务永久卡死 | 同步收包单独用短超时(如 3s),与通用收发超时分离 | high |
| P2-9 | `App/log/sys_log_mcu.c` | 挂载时 mkdir 失败 → `s_fs_ready` 不置位,drain 永久 no-op 无重试(`syslog_mcu_mounted` 仅调用一次) | 周期重试挂载/建目录 | medium |
| P2-10 | `App/log/sys_log_mcu.c` | 容量满 unlink 与 UI 读记录(FA_READ)存在竞态窗口 | unlink 前等待读者释放,或双文件轮转 | medium |
| P2-11 | `App/task/net_task.c` | RECONFIG 事件用 `osEventFlagsGet`+Clear,非原子(检查与清除间可丢事件) | 改 `osEventFlagsWait` 原子获取 | high |
| P2-12 | `App/app_cfg.h` | `APP_NET_ENABLE`/`APP_ADC_ENABLE`/`APP_RS485_ENABLE` 全仓库无 .c 引用,纯装饰 | 真实接入模块门控,或从文档/注释中删除"开关"说法 | high |
| P2-13 | `Src/freertos.c:168` | testTask 无条件创建,产品构建空转占 4KB 栈 | 按 `test_config.h` 门控创建 | high |
| P2-14 | `MDK-ARM/build.bat` | ① 成功标记子串匹配:`"10 Error(s), 0 Warning(s)"` 也命中 → 10/20/30… 错误误判 BUILD_OK;② UV4 未运行(路径错/换机)时陈旧 `build_log.txt` 残留成功标记 → 假 PASS | 标记加行前缀(`- 0 Error(s)`);调用 UV4 前先删除旧日志 | high |
| P2-15 | `MDK-ARM/download.bat` | 同 P2-14②:陈旧 "Application running" 掩盖失败烧录 | 调用前先删旧日志 | high |
| P2-16 | `AGENTS.md` 任务栈表 | 表格值全部为实际的 4 倍(表:2048/4096/4096/4096/16384/2048w;`freertos.c` 实际:512/1024/1024/1024/4096/512w,合计 32KB 而非 114KB)——直接扭曲待处理的内存预算基线 | 按 `Src/freertos.c:64-100` 实际值更新表格 | high |
| P2-13 | `Src/freertos.c:183` | testTask 无条件创建,产品构建空转占 2048 words(8KB,CCM 堆,2026-09-21 口径) | 按 `test_config.h` 门控创建 | high |
| P2-15 | `MDK-ARM/download.bat` | 调用 UV4 前不删旧 `download_log.txt`:陈旧 "Application running" 掩盖失败烧录 | 调用前先删旧日志 | high |
---
@@ -146,14 +87,44 @@
| P3-6 | `Drivers/BSP/CH395F/ch395f.c` `ch395f_get_socket_status` | `p_status` 无 NULL 检查 |
| P3-7 | `test/test.txt` | 0 字节空文件(删除或补内容) |
| P3-8 | `.opencode/command/build.md` | 退出码契约写 "2+ = 编译错误",`build.bat` 实际只有 0/1 两档(与 AGENTS.md 一致的是后者) |
| P3-9 | `docs/测试说明/FTP_Test_Guide.md` | 仍描述旧 7s 魔法延时(代码已改为事件屏障) |
| P3-10 | `docs/测试说明/CH395F_Test_Guide.md` | "硬件层模式 netTask 不创建"表述过期(line 87/90/126/146/239 共 5 处,与代码矛盾)✅ 已修复(2026-09-15:改写为"netTask 自挂起(创建但不运行)",与 P1-6 守卫一致) |
| P3-11 | `App/task/adc_task.c` / `rs485_task.c` | 空桩无注释说明原因(建议注明"预留,未启用") |
| P3-12 | `App/time_sync.c` | `len >= 8` 严格判定:TIME 包被 TCP 拆两段时拒绝处理(可容忍,增强为累积到 8 字节再判) |
| P3-13 | `test/ch395f_test_task.c` `test_parse_ip` | 门控为 `ENABLE_HW_LAYER_TESTS`,实际引用仅在 Phase 2/5 → 单选阶段(如仅 Phase 1)时 `#177-D` 未引用函数告警(门控应改为 `PHASE2/PHASE5` 析取) |
---
## 待验证
- **P0-1**(2026-09-18 修复:cfg_file C 库 `malloc` → `cfg_store_alloc/free/heap_free`,MCU 端 = FreeRTOS 堆,`CFG_HEAP_BUDGET=10,240B` 编译期预算 + 四条失败路径自检):真机 `@test` 一次,确认 `load: OK` 出现且 Forbidden `FAIL` 零命中(双端构建/`--cfgtest` 已绿;模拟器宿主堆照不出真机问题,真机正向确认是最后一道门)。
---
## 待确认(需手册/硬件/产品定义,暂不直接改码)
1. TPAFE5160 是否有自动扫描模式(决定 P1-1 定 P0 还是 P1)。
2. CH395F 手册 §9.2.1:`INIT_CH395` 是否锁存 MAC 寄存器(决定 P1-7 修复紧迫度)。
3. `APP_ADC_ENABLE` / `APP_RS485_ENABLE` 是否应在产品构建真实门控模块(关联 P1-1、P2-12、P3-11)。
4. RS-485 PD0 DE 的半双工方向语义需硬件实测确认(本次仅静态审查)。
## 内存预算(支撑 `待处理内容.md`)
现行权威数据 = `docs/内存管理/RAM使用分析与优化方案.md` v1.2(2026-09-21):任务栈在 CCM 堆(defaultTask 1024w / netTask 1024w / ftpTask 1024w / testTask 2048w / uiTask 4096w / timeSyncTask 512w);产品构建 RW_IRAM1 82,048/131,072 B(62.6%)+ RW_CCM 49,184/65,536 B(75.0%);实测堆 `free=8,784 / min_ever=4,848` B;台账工具 `scripts/ram_report.py` + `scripts/stack_report.py`。本清单旧栈表/旧余量数字作废,勿引用。
## 已完成(勿重复报)
- **P0-1**(2026-09-18):配置引擎堆分配走 `cfg_store_alloc`(MCU=FreeRTOS 堆),`malloc.o` 退出链接,静态区 126,584 → 126,064 B;真机 `@test` 见「待验证」。
- **P1-2**(2026-09-15):墙钟 49.7 天回绕 → 30 天惰性再基准化 + init 失败降级返回 -1(自检复活)+ 哨兵修正。
- **P1-3**(2026-09-15):cfg_file 跨任务竞态 → 引擎属主 = defaultTask,UI 保存跨任务交接(`SYS_EVT_CFG_SAVE`)。
- **P1-4**(2026-09-15):lftpd 写路径 `n <= 0` → -1,零进展超时判致命,ftpTask 不再空转。
- **P1-5**(2026-09-15):defaultTask 2s 周期 `cfg_file_poll`(FTP 改配置免重启重载)。
- **P1-6**(2026-09-15):netTask 基础线程唯一实例 + 硬件层测试入口自挂起守卫(testTask 独占 CH395F)。
- **P1-9**(2026-09-16):测试固件 `s_rx_buf`/`s_tx_buf` 声明前移 + Phase 9 方向门控补全(7 配置编译阶段复验通过)。
- **P2-6**:SD2506 上电后不写 CTR1(按手册确认写禁止默认态、删除无效 0x7B 写;ARST 位实位于 CTR3 D7),所有受保护寄存器写均在 WRTC 窗口内。
- **P2-14**:`build.bat` 调 UV4 前先删旧日志(UV4 未运行 → `BUILD_FAIL: no build log`)+ `error:` 诊断检查 + `0 Error(s), 0 Warning(s)` 成功标记。
- **P2-16**(2026-09-21):AGENTS.md 任务栈表已更新为 `freertos.c` 实际值(1024/1024/1024/2048/4096/512w)。
- **P3-9**(2026-09-21):`FTP_Test_Guide.md` 启动时序改写为事件屏障(含 `osFlagsNoClear` 教训 §8.6),旧 7s 魔法延时表述已删。
- **P3-10**(2026-09-15):`CH395F_Test_Guide.md` 改写为"netTask 自挂起(创建但不运行)",与 P1-6 守卫一致。
## 已核验无问题(勿重复报)
- `App/util/ringbuf.c`、`App/util/crc.c`、`App/task/ui_task.c`:结构正确。
@@ -162,26 +133,3 @@
- FatFS 卷归属:产品构建单卷拥有者 = defaultTask 的 `f_mount` 实例,lftpd 复用不另 mount;`FF_FS_REENTRANT=1` ✓。
- CH395F trap 修复在位:Trap 01(listen 顺序)、Trap 10(xTaskNotify)、Trap 11(单连接 accept)、Trap 20(send 分块 `NET_SEND_CHUNK_MAX`)均核验存在。
- 宿主侧:`test/verify_log.py`、`test/run_boot_test.py`、`test/time_sync_server.py`(伪 epoch 与时区处理注释完备)、`tools/menu_gen/gen_menu.py`(自带校验:拒 Tab/缩进非整倍数/节点 >255)、`tools/serial_tool/`(近期已验证)均健康。
## 待确认(需手册/硬件/产品定义,暂不直接改码)
1. TPAFE5160 是否有自动扫描模式(决定 P1-1 定 P0 还是 P1)。
2. CH395F 手册 §9.2.1:`INIT_CH395` 是否锁存 MAC 寄存器(决定 P1-7 修复紧迫度)。
3. `APP_ADC_ENABLE` / `APP_RS485_ENABLE` 是否应在产品构建真实门控模块(关联 P1-1、P2-12、P3-11)。
4. RS-485 PD0 DE 的半双工方向语义需硬件实测确认(本次仅静态审查)。
## 内存预算证据(支撑 `待处理内容.md`)
实测任务栈(`Src/freertos.c:64-100`)合计 **32KB**(AGENTS.md 旧表 114KB 为 4 倍失真值,见 P2-16):
| 任务 | 栈 | 备注 |
|---|---|---|
| defaultTask | 512w (2KB) | FatFS 挂载 + 配置加载/保存/轮询(引擎属主)+ LED |
| netTask | 1024w (4KB) | 含 CH395F SPI 收发路径 |
| ftpTask | 1024w (4KB) | lftpd |
| testTask | 1024w (4KB) | **产品构建空转 → 门控后可省 4KB**(P2-13) |
| uiTask | 4096w (16KB) | 最大栈,需实测高水位后再谈压缩 |
| timeSyncTask | 512w (2KB) | |
静态缓冲(已核验):uiTask 侧 2×`UI_FB_SIZE`=6.4KB 帧缓冲(`ui_port.c:16-18`)+ net_sink 组帧/应答/接收缓冲 ~6.3KB(`ui_net_sink.c:40-42`)。
其余(CH395F DMA 缓冲、FatFS/dhara 页缓冲、netMsgQueue、lftpd 缓冲)建议用 `scripts/ram_report.py` + FreeRTOS heap 统计实测后并入预算表,勿沿用旧表数字。