问题记录:UI 任务看门狗停摆归因(Task #32)

- 新增 docs/问题记录/UI任务看门狗停摆分析.md,并在 docs/README.md §7.3 登记。
- 否掉"CPU 负载饱和":实测 adcTask 占空比 10%~20%(ADC1 扫描约 67us + 压环与
  相量约 10~15us + 超时忙等),且日志 ring 严格 +10000/10s(= 1000 次/秒)
  反证 adcTask 每拍都在 osDelayUntil 里睡满、没有空转。
- 定位真因:uiTask 是 required_mask 六个任务里唯一的 osPriorityBelowNormal
  (其余五个全 Normal,CMSIS 包装直接把优先级赋给 uxPriority),且其心跳必须
  先经 ui_net_sink_poll -> net_accept -> osMessageQueuePut + xTaskNotifyWait
  (portMAX_DELAY) 绕 netTask 一次往返之后才发出。失败日志只缺 bit4(UI)、
  其余任务心跳全在,与"非全局饥饿"一致。
- 另发现一个独立正确性缺陷:adc_task 在 r == 0(TPAFE 无新帧)时仍压环 +
  phasor_run;日志 ring = frames + idle 精确吻合(10001 = 9957+44)。会把重复
  采样点塞进 20 点 DFT 窗,造成约 3% 的等效采样率偏移(系统性误差)。
- 给出 P0(压环条件、osDelayUntil 重同步)/ P1(优先级、解耦心跳、ADC 去忙等)
  / P2(观测)分层处置,并建议先启用现成的 TEST_LATENCY_PROBE 测量再定方案。
- 本文只做归因与方案建议,未改动任何生产代码。
This commit is contained in:
2026-10-10 18:24:06 +08:00
parent c25baba2f1
commit 28bd391035
2 changed files with 268 additions and 0 deletions
+1
View File
@@ -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 处置建议 |
---
@@ -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 分层处置与"先测量后修"的推荐顺序 |