diag(rtc-only): Phase 8 - 音频卡顿根因诊断埋点 + 数据采集报告
数字人 RTC 模式音频卡顿根因定位。通过 4 类 ESP_LOGW 埋点采集运行时 数据，对照表格判定根因，输出 Phase 9 实施分支决策。 埋点实现（main/application.cc，PHASE8_DIAG_ENABLE 宏开关，关闭后零开销）： - DIAG-1 queue 深度：3 处（出队 + WebSocket 入队 + RTC 入队），50ms 节流 - DIAG-2 codec->OutputData 写入耗时：>15ms 阈值告警 - DIAG-3 WiFi RSSI：OnClockTimer 1Hz - DIAG-4 heap 快照 + 碎片率：OnClockTimer 1Hz 实测结论（见 DIAG_REPORT.md）：用户感知卡顿 = 两个独立根因 - A. 开机播报阶段 ③' codec init 时序缺陷（ES7210 I2C 失败 + 126 次 write_slow 集中在 2-13s） - B. RTC 对话阶段 ⑤ Opus/WebSocket 应用层帧到达抖动 （queue 突发堆积 19 + queue=0 出现 58 次，但 codec 写入 0 次 slow） 完全排除：① CPU 争抢、② PSRAM 带宽、④ WiFi 丢包（RSSI -24~-33dBm 极强）、⑥ 内存碎片（heap 全程稳定） Phase 9 推荐分支 B'（双线修复，原 A/C 的 EAF 方案不适用）： - 9.1 应用层 jitter buffer（fill-threshold + drain）—— 解 B - 9.2 开机 codec init 时序修复（ES7210 reset + ready 等待）—— 解 A - 估时 1 天 ROADMAP 同步：Phase 7 矫正为 battery_psm（实际状态）、Phase 8 新增 诊断、Phase 9 占位待 Phase 8 决策、原"集成测试"挪到 Phase 10。 新增 .planning/STATE.md 记录 roadmap evolution。 Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
4b3206dca3
commit
3dc6cadf49
42
.planning/STATE.md
Normal file
42
.planning/STATE.md
Normal file
@ -0,0 +1,42 @@
|
||||
# STATE — 项目状态追踪
|
||||
|
||||
> 跨 session 的项目状态、roadmap 演化、关键决策记录。本文件用于让新 session 快速恢复项目上下文。
|
||||
|
||||
## Current Milestone
|
||||
|
||||
- **Milestone**: `digital_human_rtc` (数字人 RTC 项目)
|
||||
- **Branch**: `Rtc_AIavatar`
|
||||
- **ROADMAP**: `.planning/milestones/digital_human_rtc/ROADMAP.md`
|
||||
- **总阶段数**: 10
|
||||
- **当前进度**: Phase 1-6 完成，Phase 7 (battery_psm) 进行中
|
||||
|
||||
## Accumulated Context
|
||||
|
||||
### Roadmap Evolution
|
||||
|
||||
记录 roadmap 在项目过程中的演化（按时间倒序，最新在前）：
|
||||
|
||||
- **2026-05-15** — Phase 7 ROADMAP 同步矫正：原 Phase 7 "集成测试 + 推送" 因发现文件系统已有 `phase_07_battery_psm`（电量保护重构）而被重编号为 Phase 10。Phase 7 在 ROADMAP 中改写为指向 `phase_07_battery_psm/README.md`。
|
||||
- **2026-05-15** — Phase 8 added: 数字人 RTC 音频卡顿根因诊断。通过 4 类 ESP_LOGW 埋点（audio queue 深度 / PCM write 耗时 / WiFi RSSI / heap）定位卡顿真因（CPU/PSRAM/DMA/WiFi/Opus/碎片 6 选 1+ 组合），产出 DIAG_REPORT.md 决定 Phase 9 实施策略。
|
||||
- **2026-05-15** — Phase 9 added (占位): 音频卡顿实施优化。具体方案待 Phase 8 数据决策，分支预案 A=EAF 旁路 / B=WiFi 扩容 / C=完整切 EAF+资源再分配 / D=DMA 排查 已列入 ROADMAP。
|
||||
|
||||
### Key Technical Decisions
|
||||
|
||||
- **方案 A vs 方案 B 路线分歧已用 Phase 8 数据驱动决策化解**：
|
||||
- 方案 A = `eaf_dec_*` 旁路替换 lv_gif（保留 LVGL）
|
||||
- 方案 B = 数字人模式完整切 esp_emote_gfx（弃用 LVGL）
|
||||
- 两者选择不靠拍脑袋，靠 Phase 8 诊断报告
|
||||
- **EAF 集成边界确认**：
|
||||
- 数字人模式 LVGL 实际范围只有 `main/dzbj/ai_chat_ui.c` (458 行) + `main/display/lcd_display.cc` 数字人分支 (~300 行)
|
||||
- 不涉及任何 `ui/screens/` 下 SquareLine 界面（属吧唧模式，`CONFIG_BAJI_BADGE_MODE` 编译排除）
|
||||
- `ui_ScreenUpdate` 已确认是吧唧模式 BLE 收图 UI，**非 OTA**，不影响数字人模式
|
||||
- **方案 B 完整切若启用，资源账本**：
|
||||
- 释放：~40KB DRAM + ~80KB PSRAM（LVGL 框架本体）
|
||||
- 投入：WiFi RX 缓冲扩容 ~15KB DRAM + Opus jitter buffer ~10KB PSRAM + RTC SDK jitter ~40KB PSRAM
|
||||
- 净结余：~20KB DRAM + ~10KB PSRAM 仍可备用
|
||||
|
||||
### Open Risks (Phase 9 实施时验证)
|
||||
|
||||
- `gfx_label` 是否支持中文自动换行 + 双行居中（方案 B/C 阻塞点）
|
||||
- `font_puhui_20_4.c`（8.5MB LVGL bitmap font）能否被 EAF 直接复用
|
||||
- `cst816s` 触摸路径在弃用 LVGL 后如何接驳（需确认数字人模式是否需要触摸交互）
|
||||
@ -1,6 +1,6 @@
|
||||
# ROADMAP — 数字人 RTC 项目
|
||||
|
||||
7 个阶段，按依赖关系串行。每个阶段产生原子 commit，可独立 revert。
|
||||
10 个阶段，按依赖关系串行。每个阶段产生原子 commit，可独立 revert。
|
||||
|
||||
## 阶段总览
|
||||
|
||||
@ -14,7 +14,13 @@ Phase 2 (分区表调整) ──┘ │
|
||||
│
|
||||
Phase 6 (RTC 空闲超时联动)
|
||||
│
|
||||
Phase 7 (集成测试 + 推送)
|
||||
Phase 7 (电量保护 + 低功耗重构)
|
||||
│
|
||||
Phase 8 (音频卡顿根因诊断)
|
||||
│
|
||||
Phase 9 (音频卡顿实施优化 - 待定)
|
||||
│
|
||||
Phase 10 (集成测试 + 推送)
|
||||
```
|
||||
|
||||
---
|
||||
@ -341,7 +347,61 @@ static const emotion_gif_map_t emotion_gif_table[] = {
|
||||
|
||||
---
|
||||
|
||||
## Phase 7: 集成测试 + 推送
|
||||
## Phase 7: 电量保护 + 低功耗管理重构
|
||||
|
||||
**目标**：把开机电量保护异步化 + 屏幕低电 UI + PowerSaveTimer 状态机重写 + esp_pm_configure 收口受守卫保护，重构成连贯系统而非局部打补丁。
|
||||
|
||||
**详细规格**：见 [phases/phase_07_battery_psm/README.md](phases/phase_07_battery_psm/README.md)
|
||||
|
||||
**完成标志**：
|
||||
- ✅ 开机不再被电池采样 6 秒阻塞
|
||||
- ✅ 屏幕分级低电 UI 提示（>25% / 15-25% / <15% / <5%）
|
||||
- ✅ PowerSaveTimer `in_sleep_mode_` 状态机无边角
|
||||
- ✅ esp_pm_configure 调用统一收口到 callback 内部
|
||||
|
||||
**产出 commit**：`refactor(power): Phase 7 - 电量保护异步化 + 低功耗状态机重写`
|
||||
|
||||
---
|
||||
|
||||
## Phase 8: 数字人 RTC 音频卡顿根因诊断
|
||||
|
||||
**目标**：通过 4 类 ESP_LOGW 日志埋点采集运行时数据，定位 RTC 音频卡顿真实根因（CPU 争抢 / PSRAM 带宽 / DMA / WiFi / Opus 抖动 / 内存碎片），让数据驱动 Phase 9 的实施策略决策。
|
||||
|
||||
**详细规格**：见 [phases/phase_08_audio_glitch_diag/README.md](phases/phase_08_audio_glitch_diag/README.md)
|
||||
|
||||
**完成标志**：
|
||||
- ✅ 4 处日志埋点编译通过并正常输出
|
||||
- ✅ 实际复现一次卡顿，采集到包含卡顿瞬间的日志
|
||||
- ✅ 产出 `DIAG_REPORT.md` 明确根因判定
|
||||
- ✅ 给出 Phase 9 实施分支推荐（A/B/C/D 之一）
|
||||
|
||||
**产出 commit**：`diag(rtc-only): Phase 8 - 音频卡顿根因诊断埋点 + 数据采集报告`
|
||||
|
||||
---
|
||||
|
||||
## Phase 9: 音频卡顿实施优化（待 Phase 8 数据决策）
|
||||
|
||||
**目标**：根据 Phase 8 `DIAG_REPORT.md` 的根因判定，按预案分支实施优化。**具体方案在 Phase 8 完成后细化为 PLAN.md**。
|
||||
|
||||
**分支预案**：
|
||||
| 分支 | 触发根因 | 实施动作 | 预估工时 |
|
||||
|---|---|---|---|
|
||||
| **A** | 仅 CPU 争抢 | `eaf_dec_*` 解码器旁路替换 `lv_gif`，保留 LVGL 框架 | 1-2 天 |
|
||||
| **B** | 仅 WiFi/网络 | WiFi 缓冲扩容（STATIC_RX 10→16、DYN_RX/TX 32→48、RX_BA_WIN 6→16）| 0.5 天 |
|
||||
| **C** | 组合 ①+④⑤ | 数字人模式完整切 EAF（`CONFIG_BAJI_BADGE_MODE=n` 分支弃用 LVGL）+ 释放的 ~40KB DRAM + ~80KB PSRAM 投到 WiFi/Opus/RTC jitter buffer 扩容 | 3-5 天 |
|
||||
| **D** | DMA/I2S | 取消 EAF 方案，转 DMA 路径排查 | 视具体问题 |
|
||||
|
||||
**完成标志**：
|
||||
- ✅ 选定分支落地代码 + 编译通过
|
||||
- ✅ 卡顿复现场景下听感主观验证：抖动消失或显著降低
|
||||
- ✅ Phase 8 埋点指标改善（`queue` 抖动、`write_slow` 频率均下降）
|
||||
- ✅ 内存/CPU 监控 30 分钟稳定
|
||||
|
||||
**产出 commit**：（按选定分支命名）`perf(rtc-only): Phase 9 - {A/B/C/D 描述}`
|
||||
|
||||
---
|
||||
|
||||
## Phase 10: 集成测试 + 推送
|
||||
|
||||
**目标**：端到端验证 MILESTONE.md 第 6 节全部验收项，推送到 gitea + GitHub。
|
||||
|
||||
@ -359,6 +419,7 @@ static const emotion_gif_map_t emotion_gif_table[] = {
|
||||
|
||||
**完成标志**：
|
||||
- ✅ MILESTONE.md 第 6 节成功标准全部 ✓
|
||||
- ✅ Phase 8/9 音频卡顿问题已解决
|
||||
- ✅ gitea + GitHub 远程已同步
|
||||
- ✅ 文档更新完成
|
||||
|
||||
@ -373,9 +434,12 @@ static const emotion_gif_map_t emotion_gif_table[] = {
|
||||
- Phase 4/5 依赖 Phase 1（dzbj 模块清理完成）+ Phase 3（GIF 资源就位）
|
||||
- Phase 4 ⊥ Phase 5（情绪映射和字幕显示独立，可并行）
|
||||
- Phase 6 依赖 Phase 1（清理 sleep_mgr 调用点）
|
||||
- Phase 7 必须最后
|
||||
- Phase 7 依赖 Phase 6（PowerSaveTimer 状态机重写需 Phase 6 守卫到位）
|
||||
- **Phase 8 依赖 Phase 6（卡顿症状在 Phase 6 收尾发现，需要 RTC 链路稳定）**
|
||||
- **Phase 9 依赖 Phase 8（实施策略由诊断报告决定）**
|
||||
- Phase 10 必须最后（依赖 Phase 9 卡顿解决）
|
||||
|
||||
**建议串行执行顺序**：1 → 2 → 3 → 4 → 5 → 6 → 7（最稳）
|
||||
**建议串行执行顺序**：1 → 2 → 3 → 4 → 5 → 6 → 7 → 8 → 9 → 10
|
||||
|
||||
---
|
||||
|
||||
@ -388,5 +452,8 @@ static const emotion_gif_map_t emotion_gif_table[] = {
|
||||
| Phase 3 | ✅ 完成（commit `7d1c7dc`） |
|
||||
| Phase 4 | ✅ 完成（commit `497c1b4`） |
|
||||
| Phase 5 | ✅ 完成（commit `f2be992`） |
|
||||
| Phase 6 | 🔄 进行中（B+C 双源 + 软退房 + Light Sleep 防护，最新方案见 PLAN 头部"实施变更记录"） |
|
||||
| Phase 7 | ⏳ 待启动 |
|
||||
| Phase 6 | ✅ 完成（commit `b8a5fe9` + `4b7b194` 收尾） |
|
||||
| Phase 7 | 🔄 进行中（[phase_07_battery_psm](phases/phase_07_battery_psm/README.md) 规格已写，实施待启动） |
|
||||
| **Phase 8** | **⏳ 待启动（音频卡顿诊断埋点，新增）** |
|
||||
| **Phase 9** | **⏸️ 阻塞中（待 Phase 8 数据，分支预案 A/B/C/D 已列）** |
|
||||
| Phase 10 | ⏳ 待启动（集成测试 + 推送，原 Phase 7 重编号） |
|
||||
|
||||
@ -0,0 +1,138 @@
|
||||
# Phase 8 — 音频卡顿诊断报告
|
||||
|
||||
> 状态：✅ 已完成
|
||||
> 实测日志：[../../../../05-最新日志.txt](../../../../05-最新日志.txt)（1716 行，777 行 DIAG）
|
||||
|
||||
---
|
||||
|
||||
## 1. 测试环境
|
||||
|
||||
| 项 | 值 |
|
||||
|---|---|
|
||||
| 日期 | 2026-05-15 11:22 |
|
||||
| 设备 | ESP32-S3-N16R8 (Kapi) |
|
||||
| 板子 | movecall-moji-esp32s3 |
|
||||
| 串口 | `/dev/cu.usbmodem834401` |
|
||||
| RSSI 基线 | -24 ~ -33 dBm（极强信号） |
|
||||
| WiFi | airhub, BW20, ch1 |
|
||||
| RTC | 火山 RTC（VolcEngineRTCLite v1.57.207.001） |
|
||||
| 测试时长 | ~70 秒（开机 → RTC 对话 ~45 秒） |
|
||||
| 主观感受 | 开机播报"卡卡在呢"声音抖 + RTC 对话过程中扬声器断续/不连贯 |
|
||||
|
||||
---
|
||||
|
||||
## 2. 用户主观感知
|
||||
|
||||
**用户报告**：两段都有卡顿
|
||||
- **A. 开机播报阶段**："卡卡在呢"语音听感抖
|
||||
- **B. RTC 对话阶段**：AI 回答声音不连贯/断续
|
||||
|
||||
---
|
||||
|
||||
## 3. 关键时段数据对照
|
||||
|
||||
### 3.1 write_slow 时段分布
|
||||
|
||||
| 时段 | write_slow 次数 | 主要场景 |
|
||||
|---|---|---|
|
||||
| 0-2s | 0 | 系统启动 |
|
||||
| **2-13s** | **126** ⚠️ | **开机播报 + standby 播报（PlaySound 路径）** |
|
||||
| 13-21s | 4 | 待机 |
|
||||
| **21-25s** | **16** ⚠️ | **BOOT 按键 → "卡卡在呢"播报** |
|
||||
| **25s+ (RTC 对话期)** | **0 ✓** | **codec 写入完全健康** |
|
||||
|
||||
**write_slow 耗时分布**：50-58ms/帧（PCM 帧时长 60ms 的 83-97%），最大 102ms 单帧
|
||||
|
||||
### 3.2 queue 深度时段分布
|
||||
|
||||
| 时段 | 平均深度 | 最大 | queue=0 次数 | queue≥5 次数 |
|
||||
|---|---|---|---|---|
|
||||
| 0-5s 开机 | 28.4 | 50 | 0 | 29 |
|
||||
| 5-13s 播报 | 21.2 | 48 | 2 | 31 |
|
||||
| 21-25s 连接 | 8.0 | 16 | 1 | 6 |
|
||||
| **25-40s 对话** | **2.4** | 7 | 7 | 21 |
|
||||
| **40s+ 对话** | **2.7** | **19** ⚠️ | **58** ⚠️ | 62 |
|
||||
|
||||
### 3.3 关键突发事件（40s+ 对话期）
|
||||
|
||||
```
|
||||
ts= 44979ms DIAG: queue=12 enq_ws ← WebSocket 入队突发
|
||||
ts= 45039ms DIAG: queue=17 enq_ws ← 50ms 内入队 +5 帧
|
||||
ts= 45089ms DIAG: queue=19 enq_ws ← 100ms 内堆积顶峰
|
||||
ts= 45139ms DIAG: queue=17 deq ← 出队开始消化
|
||||
ts= 45199ms DIAG: queue=19 enq_ws ← 又一波入队
|
||||
ts= 45249ms DIAG: queue=18 deq
|
||||
ts= 45309ms DIAG: queue=16 deq ← 消化中
|
||||
ts= 45369ms DIAG: queue=17 deq
|
||||
ts= 45429ms DIAG: queue=15 deq
|
||||
ts= 45479ms DIAG: queue=15 enq_ws
|
||||
...
|
||||
（在此期间无任何 write_slow，codec 写入正常）
|
||||
```
|
||||
|
||||
### 3.4 ES7210 初始化错误（影响段 A）
|
||||
|
||||
```
|
||||
I (2520) ES8311: Work in Slave mode
|
||||
E (2690) I2C_If: Fail to write to dev 80 ← I2C 0x80 写入失败
|
||||
E (2770) ES7210: Write register fail ← 接连失败
|
||||
E (2770) ES7210: Open fail ← ES7210 输入侧 Open 失败
|
||||
I (2009) ES7210: Enable ES7210_INPUT_MIC1 ← 但随后又"成功"
|
||||
W (2509) DIAG: write_slow 57519us samples=960 ← 同时刻 codec 写入开始持续慢
|
||||
```
|
||||
|
||||
**推测**：ES7210 I2C 初始化报错后虽然继续，但 codec 整体 ready 状态有缺陷 → 开机播报期间每帧 PCM 写入要等 50-58ms。
|
||||
|
||||
### 3.5 RSSI / heap 全程
|
||||
|
||||
- RSSI 全程 **-24 ~ -33 dBm**（极强）→ 物理层 WiFi 完全健康
|
||||
- free_int ~60KB / PSRAM 6.7MB 全程稳定，frag 60% 但不上涨 → 无内存碎片问题
|
||||
|
||||
---
|
||||
|
||||
## 4. 根因判定
|
||||
|
||||
| 候选根因 | 成立？ | 证据 |
|
||||
|---|---|---|
|
||||
| ① CPU 争抢 (LZW vs Opus) | ❌ 排除 | 对话期 0 次 write_slow，codec 时间预算充足 |
|
||||
| ② PSRAM 带宽争抢 | ❌ 排除 | 同上 |
|
||||
| ③ I2S DMA 延迟（通用）| ❌ 排除（对话期）| RTC 对话期写入完全 normal |
|
||||
| **③' codec init 时序缺陷（开机阶段专属）** | **✅ 成立（A）** | ES7210 I2C 失败 + 2-13s 集中 126 次 write_slow |
|
||||
| ④ WiFi 丢包 | ❌ 排除 | RSSI -24 ~ -33 dBm 极强 |
|
||||
| **⑤ Opus/WebSocket 帧到达抖动** | **✅ 成立（B）** | queue 突发堆积 19 + queue=0 出现 58 次（40s+ 对话期） |
|
||||
| ⑥ 内存碎片 | ❌ 排除 | heap 全程稳定 |
|
||||
|
||||
**最终判定**：**两个独立根因 ③'（开机 codec 时序）+ ⑤（应用层网络抖动）**，分别对应用户主观感知的 A 和 B 段。
|
||||
|
||||
---
|
||||
|
||||
## 5. Phase 9 分支推荐
|
||||
|
||||
> 原 PLAN 预案 A/B/C/D 都不完全匹配。本案需要**双线并行修复**。
|
||||
|
||||
### 推荐：分支 B' —— 双线修复（精准化版）
|
||||
|
||||
| 子任务 | 解决问题 | 实施 | 估时 |
|
||||
|---|---|---|---|
|
||||
| **9.1 应用层 jitter buffer**（主线） | ⑤ Opus 帧到达抖动 → 用户感知 B 段卡顿 | 在 `audio_decode_queue_` 消费侧加 "fill-threshold + drain"：队列首次填到 N=4 帧才开始消费；下面阈值若降到 1 帧暂停消费等再次蓄水；上限阈值 12 帧触发丢包/降级（避免无限堆积）| 0.5 天 |
|
||||
| **9.2 开机 codec init 时序修复** | ③' ES7210 init 失败 → 用户感知 A 段卡顿 | 排查 `BoxAudioCodec::Initialize` 路径：①ES7210 reset 时序（拉低/拉高/等待）②`Adev_Codec` open 重试 ③播报前等真正 ready | 0.5 天 |
|
||||
|
||||
### 不做的事（基于数据）
|
||||
|
||||
- ❌ 不引入 esp_emote_gfx（CPU 完全够用，原 A/C 分支无效）
|
||||
- ❌ 不扩 `CONFIG_ESP_WIFI_*_BUFFER_NUM`（物理层 RX 健康）
|
||||
- ❌ 不优化 Opus 解码（耗时未浮现成瓶颈）
|
||||
|
||||
### 实施估时合计：1 天
|
||||
|
||||
---
|
||||
|
||||
## 6. 附录
|
||||
|
||||
- 实测日志：`/Users/rdzleo/Desktop/Baji_Rtc_Toy/05-最新日志.txt`
|
||||
- 关键代码位置：
|
||||
- 入队点：[application.cc:351](../../../../main/application.cc#L351) / [:801](../../../../main/application.cc#L801) / [:2899](../../../../main/application.cc#L2899)
|
||||
- 出队点：[application.cc:2197](../../../../main/application.cc#L2197) 附近
|
||||
- codec 写入：[application.cc:2290](../../../../main/application.cc#L2290)
|
||||
- codec init：`main/audio_codecs/box_audio_codec.cc`（待 Phase 9 改）
|
||||
- PHASE8_DIAG_ENABLE 关闭：`#define PHASE8_DIAG_ENABLE 0`（[main/application.cc](../../../../main/application.cc) 顶部）
|
||||
@ -0,0 +1,367 @@
|
||||
# Phase 8 PLAN — 数字人 RTC 音频卡顿根因诊断
|
||||
|
||||
> 里程碑: `digital_human_rtc`
|
||||
> 阶段目标: 通过 4 类 ESP_LOGW 埋点，定位 RTC 音频卡顿真因（6 候选根因 → 1+ 组合），产出 DIAG_REPORT.md 决定 Phase 9 实施分支（A/B/C/D）。
|
||||
> 性质: **诊断 phase，零业务逻辑改动**，可一键 revert。
|
||||
|
||||
---
|
||||
|
||||
## 0. 调研结论
|
||||
|
||||
### 0.1 关键代码位置
|
||||
|
||||
| 位置 | 用途 | 埋点策略 |
|
||||
|---|---|---|
|
||||
| [main/application.cc:339](../../../../main/application.cc#L339) | 第一处 `audio_decode_queue_.emplace_back(opus)` 入队 | 入队后采样队列深度 |
|
||||
| [main/application.cc:789](../../../../main/application.cc#L789) | RTC 下行数据入队 `audio_decode_queue_.emplace_back(data)` | 入队后采样队列深度 |
|
||||
| [main/application.cc:2155-2156](../../../../main/application.cc#L2155) | `OnAudioOutput()` 中出队 `pop_front()` | 出队后采样队列深度 |
|
||||
| [main/application.cc:2258](../../../../main/application.cc#L2258) | `codec->OutputData(pcm)` 唯一 PCM 写入点 | 写入前后包 timer，>15ms 告警 |
|
||||
| [main/application.cc:1957](../../../../main/application.cc#L1957) | `OnClockTimer()` 周期任务（`clock_ticks_++` 节流，已有 `% 10 == 0` 分支 ≈ 1Hz）| 1Hz 分支挂 RSSI + heap 采样 |
|
||||
| [main/audio_codecs/audio_codec.cc:17](../../../../main/audio_codecs/audio_codec.cc#L17) | `AudioCodec::OutputData` → 内部 `Write` | 不动，timer 包在调用方 |
|
||||
|
||||
### 0.2 已掌握的事实
|
||||
|
||||
- `OnAudioOutput` 在 `AudioLoop` 中每 ~10ms 循环调用（[application.cc:2019](../../../../main/application.cc#L2019)），处理一个完整 PCM 帧（~20ms）
|
||||
- 队列 push/pop 都在 `mutex_` 保护下，size() 调用安全
|
||||
- `background_task_->Schedule()` 异步执行解码 + `codec->OutputData()`，Core 1 上跑
|
||||
- `clock_ticks_` 在 [application.cc:1958](../../../../main/application.cc#L1958) 自增，`% 10 == 0` 分支已存在 → 复用为 1Hz 触发点
|
||||
- `codec->OutputData` 内部 `Write(data, samples)` 是纯虚 → 不同板子（ES7210/ES8311）实现不同，最好在 application.cc 端测耗时，覆盖所有板子
|
||||
|
||||
### 0.3 ESP_LOGW 性能影响评估
|
||||
|
||||
- ESP_LOGW 走 UART0/USB CDC（取决于 `CONFIG_ESP_CONSOLE_*`），单次输出 ~100-500us
|
||||
- 高频打印会拖慢观察对象本身 → 加节流（50ms / 1Hz / 阈值告警）
|
||||
- 不需要切到 USB CDC：当前项目已用 UART0 输出日志且实测可承受 ESP_LOGI 高频打印（参考 phase_06 `🔍 中止后音频[N]` 等密集 INFO 日志）
|
||||
|
||||
---
|
||||
|
||||
## 1. 设计方案
|
||||
|
||||
### 1.1 埋点 4 处（节流策略）
|
||||
|
||||
| 编号 | 位置 | 触发条件 | 输出格式 | 节流 |
|
||||
|---|---|---|---|---|
|
||||
| **DIAG-1** | OnAudioOutput 入口 + 入队点 | 队列深度变化 | `ESP_LOGW("DIAG", "queue=%d ts=%lld", size, esp_timer_get_time())` | 50ms 节流（last_log_us 全局） |
|
||||
| **DIAG-2** | `codec->OutputData(pcm)` 前后 | 写入耗时 > 15ms | `ESP_LOGW("DIAG", "write_slow %lldus samples=%zu", cost, pcm.size())` | 阈值告警（>15000us 才打印） |
|
||||
| **DIAG-3** | OnClockTimer 1Hz 分支 | 1Hz 周期 | `ESP_LOGW("DIAG", "rssi=%d ch=%d", rssi, channel)` | 复用 `clock_ticks_ % 10 == 0` |
|
||||
| **DIAG-4** | OnClockTimer 1Hz 分支 | 1Hz 周期 | `ESP_LOGW("DIAG", "free_int=%d psram=%d largest_int=%d frag=%.1f%%", ...)` | 同 DIAG-3 |
|
||||
|
||||
### 1.2 实现位置统一
|
||||
|
||||
所有埋点集中在 [main/application.cc](../../../../main/application.cc)。**不修改 audio_codecs/ 或其他模块**。便于一次性 revert：
|
||||
|
||||
```cpp
|
||||
// 顶部加包裹宏（编译期开关）
|
||||
#ifndef PHASE8_DIAG_ENABLE
|
||||
#define PHASE8_DIAG_ENABLE 1
|
||||
#endif
|
||||
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
#define DIAG_LOG(fmt, ...) ESP_LOGW("DIAG", fmt, ##__VA_ARGS__)
|
||||
static int64_t g_diag_queue_last_us = 0;
|
||||
#else
|
||||
#define DIAG_LOG(fmt, ...) ((void)0)
|
||||
#endif
|
||||
```
|
||||
|
||||
Phase 8 完成后做 Phase 9 时，可以 `#define PHASE8_DIAG_ENABLE 0` 一键关掉所有埋点。
|
||||
|
||||
### 1.3 复现卡顿的测试场景
|
||||
|
||||
1. **基线对话**（5 分钟）：连续 RTC 对话，每分钟主动说话 2-3 次
|
||||
2. **情绪触发**（5 分钟）：让 AI 说带情绪标签的回复（"（happy）..."、"（sad）..."），触发 GIF 切换瞬间观察 queue + write_slow
|
||||
3. **WiFi 抗扰**（可选）：手机开热点 + 远离路由器，观察 rssi 下降时 queue 是否变空
|
||||
4. **长时压测**（10 分钟）：连续无停顿对话，看是否 free_int / largest_int 持续下降
|
||||
|
||||
日志收集：`idf.py monitor 2>&1 | tee phase_08_diag.log`
|
||||
|
||||
### 1.4 数据分析方法
|
||||
|
||||
筛选 DIAG 日志：`grep "DIAG" phase_08_diag.log > diag_only.log`
|
||||
|
||||
按时间序对照表格：
|
||||
|
||||
| 时间窗口 | queue 序列 | write_slow 次数 | rssi 趋势 | free_int 趋势 | 推断根因 |
|
||||
|---|---|---|---|---|---|
|
||||
| 卡顿前 5s | ? | ? | ? | ? | — |
|
||||
| 卡顿瞬间 | ? | ? | ? | ? | ?（对照表 1） |
|
||||
| 卡顿后 5s | ? | ? | ? | ? | — |
|
||||
|
||||
参照 [README.md §5 卡顿日志特征对照表](README.md#5-卡顿日志特征对照表) 给出根因判定 + Phase 9 分支推荐。
|
||||
|
||||
---
|
||||
|
||||
## 2. 任务清单
|
||||
|
||||
### 任务 2.1 — 顶部包裹宏 + 全局节流变量
|
||||
|
||||
**文件**: `main/application.cc`
|
||||
|
||||
**读取参考**:
|
||||
- 现有 include 顺序（不影响）
|
||||
- 现有静态全局变量风格（参考 `last_subtitle_emotion` 等）
|
||||
|
||||
**改动**（加在 file 顶部 include 之后、其他静态变量附近）:
|
||||
|
||||
```cpp
|
||||
// ============================================================
|
||||
// Phase 8: 音频卡顿诊断埋点（一键开关，关闭后零运行时开销）
|
||||
// ============================================================
|
||||
#ifndef PHASE8_DIAG_ENABLE
|
||||
#define PHASE8_DIAG_ENABLE 1
|
||||
#endif
|
||||
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
static int64_t g_diag_queue_last_us = 0; // queue 深度日志节流（50ms）
|
||||
#endif
|
||||
```
|
||||
|
||||
**验收**:
|
||||
- `grep "PHASE8_DIAG_ENABLE" main/application.cc` 返回至少 1 处
|
||||
- 编译通过：`idf.py build`
|
||||
|
||||
---
|
||||
|
||||
### 任务 2.2 — DIAG-1: queue 深度埋点（3 处）
|
||||
|
||||
**文件**: `main/application.cc`
|
||||
|
||||
**读取参考**:
|
||||
- 第 339 行 `audio_decode_queue_.emplace_back(std::move(opus))`（入队点 1）
|
||||
- 第 789 行 `audio_decode_queue_.emplace_back(std::move(data))`（入队点 2，RTC 下行）
|
||||
- 第 2156 行 `audio_decode_queue_.pop_front()`（出队点）
|
||||
|
||||
**改动**: 在 3 处之后插入节流采样块（共用宏，统一节流）：
|
||||
|
||||
```cpp
|
||||
// 在 339 行 emplace_back 之后立即插入
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
{
|
||||
int64_t now_us = esp_timer_get_time();
|
||||
if (now_us - g_diag_queue_last_us > 50000) { // 50ms 节流
|
||||
g_diag_queue_last_us = now_us;
|
||||
ESP_LOGW("DIAG", "queue=%zu enq1", audio_decode_queue_.size());
|
||||
}
|
||||
}
|
||||
#endif
|
||||
```
|
||||
|
||||
入队点 2（line 789 后）用 tag `enq2`，出队点（line 2156 后）用 tag `deq`。
|
||||
|
||||
**验收**:
|
||||
- `grep -c 'ESP_LOGW("DIAG", "queue=' main/application.cc` 返回 ≥ 3
|
||||
- 编译通过
|
||||
- 烧录后 `idf.py monitor` 能看到 `DIAG: queue=N enqX` / `queue=N deq` 日志
|
||||
|
||||
---
|
||||
|
||||
### 任务 2.3 — DIAG-2: codec OutputData 写入耗时
|
||||
|
||||
**文件**: `main/application.cc`
|
||||
|
||||
**读取参考**:
|
||||
- 第 2258 行 `codec->OutputData(pcm)`
|
||||
|
||||
**改动**: 将该行替换为耗时统计块：
|
||||
|
||||
```cpp
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
int64_t _diag_t = esp_timer_get_time();
|
||||
codec->OutputData(pcm);
|
||||
int64_t _diag_cost = esp_timer_get_time() - _diag_t;
|
||||
if (_diag_cost > 15000) {
|
||||
ESP_LOGW("DIAG", "write_slow %lldus samples=%zu", _diag_cost, pcm.size());
|
||||
}
|
||||
#else
|
||||
codec->OutputData(pcm);// 直接输出PCM数据
|
||||
#endif
|
||||
```
|
||||
|
||||
**验收**:
|
||||
- `grep -n "write_slow" main/application.cc` 返回 1 处（在 codec->OutputData 上下文）
|
||||
- 编译通过
|
||||
- 主动制造卡顿（如同时启动多个 RTC GIF 切换）能在日志中看到至少 1 次 `write_slow` 输出
|
||||
|
||||
---
|
||||
|
||||
### 任务 2.4 — DIAG-3 + DIAG-4: OnClockTimer 1Hz 采样
|
||||
|
||||
**文件**: `main/application.cc`
|
||||
|
||||
**读取参考**:
|
||||
- 第 1957-1985 行 `Application::OnClockTimer()` 完整函数
|
||||
- 现有 `if (clock_ticks_ % 10 == 0)` 分支
|
||||
- ESP-IDF `esp_wifi_sta_get_ap_info` API 签名（`<esp_wifi.h>`）
|
||||
- `heap_caps_get_free_size` / `heap_caps_get_largest_free_block` API（`<esp_heap_caps.h>`）
|
||||
|
||||
**改动**: 在 OnClockTimer 现有的 `% 10 == 0` 分支末尾追加：
|
||||
|
||||
```cpp
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
// DIAG-3: WiFi RSSI（每 ~1s 一次）
|
||||
wifi_ap_record_t _diag_ap;
|
||||
if (esp_wifi_sta_get_ap_info(&_diag_ap) == ESP_OK) {
|
||||
ESP_LOGW("DIAG", "rssi=%d ch=%d", _diag_ap.rssi, _diag_ap.primary);
|
||||
}
|
||||
// DIAG-4: heap snapshot
|
||||
int _diag_free_int = heap_caps_get_free_size(MALLOC_CAP_INTERNAL);
|
||||
int _diag_free_psram = heap_caps_get_free_size(MALLOC_CAP_SPIRAM);
|
||||
int _diag_largest_int = heap_caps_get_largest_free_block(MALLOC_CAP_INTERNAL);
|
||||
float _diag_frag = _diag_free_int > 0 ? (1.0f - (float)_diag_largest_int / (float)_diag_free_int) * 100.0f : 0.0f;
|
||||
ESP_LOGW("DIAG", "free_int=%d psram=%d largest_int=%d frag=%.1f%%",
|
||||
_diag_free_int, _diag_free_psram, _diag_largest_int, _diag_frag);
|
||||
#endif
|
||||
```
|
||||
|
||||
确保 [application.cc](../../../../main/application.cc) 顶部 include 已包含：
|
||||
- `<esp_wifi.h>`（如缺则 add）
|
||||
- `<esp_heap_caps.h>`（如缺则 add）
|
||||
|
||||
**验收**:
|
||||
- `grep -c 'ESP_LOGW("DIAG", "rssi=' main/application.cc` = 1
|
||||
- `grep -c 'ESP_LOGW("DIAG", "free_int=' main/application.cc` = 1
|
||||
- `grep -nE "esp_wifi.h|esp_heap_caps.h" main/application.cc` 至少能找到 esp_wifi.h
|
||||
- 编译通过
|
||||
- 烧录后 1Hz 频率持续输出 `DIAG: rssi=-XX` 和 `DIAG: free_int=...` 日志
|
||||
|
||||
---
|
||||
|
||||
### 任务 2.5 — 编译 + 烧录 + 启动 RTC 对话
|
||||
|
||||
**前置**:
|
||||
- `idf.py set-target esp32s3`（如未设置）
|
||||
- `idf.py menuconfig` 确认 `CONFIG_LOG_DEFAULT_LEVEL >= 3 (WARN)` 否则 ESP_LOGW 不输出
|
||||
|
||||
**步骤**:
|
||||
```bash
|
||||
idf.py build flash monitor 2>&1 | tee .planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/phase_08_diag.log
|
||||
```
|
||||
|
||||
启动后：
|
||||
1. 等待数字人 RTC 连接成功
|
||||
2. 开始连续对话至少 5 分钟（按 §1.3 测试场景）
|
||||
3. 至少触发一次明确卡顿（抖动/嗡嗡感）
|
||||
4. 触发后再保持采样 30 秒
|
||||
5. Ctrl+] 退出 monitor
|
||||
|
||||
**验收**:
|
||||
- 日志文件 `phase_08_diag.log` 已生成且 > 100KB
|
||||
- `grep -c "DIAG:" phase_08_diag.log` ≥ 500（5 分钟 × 多类日志）
|
||||
- 日志中至少有 1 处 `write_slow` 或 `queue=0` 频次密集出现
|
||||
|
||||
---
|
||||
|
||||
### 任务 2.6 — 数据分析 + DIAG_REPORT.md
|
||||
|
||||
**文件**: 新建 `.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/DIAG_REPORT.md`
|
||||
|
||||
**结构**:
|
||||
|
||||
```markdown
|
||||
# Phase 8 — 音频卡顿诊断报告
|
||||
|
||||
## 1. 测试环境
|
||||
- 日期 / 固件 commit / 路由器型号 / 房间距离
|
||||
|
||||
## 2. 卡顿瞬间日志片段
|
||||
（卡顿前 5s + 卡顿瞬间 + 卡顿后 5s 的 DIAG 行）
|
||||
|
||||
## 3. 指标统计
|
||||
| 指标 | 卡顿前 60s 平均 | 卡顿瞬间 | 卡顿后 60s 平均 |
|
||||
| queue | ? | ? | ? |
|
||||
| write_slow 次数 | ? | ? | ? |
|
||||
| rssi | ? | ? | ? |
|
||||
| free_int | ? | ? | ? |
|
||||
| largest_int / free_int | ? | ? | ? |
|
||||
|
||||
## 4. 根因判定
|
||||
对照 README §5 表格：__（① / ② / ③ / ④ / ⑤ / ⑥ 中的一个或多个）__
|
||||
|
||||
## 5. Phase 9 分支推荐
|
||||
推荐分支：__（A / B / C / D）__
|
||||
理由：...
|
||||
|
||||
## 6. 附录
|
||||
- 完整日志文件路径
|
||||
- 分析脚本（可选）
|
||||
```
|
||||
|
||||
**验收**:
|
||||
- `DIAG_REPORT.md` 存在
|
||||
- 第 4 节明确指出 ①-⑥ 中的一个或多个
|
||||
- 第 5 节明确给出 A/B/C/D 之一
|
||||
- 第 2 节附实际日志片段（不是占位符）
|
||||
|
||||
---
|
||||
|
||||
### 任务 2.7 — 提交 commit
|
||||
|
||||
**前置**: 任务 2.1-2.6 全部验收通过
|
||||
|
||||
**改动文件清单**:
|
||||
- `main/application.cc`（埋点）
|
||||
- `.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/PLAN.md`（本文件，已存在）
|
||||
- `.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/DIAG_REPORT.md`
|
||||
- `.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/phase_08_diag.log`（实测日志）
|
||||
|
||||
**commit message**:
|
||||
```
|
||||
diag(rtc-only): Phase 8 - 音频卡顿根因诊断埋点 + 数据采集报告
|
||||
|
||||
- 加 4 处 DIAG ESP_LOGW 埋点：queue 深度 / write_slow / rssi / heap
|
||||
- PHASE8_DIAG_ENABLE 一键开关，关闭后零运行时开销
|
||||
- 实测复现卡顿 + DIAG_REPORT.md 输出根因判定
|
||||
- Phase 9 实施分支推荐：{A/B/C/D}（待 DIAG_REPORT 填）
|
||||
```
|
||||
|
||||
**验收**:
|
||||
- `git log -1 --format=%s` 包含 "Phase 8"
|
||||
- `git show --stat HEAD` 列出预期 4 个文件
|
||||
|
||||
---
|
||||
|
||||
## 3. 任务顺序
|
||||
|
||||
```
|
||||
2.1 顶部宏 → 2.2 queue 埋点 ─┐
|
||||
├→ 2.5 编译烧录 → 2.6 DIAG_REPORT → 2.7 commit
|
||||
2.3 write 埋点 ─┤
|
||||
2.4 1Hz 采样 ─┘
|
||||
```
|
||||
|
||||
2.2 / 2.3 / 2.4 可并行编辑，但都依赖 2.1 的宏定义。
|
||||
|
||||
---
|
||||
|
||||
## 4. 风险与回滚
|
||||
|
||||
| 风险 | 触发条件 | 缓解 / 回滚 |
|
||||
|---|---|---|
|
||||
| ESP_LOGW 自身耗时干扰测量 | 卡顿瞬间日志被自身拖累 | 50ms / 阈值 / 1Hz 已做节流；如仍不准，可改用 ringbuffer + 离线 dump |
|
||||
| `esp_wifi_sta_get_ap_info` 在 STA 未连接时 ENOENT | RTC 连接前调用 | 已用 `== ESP_OK` 守卫 |
|
||||
| heap fragmentation 计算有除零风险 | free_int = 0（极端情况）| 已加 `> 0` 守卫 |
|
||||
| 卡顿无法复现 | 测试场景不足 | 至少跑完 §1.3 三种场景；若仍不复现，扩展到 30 分钟压测 |
|
||||
| 编译期开关失效 | `#ifndef` 被覆盖 | 用 `grep "PHASE8_DIAG_ENABLE" main/application.cc` 确认且没有冲突 |
|
||||
| 一键 revert | Phase 9 完成后需要去除埋点 | 直接 `git revert <Phase8_commit>` 或 `#define PHASE8_DIAG_ENABLE 0` |
|
||||
|
||||
---
|
||||
|
||||
## 5. Phase 8 完成验收清单
|
||||
|
||||
- [ ] 任务 2.1-2.7 全部验收
|
||||
- [ ] `PHASE8_DIAG_ENABLE` 宏一键开关已就位
|
||||
- [ ] 实测日志 `phase_08_diag.log` 已采集（> 5 分钟 RTC 对话 + 至少 1 次卡顿）
|
||||
- [ ] `DIAG_REPORT.md` 明确根因判定（①-⑥ 之一或组合）
|
||||
- [ ] `DIAG_REPORT.md` 明确 Phase 9 实施分支推荐（A/B/C/D 之一）
|
||||
- [ ] commit 推送到 `Rtc_AIavatar` 分支
|
||||
|
||||
---
|
||||
|
||||
## 6. Phase 8 不做的事
|
||||
|
||||
- ❌ 不修改业务逻辑（pure observability）
|
||||
- ❌ 不引入 esp_emote_gfx 依赖
|
||||
- ❌ 不调整 sdkconfig（WiFi 缓冲、PSM、jitter buffer 都不动）
|
||||
- ❌ 不优化 lv_gif / LZW 解码（那是 Phase 9 的事）
|
||||
- ❌ 不写 audio_codecs/ 层埋点（写在 application.cc 端覆盖所有板子足够）
|
||||
- ❌ 不删除已有日志（DIAG 是新增 tag，不冲突）
|
||||
@ -0,0 +1,197 @@
|
||||
# Phase 8：数字人 RTC 音频卡顿根因诊断
|
||||
|
||||
**性质**：诊断 phase（仅埋点 + 数据采集，零业务逻辑改动）
|
||||
**预估工时**：半天
|
||||
**Depends on**：Phase 6（卡顿症状在 Phase 6 收尾发现）
|
||||
|
||||
> ⚠️ Phase 7 在 ROADMAP 旧版中标注为"集成测试 + 推送"，实际已被 [phase_07_battery_psm](../phase_07_battery_psm/README.md)（电量保护 + 低功耗管理重构）占用。原"集成测试 + 推送" phase 后挪到 Phase 10。
|
||||
|
||||
---
|
||||
|
||||
## 1. 背景
|
||||
|
||||
Phase 6 收尾时观察到 RTC 数字人对话期间扬声器音频抖动/卡顿。已采取的对策**未能消除**卡顿：
|
||||
|
||||
- ✅ LVGL 任务绑 Core 0、音频循环绑 Core 1
|
||||
- ✅ GIF 定时器周期从 10ms 拉到 20ms
|
||||
- ✅ GIF 颜色压到 8 色减少 LZW CPU 开销
|
||||
- ✅ DMA flush 串行化到 `background_task_`
|
||||
- ✅ HTTPS 播放参数恢复通过 `background_task_->Schedule()` 串行
|
||||
|
||||
继续盲投优化（如切换 esp_emote_gfx EAF 框架或 WiFi 缓冲扩容）有 3-5 天工时风险，**方向选错就浪费**。
|
||||
|
||||
本 phase 通过**最小日志埋点**采集运行时数据，让根因数据驱动 Phase 9 的实施策略决策。
|
||||
|
||||
---
|
||||
|
||||
## 2. 目标
|
||||
|
||||
通过 4 类 ESP_LOGW 日志埋点采集运行时数据，定位 RTC 音频卡顿的真实主要责任方，从下列候选根因中确认（或确认是组合）：
|
||||
|
||||
| ID | 候选根因 | 验证手段 |
|
||||
|---|---|---|
|
||||
| ① | CPU 争抢（LVGL/GIF LZW 解码 vs Opus 解码） | 单帧 GIF 解码耗时 + audio queue 堆积 |
|
||||
| ② | PSRAM 带宽争抢 | free heap 变化 + cache miss 推断 |
|
||||
| ③ | I2S DMA flush 延迟 | `codec->Write()` 单次耗时 |
|
||||
| ④ | WiFi RX 丢包/重传 | RSSI + queue 空缺 |
|
||||
| ⑤ | Opus 帧到达抖动（网络层） | queue 长期空 + RSSI 正常 |
|
||||
| ⑥ | 内存碎片导致 malloc 卡顿 | free heap 抖动 + largest free block |
|
||||
|
||||
---
|
||||
|
||||
## 3. 任务
|
||||
|
||||
### 任务 1 — 埋点：Opus 解码队列深度
|
||||
|
||||
**位置**：[main/application.cc](../../../../main/application.cc) 的 `OnAudioOutput` 入队/出队点
|
||||
|
||||
**实现**：
|
||||
```cpp
|
||||
// 每次入队或出队后
|
||||
if (esp_log_timestamp() - last_log_ms > 50) { // 50ms 节流
|
||||
last_log_ms = esp_log_timestamp();
|
||||
ESP_LOGW("DIAG", "queue=%d", audio_decode_queue_.size());
|
||||
}
|
||||
```
|
||||
|
||||
**目的**：观察 audio queue 在卡顿瞬间是空（网络/抖动）还是堆积（CPU/带宽）。
|
||||
|
||||
---
|
||||
|
||||
### 任务 2 — 埋点：PCM 写入耗时
|
||||
|
||||
**位置**：[main/application.cc](../../../../main/application.cc) 调用 `codec->Write(pcm, samples)` 前后
|
||||
|
||||
**实现**：
|
||||
```cpp
|
||||
int64_t t = esp_timer_get_time();
|
||||
codec->Write(pcm, samples);
|
||||
int64_t cost = esp_timer_get_time() - t;
|
||||
if (cost > 15000) { // > 15ms 才告警
|
||||
ESP_LOGW("DIAG", "write_slow %lldus", cost);
|
||||
}
|
||||
```
|
||||
|
||||
**目的**：识别 I2S/DMA 路径上的写入阻塞（根因 ③）。
|
||||
|
||||
---
|
||||
|
||||
### 任务 3 — 埋点：WiFi RSSI
|
||||
|
||||
**位置**：周期性任务（建议 1Hz），可挂在现有 `OnClockTimer` 上
|
||||
|
||||
**实现**：
|
||||
```cpp
|
||||
wifi_ap_record_t ap;
|
||||
if (esp_wifi_sta_get_ap_info(&ap) == ESP_OK) {
|
||||
ESP_LOGW("DIAG", "rssi=%d", ap.rssi);
|
||||
}
|
||||
```
|
||||
|
||||
**目的**：判断 WiFi 信号是否参与卡顿（根因 ④⑤）。
|
||||
|
||||
---
|
||||
|
||||
### 任务 4 — 埋点：Internal/PSRAM 可用堆
|
||||
|
||||
**位置**：周期性任务（建议 1Hz），同 OnClockTimer
|
||||
|
||||
**实现**：
|
||||
```cpp
|
||||
ESP_LOGW("DIAG", "free_int=%d free_psram=%d largest_int=%d",
|
||||
heap_caps_get_free_size(MALLOC_CAP_INTERNAL),
|
||||
heap_caps_get_free_size(MALLOC_CAP_SPIRAM),
|
||||
heap_caps_get_largest_free_block(MALLOC_CAP_INTERNAL));
|
||||
```
|
||||
|
||||
**目的**：判断是否有内存碎片（根因 ⑥）或 PSRAM 带宽压力。
|
||||
|
||||
---
|
||||
|
||||
### 任务 5 — 触发卡顿采集
|
||||
|
||||
1. `idf.py build flash monitor` 烧录埋点版本
|
||||
2. 启动数字人 RTC 对话至少 **5 分钟**
|
||||
3. 主动触发数字人 GIF 切换（让 AI 说带情绪标签的话，如"（happy）你好"、"（sad）抱歉"等）观察切换瞬间
|
||||
4. 复现至少一次明确卡顿（抖动/嗡嗡感）
|
||||
5. 用 `idf.py monitor` 保存日志到文件：`monitor 2>&1 | tee phase_08_diag.log`
|
||||
|
||||
---
|
||||
|
||||
### 任务 6 — 数据分析报告
|
||||
|
||||
在本目录下产出 **`DIAG_REPORT.md`**，包含：
|
||||
|
||||
- **卡顿瞬间日志片段**：摘取卡顿前后 5 秒的 DIAG 日志
|
||||
- **根因判定**：对照「卡顿日志特征对照表」（见 §5），明确指认 ①-⑥ 哪一类或组合
|
||||
- **Phase 9 分支推荐**：A / B / C / D 之一（见 §6）
|
||||
- **附录**：完整日志文件或链接
|
||||
|
||||
---
|
||||
|
||||
## 4. 验收标准
|
||||
|
||||
- ✅ 4 处日志埋点编译通过，正常输出 `DIAG` tag 日志
|
||||
- ✅ 实际复现一次卡顿，采集到包含卡顿瞬间的日志
|
||||
- ✅ 写出 `DIAG_REPORT.md`，明确判定根因属于 ①-⑥ 哪一类（或组合）
|
||||
- ✅ 给出 Phase 9 实施分支推荐（A/B/C/D 之一）
|
||||
- ✅ 不引入业务逻辑改动，可一键 revert 埋点代码
|
||||
|
||||
---
|
||||
|
||||
## 5. 卡顿日志特征对照表
|
||||
|
||||
| 日志特征 | 推断根因 | Phase 9 分支 |
|
||||
|---|---|---|
|
||||
| `queue=0` 频繁出现 + `rssi < -70` | WiFi 丢包 | B |
|
||||
| `queue=0` 频繁出现 + `rssi 正常` | Opus 帧抖动 | B |
|
||||
| `write_slow` 频繁 | DMA/I2S 问题 | D |
|
||||
| `queue` 堆积（>5）+ `write_slow` 偶发 | CPU/带宽争抢 | A 或 C |
|
||||
| `largest_int` 持续下降 | 内存碎片 | 单独修复 |
|
||||
| 全都正常但听感差 | 心理学/采样率，与代码无关 | 取消 |
|
||||
|
||||
---
|
||||
|
||||
## 6. Phase 9 实施分支预案
|
||||
|
||||
| 分支 | 根因 | 实施动作 |
|
||||
|---|---|---|
|
||||
| **A** | 仅 CPU 争抢 ① | 用 esp_emote_gfx 的 `eaf_dec_*` 解码器替换 `lv_gif`（LZW），保留 LVGL 框架，旁路渲染到 `lv_canvas`。预估 1-2 天 |
|
||||
| **B** | 仅 WiFi/网络 ④⑤ | WiFi 缓冲扩容（`CONFIG_ESP_WIFI_STATIC_RX_BUFFER_NUM` 10→16、`DYNAMIC_RX/TX_BUFFER_NUM` 32→48、`RX_BA_WIN` 6→16）。预估 0.5 天 |
|
||||
| **C** | 组合 ①+④⑤ | 数字人模式完整切 EAF（仅 `CONFIG_BAJI_BADGE_MODE=n` 分支）：弃用 LVGL，重写 `ai_chat_ui.c` 用 `gfx_obj/gfx_anim/gfx_label`，释放 ~40KB DRAM + ~80KB PSRAM，资源投到 WiFi RX + Opus jitter + RTC SDK jitter 扩容。预估 3-5 天 |
|
||||
| **D** | DMA/I2S ③ | 取消 EAF 方案，转 DMA 路径排查（与 EAF/WiFi 无关）。预估视具体问题 |
|
||||
|
||||
---
|
||||
|
||||
## 7. 不在范围
|
||||
|
||||
- 不修改业务逻辑（纯埋点）
|
||||
- 不引入 esp_emote_gfx 依赖
|
||||
- 不调整 sdkconfig（WiFi 缓冲、jitter buffer 都不动）
|
||||
- 不删除已有日志（埋点是新增）
|
||||
|
||||
---
|
||||
|
||||
## 8. 风险点
|
||||
|
||||
| 风险 | 缓解 |
|
||||
|---|---|
|
||||
| ESP_LOGW 走 UART 输出本身有耗时（~100us），可能影响时序观察 | 50ms 节流，避免高频打印；必要时切到 USB CDC 高速通道 |
|
||||
| WiFi 信号采样频率过高拖累性能 | 限制 1Hz 即可，足以观察 RSSI 趋势 |
|
||||
| 复现卡顿需要特定网络/对话场景 | 至少 5 分钟对话 + 主动触发 GIF 切换 + 让 AI 说情绪标签句 |
|
||||
| 日志埋点本身改变测量结果（观察者效应） | 必要时改用 ringbuffer + 离线 dump，减少在线 IO 开销 |
|
||||
|
||||
---
|
||||
|
||||
## 9. 产出 commit
|
||||
|
||||
```
|
||||
diag(rtc-only): Phase 8 - 音频卡顿根因诊断埋点 + 数据采集报告
|
||||
```
|
||||
|
||||
---
|
||||
|
||||
## 10. 后续 phase
|
||||
|
||||
- **Phase 9**：根据本 phase `DIAG_REPORT.md` 的根因结论，按 §6 分支预案选定实施方案（A/B/C/D）
|
||||
- **Phase 10**（原 ROADMAP 中的 Phase 7）：集成测试 + 推送
|
||||
File diff suppressed because it is too large
Load Diff
@ -49,6 +49,18 @@ extern "C" void ai_chat_resume_animation(void);
|
||||
// 取消注释下行宏可恢复方案 A 作为兜底（双源刷新）。
|
||||
// #define PHASE6_ENABLE_AUDIO_FALLBACK
|
||||
|
||||
// ============================================================
|
||||
// Phase 8: 音频卡顿诊断埋点（一键开关，关闭后零运行时开销）
|
||||
// 完成根因定位后改为 0 或 git revert 即可移除全部埋点。
|
||||
// ============================================================
|
||||
#ifndef PHASE8_DIAG_ENABLE
|
||||
#define PHASE8_DIAG_ENABLE 1
|
||||
#endif
|
||||
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
#include <esp_heap_caps.h>
|
||||
static int64_t g_diag_queue_last_us = 0; // queue 深度日志节流（50ms）
|
||||
#endif
|
||||
|
||||
// 定义设备状态字符串
|
||||
static const char* const STATE_STRINGS[] = {
|
||||
@ -787,6 +799,16 @@ void Application::Start() {
|
||||
std::lock_guard<std::mutex> lock(mutex_);
|
||||
size_t len = data.size();
|
||||
audio_decode_queue_.emplace_back(std::move(data));
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
// Phase 8 DIAG-1: WebSocket 入队后队列深度（50ms 节流）
|
||||
{
|
||||
int64_t _diag_now = esp_timer_get_time();
|
||||
if (_diag_now - g_diag_queue_last_us > 50000) {
|
||||
g_diag_queue_last_us = _diag_now;
|
||||
ESP_LOGW("DIAG", "queue=%zu enq_ws", audio_decode_queue_.size());
|
||||
}
|
||||
}
|
||||
#endif
|
||||
static bool first_enqueue_logged = false;
|
||||
if (!first_enqueue_logged && len > 0) {
|
||||
ESP_LOGI(TAG, "收到下行音频首包入队: 字节=%zu", len);
|
||||
@ -1957,6 +1979,27 @@ void Application::Start() {
|
||||
void Application::OnClockTimer() {
|
||||
clock_ticks_++;
|
||||
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
// Phase 8 DIAG-3: WiFi RSSI（1Hz，clock_timer 周期 1s）
|
||||
{
|
||||
wifi_ap_record_t _diag_ap;
|
||||
if (esp_wifi_sta_get_ap_info(&_diag_ap) == ESP_OK) {
|
||||
ESP_LOGW("DIAG", "rssi=%d ch=%d", _diag_ap.rssi, _diag_ap.primary);
|
||||
}
|
||||
}
|
||||
// Phase 8 DIAG-4: heap 快照 + 碎片率（1Hz）
|
||||
{
|
||||
int _diag_free_int = heap_caps_get_free_size(MALLOC_CAP_INTERNAL);
|
||||
int _diag_free_psram = heap_caps_get_free_size(MALLOC_CAP_SPIRAM);
|
||||
int _diag_largest_int = heap_caps_get_largest_free_block(MALLOC_CAP_INTERNAL);
|
||||
float _diag_frag = _diag_free_int > 0
|
||||
? (1.0f - (float)_diag_largest_int / (float)_diag_free_int) * 100.0f
|
||||
: 0.0f;
|
||||
ESP_LOGW("DIAG", "free_int=%d psram=%d largest_int=%d frag=%.1f%%",
|
||||
_diag_free_int, _diag_free_psram, _diag_largest_int, _diag_frag);
|
||||
}
|
||||
#endif
|
||||
|
||||
// 每10秒打印一次调试信息
|
||||
if (clock_ticks_ % 10 == 0) {
|
||||
int free_sram = heap_caps_get_free_size(MALLOC_CAP_INTERNAL);
|
||||
@ -2154,6 +2197,16 @@ void Application::OnAudioOutput() {
|
||||
|
||||
auto opus = std::move(audio_decode_queue_.front());
|
||||
audio_decode_queue_.pop_front();
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
// Phase 8 DIAG-1: 出队后队列深度（50ms 节流）
|
||||
{
|
||||
int64_t _diag_now = esp_timer_get_time();
|
||||
if (_diag_now - g_diag_queue_last_us > 50000) {
|
||||
g_diag_queue_last_us = _diag_now;
|
||||
ESP_LOGW("DIAG", "queue=%zu deq", audio_decode_queue_.size());
|
||||
}
|
||||
}
|
||||
#endif
|
||||
// 在出队时捕获opus解码标志，避免background_task异步执行时标志已变化
|
||||
// 导致残留的Opus帧被当作PCM播放（产生杂音）
|
||||
bool is_opus_frame = opus_playback_active_.load();
|
||||
@ -2255,7 +2308,17 @@ void Application::OnAudioOutput() {
|
||||
}
|
||||
} else {
|
||||
ESP_LOGD(TAG, "直接输出PCM到编解码器: 样本=%zu", pcm.size());
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
// Phase 8 DIAG-2: codec PCM 写入耗时（>15ms 阈值告警）
|
||||
int64_t _diag_t = esp_timer_get_time();
|
||||
codec->OutputData(pcm);// 直接输出PCM数据
|
||||
int64_t _diag_cost = esp_timer_get_time() - _diag_t;
|
||||
if (_diag_cost > 15000) {
|
||||
ESP_LOGW("DIAG", "write_slow %lldus samples=%zu", _diag_cost, pcm.size());
|
||||
}
|
||||
#else
|
||||
codec->OutputData(pcm);// 直接输出PCM数据
|
||||
#endif
|
||||
#ifdef PHASE6_ENABLE_AUDIO_FALLBACK
|
||||
if (!pcm.empty()) {
|
||||
this->last_audible_output_time_ = std::chrono::steady_clock::now();
|
||||
@ -2827,6 +2890,16 @@ void Application::HttpsPlaybackFromUrl(const std::string& url) {
|
||||
{
|
||||
std::lock_guard<std::mutex> lock(app.mutex_);
|
||||
app.audio_decode_queue_.emplace_back(std::move(opus_frame));
|
||||
#if PHASE8_DIAG_ENABLE
|
||||
// Phase 8 DIAG-1: RTC/HTTPS 入队后队列深度（50ms 节流）
|
||||
{
|
||||
int64_t _diag_now = esp_timer_get_time();
|
||||
if (_diag_now - g_diag_queue_last_us > 50000) {
|
||||
g_diag_queue_last_us = _diag_now;
|
||||
ESP_LOGW("DIAG", "queue=%zu enq_rtc", app.audio_decode_queue_.size());
|
||||
}
|
||||
}
|
||||
#endif
|
||||
}
|
||||
enqueued++;
|
||||
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user