diff --git a/docs/README.md b/docs/README.md index 84fc8179..43461feb 100644 --- a/docs/README.md +++ b/docs/README.md @@ -186,6 +186,7 @@ docs/ | [`GD5F2GQ5UE_Trap_Records.md`](问题记录/GD5F2GQ5UE_Trap_Records.md) | GD5F2GQ5UE SPI NAND 陷阱台账 | | [`SD2506_Trap_Records.md`](问题记录/SD2506_Trap_Records.md) | SD2506 RTC 陷阱台账 | | [`错误码传播审计.md`](问题记录/错误码传播审计.md) | 错误码传播缺陷审计(9 类模式 × 子系统) | +| [`UI任务看门狗停摆分析.md`](问题记录/UI任务看门狗停摆分析.md) | **Task #32 归因**:uiTask 看门狗停摆(L2 引入的间歇性回归)——否掉"CPU 饱和",定位为**优先级饥饿 + 心跳依赖 netTask 往返**;含量化算式、独立缺陷(无新帧仍压环)与 P0/P1/P2 处置建议 | --- diff --git a/docs/问题记录/UI任务看门狗停摆分析.md b/docs/问题记录/UI任务看门狗停摆分析.md new file mode 100644 index 00000000..fbf621ac --- /dev/null +++ b/docs/问题记录/UI任务看门狗停摆分析.md @@ -0,0 +1,267 @@ +# UI 任务看门狗停摆分析(Task #32) + +> **对象**:`[ERR][WD] task stall: mask=0x00000067 req=0x00000077`(缺 bit4 = `TASK_WD_UI`) +> → 连续 8 次(800ms)缺席 → 停喂 IWDG → 复位。 +> **背景**:L2 相量层落地(commit `3762c03`)后**新出现**的间歇性回归:L2 版 3/10 次运行失败, +> 改前基线(`git stash` 重建)0/6。 +> **状态**:**分析完成,处置待确认**(2026-10-10)。本文只做归因,未改动生产代码。 +> **关联**: +> [`../待处理内容.md`](../待处理内容.md)(**N-17** 心跳缺口登记)、 +> [`../子系统设计/看门狗设计说明.md`](../子系统设计/看门狗设计说明.md)(`required_mask` / 抽样窗 / 长耗时白名单)、 +> [`../子系统设计/ADC采样节拍设计说明.md`](../子系统设计/ADC采样节拍设计说明.md)(1 kHz 节拍)、 +> [`../测试说明/实机测试实施指南.md`](../测试说明/实机测试实施指南.md)(停喂取证机制)、 +> [`../../AGENTS.md`](../../AGENTS.md)(看门狗铁律) + +--- + +## 1. 结论速览 + +**用户假设"计算量太大、CPU 负载满了"——方向对(L2 的 CPU 开销确实是触发因素),但结论不成立。** + +实测占空比约 **10%~20%**,距饱和很远(§3 有算式与日志反证)。真正的失效是 +**优先级饥饿 + 心跳路径依赖另一个任务**: + +1. `uiTask` 是 `required_mask` 六个任务里**唯一的 `osPriorityBelowNormal`**(其余五个全是 + `osPriorityNormal`)。FreeRTOS 下**就绪的 Normal 任务永远抢占 BelowNormal 任务**, + 时间片轮转只对**同优先级**生效 → uiTask 只能在"五个 Normal 任务同时阻塞"的缝隙里运行。 +2. `uiTask` 的心跳**不是自产的**:它每轮先调 `ui_net_sink_poll()` → `net_accept()` → + `osMessageQueuePut` + **`xTaskNotifyWait(portMAX_DELAY)`**,即**绕 `netTask` 走一次往返**, + 之后才 `task_wd_beat(TASK_WD_UI)`。**netTask 慢一拍,UI 的心跳就晚一拍。** + +**决定性证据**:失败时掩码 `0x67` 只缺 UI 一位,其余五个任务(default / net / ftp / timeSync / adc) +的心跳**全部正常**。若是 CPU 饱和,Normal 级的 netTask/ftpTask/adcTask 会**一起**掉线——它们没有。 + +--- + +## 2. 证据:失败日志时间线 + +唯一留存的失败日志:`.dsh/skills/serial-assistant/scripts/state/serial.log`(2026-10-10 17:36)。 +(其余失败运行未归档,`docs/测试说明/boot_log_data/` 只存了通过的两次。) + +| 时刻(抓包侧) | 事件 | +|---|---| +| 17:36:12.551 | 内核启动;`reset cause: software (NVIC_SystemReset) (CSR=0x14000000)` | +| 17:36:12.813 | `phasor layer init: OK (inst=5)` | +| 17:36:17.002 | `[FS] FATFS mounted`(距 NAND FTL ready 17:36:12.897 **约 4.1 s**) | +| 17:36:17.196 | `MISS start snap=0x00000067 req=0x00000077 t=4756` | +| 17:36:17.206 | `[WD] armed: timeout ~2498ms (worst ~1701ms), miss_tol=800ms` | +| 17:36:17.206 | `UI task: started, wait net ready` | +| 17:36:17.868 | `[STACK] ui peak_used=488/16384`(UI 尚未渲染) | +| 17:36:18.219 | `UI task: net ready, init port` → 菜单/待机屏初始化 | +| 17:36:18.343 | **`UI net sink: started (port 7003)`** ← **UI 的最后一条日志** | +| 17:36:18.343 | `MISS start snap=0x00000067 req=0x00000077 t=5904` | +| 17:36:19.902 | `[STACK] ui peak_used=4052/16384`(LVGL 开始渲染) | +| 17:36:22.850 | `[ADC_TASK] frames=9957 idle=44 skip=0 seq=10005 frst_err=0 adc1_rc=0 adc1_err=0 ring=10001` | +| 17:36:23.027 | `MISS start snap=0x00000067 req=0x00000077 t=10585` ← **最后一轮 episode 起点** | +| 17:36:23.743 | `STALL snap=0x00000067 req=0x00000077 h=00000067 ×8 mg=330 cf=0 seg=1` | +| 17:36:23.826/.837 | `[ERR][WD] task stall: mask=0x00000067 req=0x00000077 miss=11 / miss=12` | +| 17:36:23.951 | `[STACK] ui peak_used=4052/16384`(与 19.902 相同 → UI 此后**没有推进过**) | +| 17:36:32.855 | `frames=19352 idle=649 skip=0 seq=20005 frst_err=0 adc1_rc=0 adc1_err=288 ring=20001` | +| 17:36:34.981 | 再次启动:`reset cause: software (NVIC_SystemReset)` | + +**读法说明**(`App/util/task_watchdog.c:434`):`t=` 是毫秒计数;`miss=` 是**累计**缺席次数 +(`s_miss_total`),不是连续次数;连续次数 `s_miss_streak` 饱和在 `WD_MISS_TOLERANCE=8`。 +故 `t=10585` 起算、`t≈11385` 达 8 次 → **缺口恰为 800ms**,与 `miss_tol=800ms` 一致。 + +**关键观察**: + +- UI 的最后一条日志是"推流已启动",**之后进入主循环就再没有任何心跳**(`ui peak_used` 冻结在 4052)。 +- 同时段 adcTask、defaultTask(`[STACK]`)、net/ftp/timeSync 全部活着 → **非全局饥饿**。 +- `ui peak_used=4052/16384` → UI 栈余量 75%,**排除 UI 栈溢出**。 + +--- + +## 3. 量化:CPU 到底占了多少(回答"负载满了") + +### 3.1 逐项算式 + +| 项 | 算式 | 结果(@168 MHz,1 ms = 168 000 周期) | +|---|---|---| +| ADC1 顺序扫描 | `ADC_CLOCK_SYNC_PCLK_DIV4`(84 MHz / 4 = 21 MHz);每通道 (144 + 12) 周期 = 156/21 MHz ≈ 7.4 µs × **9 通道** | **≈ 67 µs** | +| TPAFE 原子快照 + 9 路 `adc_input_raw()` | 临界区拷贝 8 值 + 9 次查表 | ≈ 10~20 µs | +| 采样环压帧 + `phasor_run()` | 5 实例 × (20 点窗拷贝 + 20 次取模 + 40 次浮点乘加 + `sqrtf`) ≈ 400~500 周期/实例 | **≈ 10~15 µs** | +| 其中:整数取模 | 窗 100 次(`% 40`,常量 → 魔数乘)+ 计算 100 次(`% n`,**运行期变量 → 走 UDIV/`__aeabi_uidivmod`**) | ≈ 3~7 µs(**占比 0.3%~0.7%**) | +| **adcTask 单拍合计** | 上列之和 | **≈ 0.10~0.13 ms → 占空比 10%~13%** | + +**含 ADC 超时的最坏情形**:日志 `adc1_err=288`(10 s 窗口)= 288 次超时 × `ADC_INPUT_POLL_TIMEOUT_MS=2` ms += **576 ms 额外忙等 / 10 s → +5.8%**。故 adcTask 最坏约 **16%~19%**。 + +### 3.2 结论 + +**合计 10%~20%,不是"负载满了"。** 按 1 ms 节拍算,adcTask 每拍仍能睡约 0.87 ms。 + +### 3.3 日志反证(有力) + +`ring` 计数在两次心跳间严格 **+10000 / 10 s = 恰好 1000 次/秒** +(`10001 → 20001`,`9957 → 19352` 同理)。 + +- 若 adcTask **失去阻塞**(空转),其循环速率 = 1/单拍耗时。按 0.11 ms 的单拍耗时算, + 空转应为 **约 9000 次/秒** → `ring` 会涨 ~90000/10 s。 +- 实测恰好 1000 次/秒 → **adcTask 确实每拍都在 `osDelayUntil` 里睡满**,没有空转。 + +**因此:在失败窗口内,adcTask 不是 CPU 独占者。** 这同时否掉了"计算量把 CPU 吃满"的直接说法。 + +--- + +## 4. 三个结构性脆弱点(均已从代码证实) + +### 4.1 uiTask 优先级垫底(**这是失效能被"定点打击"的根因**) + +`Src/freertos.c` 的任务属性 + `Middlewares/.../CMSIS_RTOS_V2/cmsis_os2.c:444` +(`prio = (UBaseType_t)attr->priority`,FreeRTOS 中**数值越大优先级越高**): + +| 任务 | `osThreadAttr_t.priority` | uxPriority | 在 `required_mask` | +|---|---|---|---| +| defaultTask | `osPriorityNormal` | 24 | ✅ | +| netTask | `osPriorityNormal` | 24 | ✅ | +| ftpTask | `osPriorityNormal` | 24 | ✅ | +| timeSyncTask | `osPriorityNormal` | 24 | ✅ | +| adcTask | `osPriorityNormal` | 24 | ✅ | +| **uiTask** | **`osPriorityBelowNormal`** | **16** | ✅ | +| testTask | `osPriorityBelowNormal` | 16 | ✖(产品构建不创建) | + +→ **uiTask 是必需掩码里唯一的低优先级任务。** 只要有**任何一个** Normal 任务持续就绪, +uiTask 就**完全拿不到 CPU**;`configUSE_TIME_SLICING=1` 只保护**同优先级**之间的公平, +对它无效。 + +### 4.2 UI 心跳依赖 `netTask` 往返(**为什么"只有 UI 掉"**) + +`App/task/ui_task.c:117` 主循环: + +```c +while (1) { + ui_port_step(10); /* LVGL:lv_tick_inc + lv_timer_handler(同步渲染) */ + ui_net_sink_poll(); /* ← 阻塞点 */ + task_wd_beat(TASK_WD_UI);/* ← 心跳在这之后才发 */ + osDelay(10); +} +``` + +`Drivers/BSP/UI/ui_net_sink.c:457` 的 `ui_net_sink_poll()` 在**无远端客户端时**(台架常态) +每轮都走 `net_accept()`;而 `Drivers/BSP/NET/net_socket.c:1222` 的 `net_accept()`: + +```c +if (osMessageQueuePut(netMsgQueueHandle, &msg, 0, osWaitForever) != osOK) { ... } /* 队列深 8,满则永久阻塞 */ +msg.result = net_wait_result("acc", sockfd); /* 等 netTask 回执 */ +``` + +`net_wait_result()`(`net_socket.c:851`)末句是 **`xTaskNotifyWait(..., portMAX_DELAY)`——无限期阻塞**。 + +→ **UI 的心跳周期 = LVGL 渲染 + 一次 `netTask` 往返 + 10 ms。** `netTask` 被延迟多久, +UI 的心跳就晚多久。**这是 UI 独有的依赖,其它任务没有**——正好解释"只有 UI 位缺失"。 + +### 4.3 adcTask 的截止期一旦错过就**不可恢复** + +`App/task/adc_task.c:243`: + +```c +next += ADC_TASK_BEAT_MS; /* 固定 +1ms,不随实际进度修正 */ +(void)osDelayUntil(next); /* ← 返回值被丢弃 */ +``` + +`osDelayUntil` 在**目标时刻已过**时返回 `osErrorParameter`(`cmsis_os2.c:898`)。 +若单拍耗时 > 1 ms,`next` 相对当前时刻**永久落后** → `osDelayUntil` 立刻返回 → +**该任务从此不再阻塞**,以 Normal 优先级空转,直到某个"快拍"把差额追平。 +(单次 2 ms 的慢拍只会多跑一拍就追平,见 §5 的 `ring` 反证;**连续**慢拍才会锁死。) +**返回值是现成的重同步钩子,但被丢弃了。** + +### 4.4 ADC 超时是"2 ms 纯忙等",不阻塞、不让出 + +`App/algo/adc_input.c:21` `ADC_INPUT_POLL_TIMEOUT_MS = 2U`,配合 +`HAL_ADC_PollForConversion()`(`stm32f4xx_hal_adc.c:882`)里的 +`while (!EOC) { if ((HAL_GetTick() - tickstart) > Timeout) return HAL_TIMEOUT; }` +—— **一个通道超时 = 2 ms 不让出 CPU 的自旋**,且发生在 Normal 优先级。 +9 通道全超时最坏 = **18 ms 连占**。这是现成的饥饿源。 + +--- + +## 5. 顺带发现的一个**独立**缺陷:无新帧仍然压环 + +`App/task/adc_task.c:140-176`:`r == 0`(TPAFE 无新帧)时**仍然**执行 +`sample_ring_push_frame()` + `phasor_run()`——只有 `r == -1` 才不压。 + +日志精确印证(`ring = frames + idle`): + +| 窗口 | frames | idle | ring | 校验 | +|---|---|---|---|---| +| 09:36:21 | 9957 | 44 | 10001 | 9957 + 44 = 10001 ✓ | +| 09:36:31 | 19352 | 649 | 20001 | 19352 + 649 = 20001 ✓ | + +**后果**:把**上一拍的重复采样值**塞进 20 点 DFT 窗 → 等效采样间隔被拉长。 +本例 `idle` 占 **3.2%** → 窗长从 20.0 ms 漂到约 20.6 ms → 对 50 Hz 信号相当于 +**约 3% 的频率失配** → 幅值/相位**系统性误差**(不是随机噪声)。 + +这与本次停摆**无关**(不增加多少 CPU),但属**L2 的真实正确性缺陷**,应一并修: +**只在 `r == 1` 时压帧**。 + +--- + +## 6. 为什么"只有 UI"、"为什么间歇" + +- **只有 UI**:UI 是唯一低优先级(§4.1)**且**心跳依赖别的任务(§4.2)的必需任务。 + 其它五个任务只要 100 ms 内被调度到一次就能喂上位,而它们全在 Normal 级,彼此时间片轮转保障。 +- **间歇**:需要一次"某个 Normal 任务连续占用 ≥800 ms"的巧合。候选(见 §7): + `netTask` 回执延迟、`defaultTask` 的长段(syslog → NAND/FTL 写、配置保存)、 + adcTask 的超时突发。 +- **为什么 L2 才暴露**:L2 让 adcTask 每拍多干 10~15 µs 并**引入了 `adc1_err` 超时** + (L1 阶段台架 `adc1_err=0`,L2 阶段出现 288/10 s)→ Normal 级的可用余量被吃掉, + uiTask 的缝隙被挤到 0。**这正是"负载上去以后最先倒下的那块短板"。** + +--- + +## 7. 尚未证实、需要测量的部分(诚实边界) + +1. **800 ms 的具体占用者未锁定。** 本次日志只能证明"UI 被饿/被拖了 800 ms", + 不能区分是 + (a) `netTask` 回执延迟(§4.2),还是 + (b) `defaultTask` 长段(syslog NAND 写 / 配置保存),还是 + (c) adcTask 超时突发(§4.4)。 +2. **`adc1_err=288` 的自身根因未查。** 2 ms 超时对 7.4 µs 的转换而言异常巨大, + 指向 ADC 被反复 `Start/Stop` 或 EOC/OVR 状态异常;需专项测量,不要与本条混谈。 +3. **复位归因存疑。** 日志报 `reset cause: software (NVIC_SystemReset) (CSR=0x14000000)`, + 即 `SFTRSTF|PINRSTF`;而按设计"停喂 → IWDG 自然溢出"应留下 `IWDGRSTF`。 + 本次复位可能来自**测试台架**(ST-LINK 拉 NRST → `PINRSTF`)而非看门狗,需与台架流程对齐。 +4. **`[STACK]` 周期从 2.0 s 拉到 4.05 s**(17:36:19.902 → 23.951,标称 `STACK_PROBE_PERIOD_MS=2000`) + 值得注意,但**不能作为证据**:控制台缓冲满时会**丢行**,该报告也可能只是被丢了。 +5. **`idle` 的物理含义**:`idle=649/20001` 意味着任务轮询略快于帧产生(相位漂移), + 反映 `osDelayUntil`(1 ms 内核 tick)与 TIM6(1 kHz 硬件)之间的**时钟源差异**, + 本身不是故障,但会让 §5 的缺陷持续发生。 + +--- + +## 8. 处置建议(分层,**待确认后执行**) + +### P0 — 缺陷修复(低风险、可独立验证) +1. **§5 压环条件**:`adc_task_func` 改为**仅在 `r == 1` 时**压帧 + `phasor_run()`, + 消除重复采样污染相量窗。 +2. **§4.3 截止期重同步**:`if (osDelayUntil(next) != osOK) { next = osKernelGetTickCount(); }` + —— 让"落后"变成**一次性重同步**,而不是永久空转。 + +### P1 — 结构性(真正消除饥饿,需择一或组合) +3. **把 uiTask 提到 `osPriorityNormal`**(一行改动)。代价:UI 与其它任务平等竞争, + LVGL 单轮 10 ms 量级可能给 netTask 增加抖动;收益:**结构上不可能再被无限期饿死**。 +4. **解开"心跳依赖别的任务"**(§4.2):`ui_task_func` 主循环把 `task_wd_beat(TASK_WD_UI)` + 提到 `ui_net_sink_poll()` **之前**;或给 `net_accept()` 一条**非阻塞**查询路径 + (`NET_MSG_DONTWAIT` 语义)供 UI 推流使用。**这条即使不动优先级也应做**—— + 否则"UI 心跳"实际测的是"netTask 响应性"。 +5. **给 adcTask 的单拍耗时设硬上界**(§4.4):ADC 扫描改 **DMA / 中断驱动**(彻底去掉忙等), + 或至少把单通道超时压到不会吃掉整拍的量级,并在超时时**整拍跳过**而非继续自旋。 + +### P2 — 观测(先能看见,再谈修) +6. 启用现成的 `TEST_LATENCY_PROBE`(`App/task/ui_task.c:109` 的 `ui_loop` 段)→ + 直接得到 UI 循环周期分布,一次性区分"饿死 vs 被拖"。 +7. 新增两个埋点:`adcTask` **单拍耗时**最坏值、`ui_net_sink_poll()` **往返耗时**最坏值。 +8. 停摆取证再加一项:把 `s_miss_hist` 与**各任务在本窗口的调用计数**一起落 `wdev.log`, + 直接指认占用者(现证据只到位图)。 + +### 建议执行顺序 +**P2-6/7 先测(一次 @test 即可拿到区分性数据)→ 按数据定 P1 的方案 → P0 顺路一起修 → 复跑 10 次确认 0/10。** +不建议直接上 P1-3(提优先级)了事:那会**掩盖** §4.2 与 §4.4 两个真实缺陷。 + +--- + +## 变更记录 + +| 日期 | 变更 | +|---|---| +| 2026-10-10 | 创建。基于唯一留存失败日志(`serial.log` @17:36)+ 代码走查完成归因:否掉"CPU 饱和"(实测占空比 10%~20%,`ring` 速率反证无空转),定位为**优先级饥饿(uiTask 唯一 BelowNormal)+ UI 心跳依赖 netTask 往返**;另发现"无新帧仍压环"的独立正确性缺陷;给出 P0/P1/P2 分层处置与"先测量后修"的推荐顺序 |