From 3dc6cadf49d64f26cbae8182178aa7a5265da194 Mon Sep 17 00:00:00 2001 From: Rdzleo Date: Fri, 15 May 2026 11:40:42 +0800 Subject: [PATCH] =?UTF-8?q?diag(rtc-only):=20Phase=208=20-=20=E9=9F=B3?= =?UTF-8?q?=E9=A2=91=E5=8D=A1=E9=A1=BF=E6=A0=B9=E5=9B=A0=E8=AF=8A=E6=96=AD?= =?UTF-8?q?=E5=9F=8B=E7=82=B9=20+=20=E6=95=B0=E6=8D=AE=E9=87=87=E9=9B=86?= =?UTF-8?q?=E6=8A=A5=E5=91=8A?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 数字人 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) --- .planning/STATE.md | 42 + .../milestones/digital_human_rtc/ROADMAP.md | 81 +- .../phase_08_audio_glitch_diag/DIAG_REPORT.md | 138 ++ .../phases/phase_08_audio_glitch_diag/PLAN.md | 367 ++++ .../phase_08_audio_glitch_diag/README.md | 197 ++ .../phase_08_diag.log | 1717 +++++++++++++++++ main/application.cc | 73 + 7 files changed, 2608 insertions(+), 7 deletions(-) create mode 100644 .planning/STATE.md create mode 100644 .planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/DIAG_REPORT.md create mode 100644 .planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/PLAN.md create mode 100644 .planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/README.md create mode 100644 .planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/phase_08_diag.log diff --git a/.planning/STATE.md b/.planning/STATE.md new file mode 100644 index 0000000..1bed834 --- /dev/null +++ b/.planning/STATE.md @@ -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 后如何接驳（需确认数字人模式是否需要触摸交互） diff --git a/.planning/milestones/digital_human_rtc/ROADMAP.md b/.planning/milestones/digital_human_rtc/ROADMAP.md index 871daf6..3c198b7 100644 --- a/.planning/milestones/digital_human_rtc/ROADMAP.md +++ b/.planning/milestones/digital_human_rtc/ROADMAP.md @@ -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 重编号） | diff --git a/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/DIAG_REPORT.md b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/DIAG_REPORT.md new file mode 100644 index 0000000..de56e65 --- /dev/null +++ b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/DIAG_REPORT.md @@ -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) 顶部） diff --git a/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/PLAN.md b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/PLAN.md new file mode 100644 index 0000000..ffb0617 --- /dev/null +++ b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/PLAN.md @@ -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 签名（``） +- `heap_caps_get_free_size` / `heap_caps_get_largest_free_block` API（``） + +**改动**: 在 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 已包含： +- ``（如缺则 add） +- ``（如缺则 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 ` 或 `#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，不冲突） diff --git a/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/README.md b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/README.md new file mode 100644 index 0000000..d9b02f6 --- /dev/null +++ b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/README.md @@ -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）：集成测试 + 推送 diff --git a/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/phase_08_diag.log b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/phase_08_diag.log new file mode 100644 index 0000000..7d63970 --- /dev/null +++ b/.planning/milestones/digital_human_rtc/phases/phase_08_audio_glitch_diag/phase_08_diag.log @@ -0,0 +1,1717 @@ +export IDF_PATH='/Users/rdzleo/esp/esp-idf/v5.4.2/esp-idf' +'/Users/rdzleo/.espressif/python_env/idf5.4_py3.13_env/bin/python3' '/Users/rdzleo/esp/esp-idf/v5.4.2/esp-idf/tools/idf_monitor.py' -p /dev/tty.usbmodem834401 -b 115200 --toolchain-prefix xtensa-esp32s3-elf- --make ''/Users/rdzleo/.espressif/python_env/idf5.4_py3.13_env/bin/python3' '/Users/rdzleo/esp/esp-idf/v5.4.2/esp-idf/tools/idf.py'' --target esp32s3 '/Users/rdzleo/Desktop/Baji_Rtc_Toy/build/kapi.elf' +rdzleo@RdzleodeMac-Studio Baji_Rtc_Toy % export IDF_PATH='/Users/rdzleo/esp/esp-idf/v5.4.2/esp-idf' +rdzleo@RdzleodeMac-Studio Baji_Rtc_Toy % '/Users/rdzleo/.espressif/python_env/idf5.4_py3.13_env/bin/python3' '/Users/rdzleo/esp/esp-idf/v5.4.2/esp-idf/tools/idf_monitor.py' -p /d +ev/tty.usbmodem834401 -b 115200 --toolchain-prefix xtensa-esp32s3-elf- --make ''/Users/rdzleo/.espressif/python_env/idf5.4_py3.13_env/bin/python3' '/Users/rdzleo/esp/esp-idf/v5.4 +.2/esp-idf/tools/idf.py'' --target esp32s3 '/Users/rdzleo/Desktop/Baji_Rtc_Toy/build/kapi.elf' +--- Warning: Serial ports accessed as /dev/tty.* will hang gdb if launched. +--- Using /dev/cu.usbmodem834401 instead... +--- esp-idf-monitor 1.8.0 on /dev/cu.usbmodem834401 115200 +--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H +ESP-ROM:esp32s3-20210327 +Build:Mar 27 2021 +rst:0x15 (USB_UART_CHIP_RESET),boot:0xb (SPI_FAST_FLASH_BOOT) +Saved PC:0x42109fa2 +--- 0x42109fa2: spiffs_obj_lu_find_entry_visitor at /Users/rdzleo/esp/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:176 +SPIWP:0xee +mode:DIO, clock div:1 +load:0x3fce2820,len:0x56c +load:0x403c8700,len:0x4 +load:0x403c8704,len:0xb88 +load:0x403cb700,len:0x2df4 +entry 0x403c88f4 +I (48) WeatherApi: 初始化天气API配置 - 默认城市: 北京 +I (49) WeatherApi: WiFi位置缓存限制已设置为: 5 条 +I (49) coexist: coex firmware version: 831ec70 +I (50) coexist: coexist rom version e7ae62f +I (50) main_task: Started on CPU0 +I (60) main_task: Calling app_main() +I (80) BackgroundTask: background_task started +I (80) BluetoothProvisioning: 蓝牙配网对象创建完成 +I (80) button: IoT Button Version: 3.5.0 +I (80) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 +I (80) button: IoT Button Version: 3.5.0 +I (80) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 +I (80) Airhub1: Initializing I2C master bus for audio codec... +I (80) Airhub1: Scanning I2C bus for devices... +I (80) Airhub1: I2C设备在线: 0x18 +I (80) Airhub1: I2C设备在线: 0x40 +I (80) Airhub1: I2C scan completed. Found 2 devices +I (80) DZBJ: 开始初始化显示硬件... +I (80) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 +I (80) st77916: LCD panel create success, version: 1.0.1 +W (210) st77916: The 3Ah command has been used and will be overwritten by external initialization sequence +I (330) LCD: TEON enabled (V-Blank mode) +I (330) LCD: LCD GRAM cleared (black filled) +I (330) DZBJ: LCD 硬件初始化完成 +I (330) gpio: GPIO[5]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2 +I (330) gpio: GPIO[6]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 +I (730) CST816S: IC id: 182 +I (730) LCD: Touch controller initialized successfully +I (730) LVGL: Starting LVGL task +I (730) LCD: LVGL buffer: 14400 bytes (W:360, Lines:20, DMA, single) +I (730) LCD: Touch controller added to LVGL +I (730) DZBJ: LVGL 初始化完成 +I (740) BG_GIF: SPIFFS 未挂载，自动挂载... +I (1100) BG_GIF: 背景图已解码: 360x360 (253.1 KB RGB565) +I (1530) BG_GIF: GIF 已加载到 PSRAM: /spiflash/hiyori_m06.gif (441.8 KB) +I (1590) BG_GIF: ✓ 背景 + GIF 叠加显示启动 +I (1590) AI_CHAT_UI: BG+GIF PoC 启动成功 +I (1590) AI_CHAT_UI: 字幕容器已提升到最上层 +I (1750) Airhub1: 🤖 AI对话模式启动 +I (1750) Airhub1: 初始化按钮... +I (1750) Airhub1: Boot button initialized on GPIO0 +I (1820) Airhub1: Volume up button initialized on GPIO-1 +I (1820) Airhub1: Volume down button initialized on GPIO-1 +I (1820) Airhub1: 故事按键已初始化，GPIO引脚 =4 +I (1820) Airhub1: 所有按键已成功初始化！ +I (1890) Airhub1: IMU传感器未初始化，跳过IoT注册 +I (2110) Airhub1: Initializing battery monitor... +I (2110) Airhub1: ADC calibration initialized +I (2110) Airhub1: 电池状态监控已初始化，GPIO:3 +I (2180) Airhub1: 非生产测试模式且不在对话状态，姿态传感器业务已禁用以节约资源 +I (2190) PowerSaveTimer: Power save timer enabled +I (2190) Airhub1: 🔋 PowerSaveTimer已启用，20秒无活动�进入低功耗模式 +I (2250) Airhub1: 电容触摸板按钮已禁用 (ENABLE_TOUCH_PAD_BUTTONS=0) +I (2250) Application: 打印设置设备状态日志: starting +I (2310) Application: 正常启动流程，将执行开机播报和网络连接播报 +I (2370) Airhub1: Initializing audio codec (duplex)... +I (2370) Airhub1: Creating BoxAudioCodec (ES8311+ES7210, without reference) ... +I (2490) BoxAudioCodec: Duplex channels created +I (2520) ES8311: Work in Slave mode +I (2520) gpio: GPIO[48]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 +E (2690) I2C_If: Fail to write to dev 80 +E (2770) ES7210: Write register fail +E (2770) ES7210: Open fail + +assert failed: BoxAudioCodec::BoxAudioCodec(void*, int, int, gpio_num_t, gpio_num_t, gpio_num_t, gpio_num_t, gpio_num_t, gpio_num_t, uint8_t, uint8_t, bool, bool) box_audio_codec.cc:77 (in_codec_if_ + + +Backtrace: 0x40379da1:0x3fcb2420 0x40386e61:0x3fcb2440 0x4038e5c9:0x3fcb2460 0x4200c817:0x3fcb2580 0x420255fa:0x3fcb2610 0x42015a41:0x3fcb2650 0x4201dcc1:0x3fcb2890 0x4220813b:0x3fcb28b0 +--- 0x40379da1: panic_abort at /Users/rdzleo/esp/esp-idf/components/esp_system/panic.c:469 +--- 0x40386e61: esp_system_abort at /Users/rdzleo/esp/esp-idf/components/esp_system/port/esp_system_chip.c:87 +--- 0x4038e5c9: __assert_func at /Users/rdzleo/esp/esp-idf/components/newlib/assert.c:80 +--- 0x4200c817: BoxAudioCodec::BoxAudioCodec(void*, int, int, gpio_num_t, gpio_num_t, gpio_num_t, gpio_num_t, gpio_num_t, gpio_num_t, unsigned char, unsigned char, bool, bool) at /Users/rdzleo/Desktop/Baji_Rtc_Toy/main/audio_codecs/box_audio_codec.cc:77 +--- 0x420255fa: MovecallMojiESP32S3::GetAudioCodec() at /Users/rdzleo/Desktop/Baji_Rtc_Toy/main/boards/movecall-moji-esp32s3/movecall_moji_esp32s3.cc:1613 +--- 0x42015a41: Application::Start() at /Users/rdzleo/Desktop/Baji_Rtc_Toy/main/application.cc:595 +--- 0x4201dcc1: app_main at /Users/rdzleo/Desktop/Baji_Rtc_Toy/main/main.cc:105 +--- 0x4220813b: main_task at /Users/rdzleo/esp/esp-idf/components/freertos/app_startup.c:208 + + + + +ELF file SHA256: 8a7099b40 + +Rebooting... +ESP-ROM:esp32s3-20210327 +Build:Mar 27 2021 +rst:0xc (RTC_SW_CPU_RST),boot:0xb (SPI_FAST_FLASH_BOOT) +Saved PC:0x40379ce5 +--- 0x40379ce5: esp_restart_noos at /Users/rdzleo/esp/esp-idf/components/esp_system/port/soc/esp32s3/system_internal.c:162 +SPIWP:0xee +mode:DIO, clock div:1 +load:0x3fce2820,len:0x56c +load:0x403c8700,len:0x4 +load:0x403c8704,len:0xb88 +load:0x403cb700,len:0x2df4 +entry 0x403c88f4 +I (48) WeatherApi: 初始化天气API配置 - 默认城市: 北京 +I (48) WeatherApi: WiFi位置缓存限制已设置为: 5 条 +I (49) coexist: coex firmware version: 831ec70 +I (49) coexist: coexist rom version e7ae62f +I (49) main_task: Started on CPU0 +I (59) main_task: Calling app_main() +I (79) BackgroundTask: background_task started +I (79) BluetoothProvisioning: 蓝牙配网对象创建完成 +I (79) button: IoT Button Version: 3.5.0 +I (79) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 +I (79) button: IoT Button Version: 3.5.0 +I (79) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 +I (79) Airhub1: Initializing I2C master bus for audio codec... +I (79) Airhub1: Scanning I2C bus for devices... +I (79) Airhub1: I2C设备在线: 0x18 +I (79) Airhub1: I2C设备在线: 0x40 +I (79) Airhub1: I2C scan completed. Found 2 devices +I (79) DZBJ: 开始初始化显示硬件... +I (79) gpio: GPIO[7]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 +I (79) st77916: LCD panel create success, version: 1.0.1 +W (209) st77916: The 3Ah command has been used and will be overwritten by external initialization sequence +I (329) LCD: TEON enabled (V-Blank mode) +I (329) LCD: LCD GRAM cleared (black filled) +I (329) DZBJ: LCD 硬件初始化完成 +I (329) gpio: GPIO[5]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:2 +I (329) gpio: GPIO[6]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 +I (729) CST816S: IC id: 182 +I (729) LCD: Touch controller initialized successfully +I (729) LVGL: Starting LVGL task +I (729) LCD: LVGL buffer: 14400 bytes (W:360, Lines:20, DMA, single) +I (729) LCD: Touch controller added to LVGL +I (729) DZBJ: LVGL 初始化完成 +I (739) BG_GIF: SPIFFS 未挂载，自动挂载... +I (1099) BG_GIF: 背景图已解码: 360x360 (253.1 KB RGB565) +I (1529) BG_GIF: GIF 已加载到 PSRAM: /spiflash/hiyori_m06.gif (441.8 KB) +I (1589) BG_GIF: ✓ 背景 + GIF 叠加显示启动 +I (1589) AI_CHAT_UI: BG+GIF PoC 启动成功 +I (1589) AI_CHAT_UI: 字幕容器已提升到最上层 +I (1739) Airhub1: 🤖 AI对话模式启动 +I (1749) Airhub1: 初始化按钮... +I (1749) Airhub1: Boot button initialized on GPIO0 +I (1819) Airhub1: Volume up button initialized on GPIO-1 +I (1819) Airhub1: Volume down button initialized on GPIO-1 +I (1819) Airhub1: 故事按键已初始化，GPIO引脚 =4 +I (1819) Airhub1: 所有按键已成功初始化！ +I (1889) Airhub1: IMU传感器未初始化，跳过IoT注册 +I (1959) Airhub1: Initializing battery monitor... +I (1959) Airhub1: ADC calibration initialized +I (1959) Airhub1: 电池状态监控已初始化，GPIO:3 +I (1959) Airhub1: 非生产测试模式且不在对话状态，姿态传感器业务已禁用以节约资源 +I (1959) PowerSaveTimer: Power save timer enabled +I (1959) Airhub1: 🔋 PowerSaveTimer已启用，20秒无活动将进入低功耗模式 +I (1959) Airhub1: 电容触摸板按钮已禁用 (ENABLE_TOUCH_PAD_BUTTONS=0) +I (1959) Application: 打印设置设备状态日志: starting +I (1969) Application: 正常启动流程，将执行开机播报和网络连接播报 +I (1969) Airhub1: Initializing audio codec (duplex)... +I (1969) Airhub1: Creating BoxAudioCodec (ES8311+ES7210, without reference) ... +I (1969) BoxAudioCodec: Duplex channels created +I (1969) ES8311: Work in Slave mode +I (1979) gpio: GPIO[48]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 +I (1979) ES7210: Work in Slave mode +I (1989) ES7210: Enable ES7210_INPUT_MIC1 +I (1989) ES7210: Enable ES7210_INPUT_MIC2 +I (1999) BoxAudioCodec: BoxAudioDevice initialized (duplex) +I (1999) Airhub1: Audio codec initialized successfully +I (1999) Application: 检测到WiFi板卡，将opus编码器复杂度设置为3 +I (1999) OpusResampler: Resampler configured with input sample rate 16000, output sample rate 8000, and channels 1 +I (1999) I2S_IF: channel mode 2 bits:16/16 channel:2 mask:1 +I (1999) I2S_IF: TDM Mode 0 bits:16/16 channel:2 sample_rate:16000 mask:1 +I (1999) I2S_IF: channel mode 0 bits:16/16 channel:2 mask:1 +I (1999) I2S_IF: STD Mode 1 bits:16/16 channel:2 sample_rate:16000 mask:1 +I (1999) ES7210: Bits 16 +I (2009) ES7210: Enable ES7210_INPUT_MIC1 +I (2009) ES7210: Enable ES7210_INPUT_MIC2 +I (2019) ES7210: Unmuted +I (2019) Adev_Codec: Open codec device OK +I (2019) BoxAudioCodec: Input opened: sr=16000 ch=1 mask=0x1 ref=0 +I (2019) AudioCodec: Set input enable to true +I (2019) I2S_IF: channel mode 0 bits:16/16 channel:2 mask:1 +I (2019) I2S_IF: STD Mode 1 bits:16/16 channel:2 sample_rate:16000 mask:1 +I (2029) Adev_Codec: Open codec device OK +I (2039) AudioCodec: Set output enable to true +I (2039) AudioCodec: Audio codec started +I (2039) AudioCodec: 将运行时输出音量设置为：80 +I (2039) Application: 设备启动完成，播放开机播报语音 +W (2069) DIAG: queue=27 deq +I (2069) pp: pp rom version: e7ae62f +I (2069) net80211: net80211 rom version: e7ae62f +I (2079) Application: 开始播放下行音频: 样本=960 采样率=16000 +I (2089) wifi:wifi driver task: 3fcdfc50, prio:23, stack:6656, core=0 +I (2089) wifi:wifi firmware version: 3263cda +I (2089) wifi:wifi certification version: v7.0 +I (2089) wifi:config NVS flash: disabled +I (2089) wifi:config nano formatting: disabled +I (2089) wifi:Init data frame dynamic rx buffer num: 32 +I (2089) wifi:Init dynamic rx mgmt buffer num: 5 +I (2089) wifi:Init management short buffer num: 32 +I (2089) wifi:Init static tx buffer num: 8 +I (2089) wifi:Init tx cache buffer num: 32 +I (2089) wifi:Init static tx FG buffer num: 2 +I (2089) wifi:Init static rx buffer size: 1600 +I (2089) wifi:Init static rx buffer num: 10 +I (2089) wifi:Init dynamic rx buffer num: 32 +I (2089) wifi_init: rx ba win: 16 +I (2089) wifi_init: accept mbox: 6 +I (2089) wifi_init: tcpip mbox: 32 +I (2089) wifi_init: udp mbox: 6 +I (2089) wifi_init: tcp mbox: 6 +I (2089) wifi_init: tcp tx win: 5760 +I (2089) wifi_init: tcp rx win: 5760 +I (2089) wifi_init: tcp mss: 1440 +I (2089) wifi_init: WiFi/LWIP prefer SPIRAM +I (2089) phy_init: phy_version 701,f4f1da3a,Mar 3 2025,15:50:10 +I (2129) phy_init: Saving new calibration data due to checksum failure or outdated calibration data, mode(0) +W (2149) DIAG: queue=48 deq +W (2169) DIAG: write_slow 39172us samples=960 +I (2189) wifi:mode : sta (d0:cf:13:03:bb:f0) +I (2189) wifi:enable tsf +W (2209) DIAG: queue=47 deq +W (2209) DIAG: write_slow 41220us samples=960 +W (2269) DIAG: write_slow 57067us samples=960 +W (2289) DIAG: queue=45 deq +W (2329) DIAG: write_slow 57381us samples=960 +W (2369) DIAG: queue=43 deq +W (2389) DIAG: write_slow 57468us samples=960 +W (2449) DIAG: queue=41 deq +W (2449) DIAG: write_slow 57510us samples=960 +W (2509) DIAG: write_slow 57519us samples=960 +W (2529) DIAG: queue=39 deq +W (2569) DIAG: write_slow 57551us samples=960 +W (2609) DIAG: queue=37 deq +W (2629) DIAG: write_slow 57496us samples=960 +W (2689) DIAG: queue=35 deq +W (2689) DIAG: write_slow 55933us samples=960 +W (2749) DIAG: write_slow 52859us samples=960 +W (2769) DIAG: queue=33 deq +W (2809) DIAG: write_slow 53280us samples=960 +W (2849) DIAG: queue=31 deq +W (2869) DIAG: write_slow 51918us samples=960 +W (2929) DIAG: queue=29 deq +W (2929) DIAG: write_slow 53314us samples=960 +W (2989) DIAG: write_slow 53596us samples=960 +W (3009) DIAG: queue=27 deq +W (3049) DIAG: write_slow 53044us samples=960 +I (3059) Airhub1: ADC: 2311, 原始电压: 2.31V, 计算电池电压: 10.03V, 电量: 100%, 满电电压: 4.20V +I (3059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (3089) DIAG: queue=25 deq +W (3109) DIAG: write_slow 51490us samples=960 +W (3169) DIAG: queue=23 deq +W (3169) DIAG: write_slow 53857us samples=960 +W (3229) DIAG: write_slow 51520us samples=960 +W (3249) DIAG: queue=21 deq +W (3289) DIAG: write_slow 52281us samples=960 +W (3329) DIAG: queue=19 deq +W (3349) DIAG: write_slow 50644us samples=960 +W (3409) DIAG: queue=17 deq +W (3409) DIAG: write_slow 54435us samples=960 +W (3469) DIAG: write_slow 53110us samples=960 +W (3489) DIAG: queue=15 deq +W (3529) DIAG: write_slow 53776us samples=960 +W (3569) DIAG: queue=13 deq +W (3589) DIAG: write_slow 53175us samples=960 +W (3649) DIAG: queue=11 deq +W (3649) DIAG: write_slow 56478us samples=960 +W (3709) DIAG: write_slow 57983us samples=960 +W (3729) DIAG: queue=9 deq +W (3769) DIAG: write_slow 58134us samples=960 +W (3809) DIAG: queue=7 deq +W (3829) DIAG: write_slow 57879us samples=960 +W (3889) DIAG: queue=5 deq +W (3889) DIAG: write_slow 57493us samples=960 +W (3949) DIAG: write_slow 57614us samples=960 +W (3969) DIAG: queue=3 deq +W (4009) DIAG: write_slow 57368us samples=960 +W (4049) DIAG: queue=1 deq +I (4059) Airhub1: ADC: 2315, 原始电压: 2.32V, 计算电池电压: 10.05V, 电量: 100%, 满电电压: 4.20V +I (4059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (4069) DIAG: write_slow 57564us samples=960 +W (4129) DIAG: write_slow 57758us samples=960 +W (4189) DIAG: write_slow 57482us samples=960 +W (4249) DIAG: write_slow 57467us samples=960 +W (4309) DIAG: write_slow 57480us samples=960 +W (4369) DIAG: write_slow 56779us samples=960 +W (4429) DIAG: write_slow 57043us samples=960 +W (4489) DIAG: write_slow 57743us samples=960 +W (4549) DIAG: write_slow 57685us samples=960 +W (4609) DIAG: write_slow 57475us samples=960 +I (4619) wifi: 发现可连接 AP: airhub, BSSID: 70:2a:d7:85:bc:eb, RSSI: -28, Channel: 1, Authmode: 3 +I (4619) WifiBoard: Starting WiFi connection, playing network connection sound +W (4619) wifi:Password length matches WPA2 standards, authmode threshold changes from OPEN to WPA2 +W (4649) DIAG: queue=50 deq +I (4719) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1, snd_ch_cfg:0x0 +I (4719) wifi:state: init -> auth (0xb0) +W (4719) DIAG: write_slow 102311us samples=960 +W (4729) DIAG: queue=48 deq +W (4749) DIAG: write_slow 27032us samples=960 +I (4769) wifi:state: auth -> assoc (0x0) +I (4779) wifi:state: assoc -> run (0x10) +W (4809) DIAG: write_slow 57648us samples=960 +W (4809) DIAG: queue=46 deq +I (4829) wifi:connected with airhub, aid = 5, channel 1, BW20, bssid = 70:2a:d7:85:bc:eb +I (4829) wifi:security: WPA2-PSK, phy: bgn, rssi: -28 +I (4829) wifi:pm start, type: 1 + +I (4829) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us +I (4829) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000 +W (4869) DIAG: write_slow 57210us samples=960 +I (4869) wifi:AP's beacon interval = 102400 us, DTIM period = 1 +W (4889) DIAG: queue=44 deq +W (4929) DIAG: write_slow 57082us samples=960 +W (4969) DIAG: queue=42 deq +W (4989) DIAG: write_slow 57309us samples=960 +W (5049) DIAG: write_slow 57680us samples=960 +W (5049) DIAG: queue=40 deq +I (5059) Airhub1: ADC: 2318, 原始电压: 2.32V, 计算电池电压: 10.06V, 电量: 100%, 满电电压: 4.20V +I (5059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (5109) DIAG: write_slow 57986us samples=960 +W (5129) DIAG: queue=38 deq +W (5169) DIAG: write_slow 57198us samples=960 +W (5209) DIAG: queue=36 deq +W (5229) DIAG: write_slow 57329us samples=960 +W (5289) DIAG: write_slow 57420us samples=960 +W (5289) DIAG: queue=34 deq +W (5349) DIAG: write_slow 57542us samples=960 +W (5369) DIAG: queue=32 deq +I (5369) wifi:idx:0 (ifx:0, 70:2a:d7:85:bc:eb), tid:0, ssn:0, winSize:64 +W (5409) DIAG: write_slow 57426us samples=960 +W (5449) DIAG: queue=30 deq +W (5469) DIAG: write_slow 57437us samples=960 +W (5529) DIAG: write_slow 56016us samples=960 +W (5529) DIAG: queue=28 deq +W (5589) DIAG: write_slow 56574us samples=960 +W (5609) DIAG: queue=26 deq +W (5649) DIAG: write_slow 57250us samples=960 +W (5689) DIAG: queue=24 deq +W (5709) DIAG: write_slow 57882us samples=960 +W (5769) DIAG: write_slow 57836us samples=960 +W (5769) DIAG: queue=22 deq +W (5829) DIAG: write_slow 57801us samples=960 +W (5849) DIAG: queue=20 deq +W (5889) DIAG: write_slow 57381us samples=960 +W (5929) DIAG: queue=18 deq +W (5949) DIAG: write_slow 57664us samples=960 +W (6009) DIAG: write_slow 57651us samples=960 +W (6009) DIAG: queue=16 deq +I (6059) Airhub1: ADC: 2319, 原始电压: 2.32V, 计算电池电压: 10.06V, 电量: 100%, 满电电压: 4.20V +I (6059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (6069) DIAG: write_slow 57166us samples=960 +W (6089) DIAG: queue=14 deq +W (6129) DIAG: write_slow 57340us samples=960 +W (6169) DIAG: queue=12 deq +W (6189) DIAG: write_slow 56989us samples=960 +W (6249) DIAG: write_slow 56982us samples=960 +W (6249) DIAG: queue=10 deq +W (6309) DIAG: write_slow 57123us samples=960 +W (6329) DIAG: queue=8 deq +W (6369) DIAG: write_slow 57181us samples=960 +W (6409) DIAG: queue=6 deq +W (6429) DIAG: write_slow 57198us samples=960 +I (6469) wifi: Got IP: 192.168.124.92 +I (6469) esp_netif_handlers: sta ip: 192.168.124.92, mask: 255.255.255.0, gw: 192.168.124.1 +W (6489) DIAG: write_slow 56975us samples=960 +W (6489) DIAG: queue=4 deq +W (6549) DIAG: write_slow 56615us samples=960 +W (6569) DIAG: queue=2 deq +W (6609) DIAG: write_slow 56879us samples=960 +W (6649) DIAG: queue=0 deq +W (6669) DIAG: write_slow 56995us samples=960 +W (6729) DIAG: write_slow 57319us samples=960 +W (6789) DIAG: write_slow 57454us samples=960 +W (6849) DIAG: write_slow 56768us samples=960 +W (6909) DIAG: write_slow 57515us samples=960 +W (6969) DIAG: write_slow 57204us samples=960 +W (7029) DIAG: write_slow 57573us samples=960 +I (7059) Airhub1: ADC: 2325, 原始电压: 2.33V, 计算电池电压: 10.09V, 电量: 100%, 满电电压: 4.20V +I (7059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (7089) DIAG: write_slow 57776us samples=960 +W (7149) DIAG: write_slow 57346us samples=960 +W (7209) DIAG: write_slow 57525us samples=960 +W (7269) DIAG: write_slow 57468us samples=960 +W (7329) DIAG: write_slow 57450us samples=960 +W (7389) DIAG: write_slow 57491us samples=960 +W (7449) DIAG: write_slow 57489us samples=960 +W (7509) DIAG: write_slow 57175us samples=960 +W (7569) DIAG: write_slow 57223us samples=960 +W (7629) DIAG: write_slow 56834us samples=960 +W (7689) DIAG: write_slow 57379us samples=960 +W (7749) DIAG: write_slow 57857us samples=960 +W (7809) DIAG: write_slow 57884us samples=960 +W (7869) DIAG: write_slow 57911us samples=960 +W (7929) DIAG: write_slow 57514us samples=960 +W (7989) DIAG: write_slow 57722us samples=960 +W (8049) DIAG: write_slow 57879us samples=960 +I (8059) Airhub1: ADC: 2329, 原始电压: 2.33V, 计算电池电压: 10.11V, 电量: 100%, 满电电压: 4.20V +I (8059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (8109) DIAG: write_slow 57891us samples=960 +W (8169) DIAG: write_slow 57364us samples=960 +I (9059) Airhub1: ADC: 2334, 原始电压: 2.33V, 计算电池电压: 10.13V, 电量: 100%, 满电电压: 4.20V +I (9059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +I (10059) Airhub1: ADC: 2334, 原始电压: 2.33V, 计算电池电压: 10.13V, 电量: 100%, 满电电压: 4.20V +I (10059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +I (10689) wifi:idx:1 (ifx:0, 70:2a:d7:85:bc:eb), tid:3, ssn:0, winSize:64 +I (10779) VolcRtcProtocol: 设置Agent配置参数: {"Config":{"WebSearchAgentConfig":{"ParamsString":"{\"bot_id\":\"7585449675889608233\",\"stream\":true,\"location_info\":{\"city\":\"广州市\"}}"}}} +I (10849) VolcRtcProtocol: VolcRtcProtocol 开始启动... +I (10909) VolcRtcProtocol: 使用配置文件中的设备名称: d0_cf_13_03_bb_f0 +I (10999) VolcRtcProtocol: NVS凭证已加载：secret=1 appid=1 device_name=d0_cf_13_03_bb_f0, free_heap=7199200 +[INF|volc_rtc.c:597]volc_rtc_create: set param[0]: {"debug":{"log_to_console":1}} +[INF|volc_rtc.c:597]volc_rtc_create: set param[1]: {"audio":{"codec":{"internal":{"enable":1}}}} +[INF|volc_rtc.c:597]volc_rtc_create: set param[2]: {"rtc":{"access":{"concurrent_requests":1}}} +[INF|volc_rtc.c:597]volc_rtc_create: set param[3]: {"rtc":{"ice":{"concurrent_agents":1}}} +2026-05-15 11:22:04.328 [I] VolcEngineRTCLite.c:153 ****************** HELLO BOOKA (68f0bc7617b8520178bef12c)(1.57.207.001)(HASH-5c3aa20fe851886d21cede0115044e17c3ec8a67) ******************** +2026-05-15 11:22:04.329 [I] VolcEngineRTCLite.c:158 Platform esp32s3 +2026-05-15 11:22:04.329 [I] VolcEngineRTCLite.c:161 OsVersion FreeRTOS/unknown +2026-05-15 11:22:04.329 [I] VolcEngineRTCLite.c:164 CompilerInfo GCC/14.2.0 +2026-05-15 11:22:04.329 [I] VolcEngineRTCLite.c:100 BOOKA_DEVICE_LOW_RESOURCE : ON +2026-05-15 11:22:04.330 [I] VolcEngineRTCLite.c:104 BOOKA_ENABLE_EVENT_REPORT : ON +2026-05-15 11:22:04.330 [I] VolcEngineRTCLite.c:108 ENABLE_G722_CODEC : ON +2026-05-15 11:22:04.330 [I] GlobalParams.c:232 pGlobalParams->configParams.rtc.access.concurrent_requests from 2 to 1 +2026-05-15 11:22:04.331 [I] GlobalParams.c:233 pGlobalParams->configParams.rtc.ice.concurrent_agents from 2 to 1 +2026-05-15 11:22:04.331 [I] GlobalParams.c:239 pGlobalParams->configParams.audio.codec.internal.enable from 0 to 1 +2026-05-15 11:22:04.331 [I] GlobalParams.c:244 pGlobalParams->configParams.debug.log_to_console from 0 to 1 +2026-05-15 11:22:04.332 [I] GlobalParams.c:247 pGlobalParams->configParams.rtc.root_path to . +2026-05-15 11:22:04.333 [E] Cache.c:273 operation returned status code: 0x00000009 +2026-05-15 11:22:04.338 [E] SocketConnection-Lite.c:191 bind local ip failed +2026-05-15 11:22:04.341 [I] LiteResolver.c:213 start resolve rtc-log-service.volcvideo.com by sep thread +2026-05-15 11:22:04.344 [I] API byte_rtc_set_audio_codec engine 0x3c5b69c0 audio_codec_type 4 +2026-05-15 11:22:04.346 [I] API byte_rtc_set_video_codec engine 0x3c5b69c0 video_codec_type 0 +2026-05-15 11:22:04.346 [I] Common.c:82 rtcAudioCodec2SdkAudioCodec codec 5 +I (11019) VolcRtcProtocol: RTC实例已准备就绪；房间加入将在监听状态后执行 +I (11019) Application: 🌐 开始初始化WebSocket协议... +I (11019) Application: 🔧 创建WebsocketProtocol实例 +I (11019) Application: 🚀 启动WebSocket协议 +I (11019) Application: ✅ WebSocket协议初始化完成 +I (11009) VolcRtcProtocol: VolcRtcProtocol初始化任务已创建 +I (11019) EspHttp: Opening HTTP connection to https://xiaozhi-dev-web.goods.fun/xiaozhi/ota/ +I (11019) Application: 打印设置设备状态日志: idle +I (11019) AI_CHAT_UI: GIF表情切换: neutral +I (11059) Airhub1: ADC: 2335, 原始电压: 2.34V, 计算电池电压: 10.13V, 电量: 100%, 满电电压: 4.20V +I (11059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +2026-05-15 11:22:04.385 [I] LiteResolver.c:213 start resolve access.rtc.volcvideo.com by sep thread +2026-05-15 11:22:04.387 [I] LiteResolver.c:213 start resolve rtc-log-info.volcvideo.com by sep thread +I (11299) BG_GIF: GIF 已加载到 PSRAM: /spiflash/hiyori_m06.gif (441.8 KB) +I (11369) BG_GIF: ✓ 切换 GIF: /spiflash/hiyori_m06.gif +I (11369) Application: Entering idle state, playing standby sound +I (11379) esp-x509-crt-bundle: Certificate validated +I (11399) WeatherApi: [AutoDetectAndSetLocation] 调用全局函数自动检测位置 +I (11399) WeatherApi: [AutoDetectLocation] ===== 开始自动检测位置 ===== +I (11399) WeatherApi: [AutoDetectLocation] 从NVS命中位置: '广州市'，已更新默认城市 +I (11399) WeatherApi: [AutoDetectLocation] ===== 位置检测完成 ===== +I (11399) main_task: Returned from app_main() +W (11409) DIAG: queue=48 deq +W (11489) DIAG: queue=46 deq +W (11509) DIAG: write_slow 21951us samples=960 +W (11569) DIAG: queue=44 deq +W (11569) DIAG: write_slow 41852us samples=960 +W (11629) DIAG: write_slow 57113us samples=960 +W (11649) DIAG: queue=42 deq +W (11689) DIAG: write_slow 56770us samples=960 +W (11729) DIAG: queue=40 deq +W (11749) DIAG: write_slow 56879us samples=960 +W (11809) DIAG: queue=38 deq +W (11809) DIAG: write_slow 56974us samples=960 +W (11869) DIAG: write_slow 57425us samples=960 +W (11889) DIAG: queue=36 deq +W (11929) DIAG: write_slow 57187us samples=960 +I (11949) Ota: HTTP response status code: 0 +I (11949) Ota: Server role: , Device role: RTC_Test +W (11949) Ota: Role mismatch (Device:RTC_Test vs Server:), upgrade denied +W (11949) Ota: ✗ Upgrade conditions not met - Role: ✗, Version check: skipped +I (11949) Ota: Running partition: ota_0 +W (11969) DIAG: queue=16 deq +W (11989) DIAG: write_slow 57501us samples=960 +W (12049) DIAG: queue=14 deq +W (12049) DIAG: write_slow 57266us samples=960 +I (12059) Airhub1: ADC: 2335, 原始电压: 2.34V, 计算电池电压: 10.13V, 电量: 100%, 满电电压: 4.20V +I (12059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (12109) DIAG: write_slow 56432us samples=960 +W (12129) DIAG: queue=12 deq +W (12169) DIAG: write_slow 57158us samples=960 +W (12209) DIAG: queue=10 deq +W (12229) DIAG: write_slow 57763us samples=960 +W (12289) DIAG: queue=8 deq +W (12289) DIAG: write_slow 57273us samples=960 +W (12349) DIAG: write_slow 57325us samples=960 +W (12369) DIAG: queue=6 deq +W (12399) DIAG: rssi=-24 ch=1 +W (12399) DIAG: free_int=63491 psram=7006168 largest_int=23552 frag=62.9% +W (12409) DIAG: write_slow 56775us samples=960 +W (12449) DIAG: queue=4 deq +W (12469) DIAG: write_slow 57092us samples=960 +W (12529) DIAG: queue=2 deq +W (12529) DIAG: write_slow 57146us samples=960 +W (12589) DIAG: write_slow 57141us samples=960 +W (12609) DIAG: queue=0 deq +W (12649) DIAG: write_slow 57185us samples=960 +W (12709) DIAG: write_slow 57479us samples=960 +W (12769) DIAG: write_slow 57080us samples=960 +W (12829) DIAG: write_slow 57355us samples=960 +W (12889) DIAG: write_slow 57718us samples=960 +W (12949) DIAG: write_slow 57689us samples=960 +W (13009) DIAG: write_slow 57475us samples=960 +2026-05-15 19:22:06.287 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +I (13059) Airhub1: ADC: 2336, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (13059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (13069) DIAG: write_slow 57751us samples=960 +W (13129) DIAG: write_slow 57601us samples=960 +W (13189) DIAG: write_slow 57583us samples=960 +W (13399) DIAG: rssi=-25 ch=1 +W (13399) DIAG: free_int=69055 psram=7006176 largest_int=23552 frag=65.9% +I (14059) Airhub1: ADC: 2337, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (14059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (14399) DIAG: rssi=-25 ch=1 +W (14399) DIAG: free_int=68399 psram=7002812 largest_int=23552 frag=65.6% +2026-05-15 19:22:08.297 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +I (15059) Airhub1: ADC: 2336, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (15059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (15399) DIAG: rssi=-26 ch=1 +W (15399) DIAG: free_int=69055 psram=6985432 largest_int=23552 frag=65.9% +2026-05-15 19:22:08.804 [E] Cache.c:311 operation returned status code: 0x00000009 +2026-05-15 19:22:09.136 [I] IceAgent.c:2533 cur nominatedCandidatePair local 192.168.124.92:0 remote 183.60.131.217:443 state ICE_CANDIDATE_PAIR_STATE_SUCCEEDED +2026-05-15 19:22:09.313 [W] LiteHttp.c:490 ID 1812851329 E_TIMEOUT : Handshark timeout +I (16059) Airhub1: ADC: 2337, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (16059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (16399) DIAG: rssi=-33 ch=1 +W (16399) DIAG: free_int=68903 psram=7004988 largest_int=23552 frag=65.8% +2026-05-15 19:22:10.287 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +I (17059) Airhub1: ADC: 2338, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (17059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (17399) DIAG: rssi=-32 ch=1 +W (17399) DIAG: free_int=68903 psram=6979908 largest_int=23552 frag=65.8% +I (18059) Airhub1: ADC: 2337, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (18059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (18399) DIAG: rssi=-30 ch=1 +W (18399) DIAG: free_int=68903 psram=7004992 largest_int=23552 frag=65.8% +2026-05-15 19:22:12.287 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +I (19059) Airhub1: ADC: 2336, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (19059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (19399) DIAG: rssi=-29 ch=1 +W (19399) DIAG: free_int=68839 psram=6979900 largest_int=23552 frag=65.8% +I (20059) Airhub1: ADC: 2337, 原始电压: 2.34V, 计算电池电压: 10.14V, 电量: 100%, 满电电压: 4.20V +I (20059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +I (20059) Airhub1: 🔋 进入低功耗模式：CPU降频、Light Sleep启用、功放关闭 +I (20059) I2S_IF: Pending out channel for in channel running +I (20059) AudioCodec: Set output enable to false +I (20059) Airhub1: 🔊 功放已关闭 +W (20399) DIAG: rssi=-26 ch=1 +W (20399) DIAG: free_int=65635 psram=7004988 largest_int=23552 frag=64.1% +I (21059) Airhub1: ADC: 2338, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (21059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +2026-05-15 19:22:14.323 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (21399) DIAG: rssi=-25 ch=1 +W (21399) DIAG: free_int=68839 psram=6979896 largest_int=23552 frag=65.8% +I (21589) Airhub1: BOOT button clicked +I (21589) Airhub1: 当前设备状态: 3 +I (21589) Airhub1: 从待命状态切换到聆听状态 +I (21589) Airhub1: 强制重新初始化音频输出 +I (21639) I2S_IF: channel mode 0 bits:16/16 channel:2 mask:1 +I (21639) I2S_IF: STD Mode 1 bits:16/16 channel:2 sample_rate:16000 mask:1 +I (21649) Adev_Codec: Open codec device OK +I (21649) AudioCodec: Set output enable to true +I (21649) Airhub1: 播放提示音：卡卡在呢 +I (21649) Airhub1: 等待音频播放完成... +W (21689) DIAG: queue=16 deq +W (21759) DIAG: write_slow 23857us samples=960 +W (21769) DIAG: queue=14 deq +W (21819) DIAG: write_slow 43601us samples=960 +W (21849) DIAG: queue=12 deq +W (21879) DIAG: write_slow 57830us samples=960 +W (21929) DIAG: queue=10 deq +W (21939) DIAG: write_slow 57826us samples=960 +W (21999) DIAG: write_slow 57991us samples=960 +W (22009) DIAG: queue=8 deq +W (22059) DIAG: write_slow 57576us samples=960 +W (22089) DIAG: queue=6 deq +W (22119) DIAG: write_slow 57906us samples=960 +W (22169) DIAG: queue=4 deq +W (22179) DIAG: write_slow 57885us samples=960 +W (22239) DIAG: write_slow 58118us samples=960 +W (22249) DIAG: queue=2 deq +W (22299) DIAG: write_slow 57975us samples=960 +W (22329) DIAG: queue=0 deq +I (22349) Airhub1: 音频队列已清空，等待硬件输出完成... +W (22359) DIAG: write_slow 57953us samples=960 +W (22419) DIAG: write_slow 57898us samples=960 +W (22479) DIAG: write_slow 57877us samples=960 +W (22539) DIAG: write_slow 57788us samples=960 +W (22599) DIAG: write_slow 57918us samples=960 +W (22659) DIAG: write_slow 57427us samples=960 +I (22849) Airhub1: 音频播放完成 +I (22859) Application: 打印设置设备状态日志: connecting +I (22859) AI_CHAT_UI: GIF表情切换: neutral +I (22859) Application: 正在尝试打开音频通道 +I (22859) WifiBoard: 🔋 电源管理模式切换: 禁用低功耗模式（恢复正常模式） +I (22859) wifi:Set ps type: 0, coexist: 0 + +I (22869) VolcRtcProtocol: Join RTC: handle=0x3c5b6abc bot=botCL63FJgWe iot_ready=1 free_heap=7024812 +[INF|volc_rtc.c:695]volc_rtc_start: bot_id=botCL63FJgWe audio_codec=4 heap_free=7024812 +[INF|volc_device_manager.c:594]Get RTC config URL: https://iot-cn-shanghai.iot.volces.com/2021-12-14/GetRTCConfig?Action=GetRTCConfig&Version=2021-12-14 +[INF|volc_device_manager.c:595]RTC config request body: {"InstanceID":"68f0bc7611a5cf890711f2d0","product_key":"69080ba98219e1f34702d133","device_name":"d0_cf_13_03_bb_f0","random_num":22819,"timestamp":22819,"signature":"gKmLQkkWlqCkiBnSIthqqTaLEbnWLT8+8gbYlgGfCDI=","bot_id":"botCL63FJgWe","audio_codec":4,"task_id":"test","Config":{"WebSearchAgentConfig":{"ParamsString":"{\"bot_id\":\"7585449675889608233\",\"stream\":true,\"location_info\":{\"city\":\"广州市\"}}"}}} +I (22889) VOLC_HTTP: HTTP POST attempt 1/3 +I (22889) VOLC_HTTP: Performing HTTP request... +I (22949) Airhub1: ADC: 2338, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (22949) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (22949) DIAG: rssi=-25 ch=1 +W (22949) DIAG: free_int=64303 psram=6985904 largest_int=23552 frag=63.4% +I (23129) esp-x509-crt-bundle: Certificate validated +2026-05-15 19:22:16.348 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (23399) DIAG: rssi=-26 ch=1 +W (23399) DIAG: free_int=64303 psram=6980196 largest_int=23552 frag=63.4% +I (23969) VOLC_HTTP: HTTP_EVENT_ON_DATA: read 307 bytes, total: 307 +I (23969) VOLC_HTTP: HTTP_EVENT_ON_DATA: read 130 bytes, total: 437 +I (23979) VOLC_HTTP: HTTP response status: 200 +I (23979) VOLC_HTTP: Content-Length: 437, actually read: 437 +I (23979) VOLC_HTTP: Successfully read response: 437 bytes +I (23989) VOLC_HTTP: HTTP POST request completed, response_buffer=0x3c4f8964 +[INF|volc_device_manager.c:605]Get RTC config response received +[INF|volc_device_manager.c:606]RTC config response content: {"ResponseMetadata":{"Action":"GetRTCConfig","Version":"2021-12-14"},"Result":{"RoomID":"aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000","TaskID":"test","UserID":"d0_cf_13_03_bb_f0","Token":"00168f0bc7617b8520178bef12ceQC4HNQAaZEGaunLD2oyAGFpYm90cnRjX0c3MTFBX2QwX2NmXzEzXzAzX2JiX2YwXzIwMjYwNTE1MTEyMjE2MDAwEQBkMF9jZl8xM18wM19iYl9mMAYAAADpyw9qAQDpyw9qAgDpyw9qAwDpyw9qBADpyw9qBQDpyw9qIACMzlLguMlozuBvM5oHtL2Me0YpW5Ze+2ozxCRSlOzaGg=="}} +[INF|volc_device_manager.c:702]Retrieved RTC config: channel_name=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000, uid=d0_cf_13_03_bb_f0, task_id=test +[INF|volc_rtc.c:701]volc_get_rtc_config success heap_free=7049116 +[INF|volc_rtc.c:119]Joining channel: aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000, uid: d0_cf_13_03_bb_f0, token: 00168f0bc7617b8520178bef12ceQC4HNQAaZEGaunLD2oyAGFpYm90cnRjX0c3MTFBX2QwX2NmXzEzXzAzX2JiX2YwXzIwMjYwNTE1MTEyMjE2MDAwEQBkMF9jZl8xM18wM19iYl9mMAYAAADpyw9qAQDpyw9qAgDpyw9qAwDpyw9qBADpyw9qBQDpyw9qIACMzlLguMlozuBvM5oHtL2Me0YpW5Ze+2ozxCRSlOzaGg==, vpub: 0, vsub: 0, apub: 1, asub: 1 +[INF|volc_rtc.c:123]Memory before byte_rtc_join_room - Heap: 7049116 bytes, SPIRAM: 7004648 bytes +2026-05-15 19:22:17.260 [I] API byte_rtc_join_room engine 0x3c5b69c0 channel_name aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 user_name d0_cf_13_03_bb_f0 token 00168f0bc7617b8520178bef12ceQC4HNQAaZEGaunLD2oyAGFpYm90cnRjX0c3MTFBX2QwX2NmXzEzXzAzX2JiX2YwXzIwMjYwNTE1MTEyMjE2MDAwEQBkMF9jZl8xM18wM19iYl9mMAYAAADpyw9qAQDpyw9qAgDpyw9qAwDpyw9qBADpyw9qBQDpyw9qIACMzlLguMlozuBvM5oHtL2Me0YpW5Ze+2ozxCRSlOzaGg== audio sub 1 pub 1 video sub 0 pub 0 +[INF|volc_rtc.c:132]Memory after byte_rtc_join_room - Heap: 7042376 bytes (change: -6740), SPIRAM: 7004068 bytes (change: -580) +2026-05-15 19:22:17.270 [I] RoomImplX.c:632 [room_event] key: join_room, type: begin, result: true +W (24399) DIAG: rssi=-27 ch=1 +W (24399) DIAG: free_int=67987 psram=6968704 largest_int=23552 frag=65.4% +2026-05-15 19:22:17.768 [I] Rtp.c:139 video_retrans_buffer_duration_ms = 3000 +2026-05-15 19:22:17.769 [I] Rtp.c:141 enable_video_transport_cc = 1 +2026-05-15 19:22:17.771 [I] Rtp.c:190 audio_retrans_buffer_duration_ms = 1000 +2026-05-15 19:22:17.771 [I] Rtp.c:193 enable_audio_transport_cc = 1 +2026-05-15 19:22:17.778 [I] RoomImplX.c:816 [room_event] key: join_room, type: end, result: true +[INF|volc_rtc.c:254]join channel success aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 elapsed 496 ms + +I (24509) VolcRtcProtocol: RTC连接成功 +I (24519) VolcRtcProtocol: Wait connect bits=0x1 free_heap=6980208 +2026-05-15 19:22:17.819 [W] IceMessageProcessor.c:360 TODO: handle signal engineControlMessage content {"roomId":"aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000","type":"changeCodec","body":{"media":"audio","codec":"PCMA"},"appId":"68f0bc7617b8520178bef12c","messageId":"5e3fa21c01bd4e87bead96e795cdc7a7","sessionId":"lZmhEy9H381d3w3oGYs8EXuikdEtMbuz"} +[INF|volc_rtc.c:268]remote user joined aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000:bot_20260515112216000 elapsed 0 ms + +I (24569) VolcRtcProtocol: RTC远程用户加入 +I (24569) Application: 🟢 音频通道已打开 +I (24569) Application: 当前设备状态: connecting +I (24569) Airhub1: 🔋 退出低功耗模式：CPU恢复正常、Light Sleep禁用、功放打开 +I (24569) Airhub1: 🔊 功放已打开 +I (24569) Airhub1: 🔋 PowerSaveTimer已唤醒，从低功耗模式恢复到正常模式 +I (24569) Application: 🔄 禁用电源低功耗管理模式 +I (24569) WifiBoard: 🔋 电源管理模式切换: 禁用低功耗模式（恢复正常模式） +I (24569) wifi:Set ps type: 0, coexist: 0 + +I (24569) Application: Dialog watchdog started, initial device state: 7 +I (24569) Application: 打印设置设备状态日志: dialog +I (24569) AI_CHAT_UI: GIF表情切换: happy +I (24569) VolcRtcProtocol: 延迟发送StartListening，等待会话就绪 +I (24569) Application: 进入对话框状态：启用全双工 +I (24599) Application: 🔊 启用音频编解码器输出 +I (24599) Application: 🔄 音频通道打开，准备播放欢迎语音 +I (24599) Application: 当前设备状态: dialog +I (24599) Application: 🟢 音频通道初始化完成 +2026-05-15 19:22:17.867 [W] EngineImplX.c:598 callback pEngineImplX->eventHandler.on_user_joined used too many times 32 +I (24959) Airhub1: 🔗 检测到RTC火山引擎已连接 +2026-05-15 19:22:18.313 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +2026-05-15 19:22:18.573 [I] rx_net_audio_jitterbuffer.c:183 first_frame_build_target_delay:1, direct_mode:0, direct_mode_max_wait_time:200 +2026-05-15 19:22:18.648 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 0:0:0,in: jitter nor=0 reor=0, wj=0, out: pkt=0 t_diff=0 seq_diff=0 buffer_ms=0 target_ms=20 expand_npkt=1 expand_loss=0 start_seq 0 end_seq 0 +W (25399) DIAG: rssi=-26 ch=1 +W (25399) DIAG: free_int=60423 psram=6838736 largest_int=23552 frag=61.0% +2026-05-15 19:22:18.809 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 1 packets . Send time history too small? +2026-05-15 19:22:18.900 [I] StreamSubscriber.c:336 [room_event] key: first_frame, media: audio, type: begin_recv +2026-05-15 19:22:18.902 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 0 +2026-05-15 19:22:18.902 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +2026-05-15 19:22:18.907 [I] rx_net_audio_jitterbuffer.c:1785 fir pkt seq=46 +2026-05-15 19:22:18.909 [I] rx_net_audio_jitterbuffer.c:1792 first recv dia cnt=0, fir pkt=46 +2026-05-15 19:22:19.002 [I] rx_net_audio_jitterbuffer.c:1443 build_target_delay over need_extract_packet s=100 +2026-05-15 19:22:19.034 [I] MediaService.c:405 [room_event] key: first_frame, media: audio, type: recv_end +2026-05-15 19:22:19.035 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 0 +I (25769) VolcRtcProtocol: 接收下行音频首包: 类型=PCM 大小=320 +W (25769) DIAG: queue=1 enq_ws +I (25769) Application: 收到下行音频首包入队: 字节=320 +W (25819) DIAG: queue=1 deq +W (25879) DIAG: queue=1 deq +W (25939) DIAG: queue=0 deq +I (25959) Airhub1: 📤 设备状态上报已启用，每30秒上报一次 +W (26049) DIAG: queue=1 enq_ws +2026-05-15 19:22:19.332 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 4630000 +W (26109) DIAG: queue=1 enq_ws +W (26189) DIAG: queue=1 enq_ws +W (26239) DIAG: queue=2 deq +W (26329) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=326 binary=1 free_heap=6800044 +I (26389) Application: .. AI: 你好， +W (26389) DIAG: queue=0 deq +W (26399) DIAG: rssi=-27 ch=1 +W (26399) DIAG: free_int=60111 psram=6764168 largest_int=23552 frag=60.8% +2026-05-15 19:22:19.698 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 5000000 +W (26469) DIAG: queue=1 enq_ws +2026-05-15 19:22:19.751 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 19 +I (26569) Application: dialog对话空闲倒计时剩余: 40 秒 +I (26589) VolcRtcProtocol: 上行音频统计: PCM帧=52 字节=16640, G711A帧=0 字节=0, 速率=66284 bps +I (26589) VolcRtcProtocol: 下行音频统计: PCM字节=7360, OPUS字节=0 +W (26599) DIAG: queue=1 enq_ws +W (26689) DIAG: queue=1 enq_ws +W (26749) DIAG: queue=0 deq +W (26899) DIAG: queue=1 enq_ws +W (26969) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=332 binary=1 free_heap=6818044 +I (26989) Application: .. AI: 你好，我 +2026-05-15 19:22:20.349 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (27229) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=338 binary=1 free_heap=6819472 +I (27389) Application: .. AI: 你好，我是 +W (27399) DIAG: rssi=-26 ch=1 +W (27399) DIAG: free_int=59663 psram=6781876 largest_int=23552 frag=60.5% +2026-05-15 19:22:20.737 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 41:0:54,in: jitter nor=115 reor=878, wj=184, out: pkt=32 t_diff=259 seq_diff=6 buffer_ms=180 target_ms=100 expand_npkt=49 expand_loss=23 start_seq 46 end_seq 108 +W (27589) DIAG: queue=1 enq_ws +W (27869) DIAG: queue=1 enq_ws +2026-05-15 19:22:21.163 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 145000 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=344 binary=1 free_heap=6828584 +I (27909) Application: .. AI: 你好，我是啦 +W (27919) DIAG: queue=1 enq_ws +2026-05-15 19:22:21.192 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 5 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=349 binary=1 free_heap=6841168 +I (27979) Application: AI回复结束，表情恢复 neutral +I (27979) Application: 📝 AI: 你好，我是啦啦~ +I (27979) AI_CHAT_UI: GIF表情切换: neutral +W (28029) DIAG: queue=1 enq_ws +W (28089) DIAG: queue=0 deq +2026-05-15 19:22:21.534 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 196750 +W (28399) DIAG: rssi=-28 ch=1 +W (28399) DIAG: free_int=59759 psram=6811948 largest_int=23552 frag=60.6% +I (28609) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63282 bps +I (28609) VolcRtcProtocol: 下行音频统计: PCM字节=6080, OPUS字节=0 +2026-05-15 19:22:21.957 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 256262 +2026-05-15 19:22:22.316 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +2026-05-15 19:22:22.390 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 324701 +W (29399) DIAG: rssi=-30 ch=1 +W (29399) DIAG: free_int=59759 psram=6803752 largest_int=23552 frag=60.6% +2026-05-15 19:22:22.734 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 403406 +2026-05-15 19:22:22.757 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 1:0:10,in: jitter nor=0 reor=1394, wj=184, out: pkt=10 t_diff=362 seq_diff=3 buffer_ms=0 target_ms=100 expand_npkt=35 expand_loss=53 start_seq 105 end_seq 105 +2026-05-15 19:22:23.243 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 493916 +2026-05-15 19:22:23.636 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 598003 +W (30399) DIAG: rssi=-27 ch=1 +W (30399) DIAG: free_int=60415 psram=6805348 largest_int=23552 frag=61.0% +I (30569) Application: dialog对话空闲倒计时剩余: 38 秒 +I (30619) VolcRtcProtocol: 上行音频统计: PCM帧=51 字节=16320, G711A帧=0 字节=0, 速率=64936 bps +I (30619) VolcRtcProtocol: 下行音频统计: PCM字节=0, OPUS字节=0 +2026-05-15 19:22:23.970 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 717703 +2026-05-15 19:22:24.351 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (31399) DIAG: rssi=-31 ch=1 +W (31399) DIAG: free_int=59759 psram=6804320 largest_int=23552 frag=60.6% +2026-05-15 19:22:24.683 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 145000 +2026-05-15 19:22:24.807 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 0:0:0,in: jitter nor=0 reor=0, wj=184, out: pkt=0 t_diff=0 seq_diff=0 buffer_ms=0 target_ms=100 expand_npkt=135 expand_loss=0 start_seq 0 end_seq 0 +2026-05-15 19:22:25.266 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 196750 +I (32059) Airhub1: ADC: 2338, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (32059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=316 binary=1 free_heap=6840340 +I (32109) Application: .. USER: 今天 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=316 binary=1 free_heap=6834108 +I (32169) Application: .. USER: 今天 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=316 binary=1 free_heap=6832744 +I (32219) Application: .. USER: 今天 +2026-05-15 19:22:25.545 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 0 +2026-05-15 19:22:25.546 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +2026-05-15 19:22:25.547 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 0 +2026-05-15 19:22:25.547 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +2026-05-15 19:22:25.636 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 256262 +W (32399) DIAG: rssi=-31 ch=1 +W (32399) DIAG: free_int=60423 psram=6809280 largest_int=23552 frag=61.0% +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=316 binary=1 free_heap=6843824 +I (32399) Application: .. USER: 今天 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=346 binary=1 free_heap=6844204 +I (32449) Application: .. USER: 今天天气怎么样 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=346 binary=1 free_heap=6847684 +I (32449) Application: .. USER: 今天天气怎么样 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=346 binary=1 free_heap=6846204 +I (32509) Application: .. USER: 今天天气怎么样 +I (32569) Application: dialog对话空闲倒计时剩余: 40 秒 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=346 binary=1 free_heap=6845688 +I (32609) Application: .. USER: 今天天气怎么样 +I (32629) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63652 bps +I (32629) VolcRtcProtocol: 下行音频统计: PCM字节=0, OPUS字节=0 +2026-05-15 19:22:25.936 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 324701 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=346 binary=1 free_heap=6841148 +I (32719) Application: .. USER: 今天天气怎么样 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=344 binary=1 free_heap=6847192 +I (32749) Application: 📝 USER: 今天天气怎么样 +2026-05-15 19:22:26.285 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +2026-05-15 19:22:26.287 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 403406 +2026-05-15 19:22:26.606 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 493916 +W (33399) DIAG: rssi=-28 ch=1 +W (33399) DIAG: free_int=60411 psram=6808864 largest_int=23552 frag=61.0% +2026-05-15 19:22:26.820 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 0:0:0,in: jitter nor=0 reor=0, wj=184, out: pkt=0 t_diff=0 seq_diff=0 buffer_ms=0 target_ms=100 expand_npkt=88 expand_loss=0 start_seq 0 end_seq 0 +2026-05-15 19:22:26.912 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 598003 +2026-05-15 19:22:27.448 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 717703 +W (34399) DIAG: rssi=-27 ch=1 +W (34399) DIAG: free_int=59755 psram=6800044 largest_int=23552 frag=60.6% +2026-05-15 19:22:27.827 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 855358 +I (34569) Application: dialog对话空闲倒计时剩余: 39 秒 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=198 binary=1 free_heap=6844824 +I (34579) VolcRtcProtocol: 接收下行消息(info): { + "event_type" : "function_calling", + "function" : "webSearch", + "response_id" : "021778815346106d3e54ebf5d2343d2942f37ab047ca488f4aa4f", + "tool_call_id" : "call_96dzvlhaeg4bw4z53u07uk5p" +} +I (34639) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63729 bps +I (34639) VolcRtcProtocol: 下行音频统计: PCM字节=0, OPUS字节=0 +2026-05-15 19:22:28.137 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 1013661 +2026-05-15 19:22:28.335 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +2026-05-15 19:22:28.537 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 1195710 +W (35399) DIAG: rssi=-27 ch=1 +W (35399) DIAG: free_int=60411 psram=6809304 largest_int=23552 frag=61.0% +2026-05-15 19:22:28.835 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 0:0:0,in: jitter nor=0 reor=0, wj=184, out: pkt=0 t_diff=0 seq_diff=0 buffer_ms=0 target_ms=100 expand_npkt=113 expand_loss=0 start_seq 0 end_seq 0 +2026-05-15 19:22:28.838 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 1405066 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=2713 binary=1 free_heap=6836524 +I (35909) VolcRtcProtocol: 接收下行消息(info): { + "event_type" : "references", + "references" : + [ + { + "cover_image" : null, + "id" : "119095579382dbb7bc7ed406b588582f8a9b35c7", + "logo_url" : "", + "publish_time" : 1778813408, + "site_name" : "\u706b\u5c71\u5982\u610f", + "source_type" : "weather", + "summary" : "", + "title" : "\u5e7f\u4e1c\u7701\u5e7f\u5dde\u5e02\u4eca\u5929\u5929\u6c14|\u672c\u5468\u5929\u6c14|\u4e0b\u5468\u5929\u6c14|\u672a\u6765\u5929\u6c14", + "url" : "https://html5.moji.com/tpd/days40_web/index.html#/home?cityid=886&platform=toutiao" + }, + { + "cover_image" : null, + "id" : "4b5c2fa0a76d831a-e1ba9c248e0311dd", + "logo_url" : "https://p11-volcsearch-sign.byteimg.com/isp-i18n-media/image/50b51b19e25c25d7f6f81d6e35bf26bc~tplv-obj.jpeg?lk3s=7acb411c&scene=volc_search&x-expires=1841886315&x-signature=8vjt%2F0fZdA%2F%2FQrqi4wbY%2BtV9jV0%3D", + "publish_time" : 1778804700, + "site_name" : "\u4e2d\u592e\u6c14\u8c61\u53f0", + "source_type" : "search_engine", + "summary" : "", + "title" : "\u5e7f\u5dde\u5929\u6c14", + "url" : "http://m.nmc.cn/publish/forecast/AGD/guangzhou.html" + }, + { + "cover_image" : null, + "id" : "3f811ef4dd97e4b4-a0406aa9feb1bed6", + "logo_url" : "https://p26-volcsearch-sign.byteimg.com/isp-i18n-media/image/43bbdc34ff90f105bb4d08685c5aed51~tplv-obj.jpeg?lk3s=7acb411c&scene=volc_search&x-expires=1841886315&x-signature=w07D%2BYvlExMlT10KVlbcstEcz2Q%3D", + "publish_time" : 1778804700, + "site_name" : "\u4e2d\u592e\u6c14\u8c61\u53f0", + "source_type" : "search_engine", + "summary" : "", + "title" : "\u5e7f\u5dde-\u5929\u6c14\u9884\u62a5", + "url" : "http://www.nmc.cn/publish/forecast/AGD/guangzhou.html?fid=44&id=951" + }, + { + "cover_image" : null, + "id" : "a9d61c843fc14f39-dfed489c284db686", + "logo_url" : "", + "publish_time" : 1131120000, + "site_name" : "\u5e7f\u4e1c\u6c14\u8c61\u7f51", + "source_type" : "search_engine", + "summary" : "", + "title" : "\u5e7f\u4e1c\u6c14\u8c61", + "url" : "https://www.gd121.cn/index_detail.shtml" + }, + { + "cover_image" : null, + "id" : "bb2ca316d267ecf5-cd6620275baa4c2b", + "logo_url" : "https://p3-volcsearch-sign.byteimg.com/isp-i18n-media/image/61324d270153723291767f4d0d118ddd~tplv-obj.jpeg?lk3s=7acb411c&scene=volc_search&x-expires=1841886315&x-signature=Z2z06zIYyhwQ70nfEh4zm7k2olA%3D", + "publish_time" : 1778729400, + "site_name" : "\u4e2d\u56fd\u5929\u6c14\u7f51\u5e7f\u4e1c\u7ad9", + "source_type" : "search_engine", + "summary" : "", + "title" : "\u5e7f\u5dde\u5929\u6c14\u9884\u62a5,\u5e7f\u5dde7\u5929\u5929\u6c14\u9884\u62a5,\u5e7f\u5dde15\u5929\u5929\u6c14\u9884\u62a5,\u5e7f\u5dde\u5929\u6c14\u67e5\u8be2", + "url" : "http://gd.weather.com.cn/weather/101280101.shtml" + } + ] +} +2026-05-15 19:22:29.183 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 10 +2026-05-15 19:22:29.330 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 1645825 +2026-05-15 19:22:29.387 [I] rx_net_audio_jitterbuffer.c:1797 the dia cnt update, last=0, seq=108, cur=1, seq=109 +2026-05-15 19:22:29.388 [I] rx_net_audio_jitterbuffer.c:1617 [a_jb]reset jb bsize=0, needr=1, rst_cur_round=0, rst_cnt=0 +2026-05-15 19:22:29.446 [I] rx_net_audio_jitterbuffer.c:1443 build_target_delay over need_extract_packet s=100 +W (36189) DIAG: queue=1 enq_ws +W (36399) DIAG: rssi=-28 ch=1 +W (36399) DIAG: free_int=59755 psram=6778412 largest_int=23552 frag=60.6% +W (36439) DIAG: queue=1 enq_ws +2026-05-15 19:22:29.713 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 1922698 +W (36499) DIAG: queue=1 deq +I (36569) Application: dialog对话空闲倒计时剩余: 37 秒 +W (36609) DIAG: queue=1 enq_ws +I (36649) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63643 bps +I (36649) VolcRtcProtocol: 下行音频统计: PCM字节=2560, OPUS字节=0 +W (36679) DIAG: queue=1 enq_ws +2026-05-15 19:22:29.959 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 12 +W (36749) DIAG: queue=1 enq_ws +W (36809) DIAG: queue=1 enq_ws +W (36869) DIAG: queue=1 enq_ws +W (36929) DIAG: queue=1 enq_ws +2026-05-15 19:22:30.204 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 833, e2e_avg: 344, e2e_max: 474 +W (36979) DIAG: queue=4 deq +2026-05-15 19:22:30.281 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (37039) DIAG: queue=5 deq +2026-05-15 19:22:30.341 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 2241102 +W (37099) DIAG: queue=5 deq +W (37159) DIAG: queue=6 enq_ws +2026-05-15 19:22:30.466 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 0 +2026-05-15 19:22:30.467 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +2026-05-15 19:22:30.467 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 0 +2026-05-15 19:22:30.468 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +W (37209) DIAG: queue=4 deq +W (37269) DIAG: queue=5 deq +W (37329) DIAG: queue=5 deq +W (37389) DIAG: queue=5 deq +2026-05-15 19:22:30.658 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 2607267 +W (37399) DIAG: rssi=-27 ch=1 +W (37399) DIAG: free_int=58671 psram=6741788 largest_int=23552 frag=59.9% +W (37449) DIAG: queue=4 deq +W (37509) DIAG: queue=2 deq +W (37569) DIAG: queue=3 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=371 binary=1 free_heap=6798872 +I (37589) Application: 字幕情绪: thinking → thinking +I (37589) Application: .. AI: 我需要查询一下 +I (37589) AI_CHAT_UI: GIF表情切换: thinking +W (37619) DIAG: queue=3 enq_ws +W (37679) DIAG: queue=5 enq_ws +W (37739) DIAG: queue=6 enq_ws +2026-05-15 19:22:31.016 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 3028357 +W (37789) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=377 binary=1 free_heap=6862092 +I (37799) Application: .. AI: 我需要查询一下今 +2026-05-15 19:22:31.065 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 4 +W (37849) DIAG: queue=7 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=383 binary=1 free_heap=6850388 +W (37909) DIAG: queue=5 deq +I (37909) Application: .. AI: 我需要查询一下今天 +2026-05-15 19:22:31.180 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 5 +W (37969) DIAG: queue=5 deq +I (37979) BG_GIF: GIF 已加载到 PSRAM: /spiflash/hiyori_m07.gif (398.5 KB) +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=389 binary=1 free_heap=6825956 +I (38009) Application: .. AI: 我需要查询一下今天的 +W (38029) DIAG: queue=5 deq +I (38049) BG_GIF: ✓ 切换 GIF: /spiflash/hiyori_m07.gif +W (38089) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=395 binary=1 free_heap=6856760 +I (38109) Application: .. AI: 我需要查询一下今天的天 +2026-05-15 19:22:31.404 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 97:2:129,in: jitter nor=9152 reor=1208, wj=115, out: pkt=81 t_diff=232 seq_diff=11 buffer_ms=340 target_ms=100 expand_npkt=0 expand_loss=29 start_seq 109 end_seq 234 +W (38149) DIAG: queue=7 enq_ws +2026-05-15 19:22:31.441 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 3512610 +W (38209) DIAG: queue=7 enq_ws +2026-05-15 19:22:31.519 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 491, e2e_avg: 318, e2e_max: 511 +W (38269) DIAG: queue=5 deq +W (38329) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=402 binary=1 free_heap=6852480 +I (38359) Application: .. AI: 我需要查询一下今天的天气 +W (38389) DIAG: queue=2 deq +W (38399) DIAG: rssi=-27 ch=1 +W (38399) DIAG: free_int=58931 psram=6814904 largest_int=23552 frag=60.0% +W (38449) DIAG: queue=5 deq +2026-05-15 19:22:31.743 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 4069501 +W (38509) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=408 binary=1 free_heap=6839084 +I (38529) Application: .. AI: 我需要查询一下今天的天气情 +I (38569) Application: dialog对话空闲倒计时剩余: 40 秒 +W (38569) DIAG: queue=3 deq +W (38629) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=414 binary=1 free_heap=6845812 +I (38649) Application: .. AI: 我需要查询一下今天的天气情况 +I (38679) VolcRtcProtocol: 上行音频统计: PCM帧=43 字节=13760, G711A帧=0 字节=0, 速率=54429 bps +I (38679) VolcRtcProtocol: 下行音频统计: PCM字节=31680, OPUS字节=0 +W (38689) DIAG: queue=4 deq +W (38749) DIAG: queue=1 deq +W (38809) DIAG: queue=0 deq +W (38889) DIAG: queue=1 enq_ws +W (38949) DIAG: queue=0 deq +W (39019) DIAG: queue=1 enq_ws +2026-05-15 19:22:32.285 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (39079) DIAG: queue=0 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=420 binary=1 free_heap=6813024 +I (39129) Application: .. AI: 我需要查询一下今天的天气情况呢 +W (39149) DIAG: queue=1 enq_ws +W (39209) DIAG: queue=1 enq_ws +2026-05-15 19:22:32.483 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 4709926 +W (39259) DIAG: queue=3 deq +W (39319) DIAG: queue=1 deq +W (39399) DIAG: rssi=-28 ch=1 +W (39399) DIAG: free_int=59511 psram=6825520 largest_int=23552 frag=60.4% +W (39419) DIAG: queue=1 enq_ws +W (39469) DIAG: queue=1 enq_ws +2026-05-15 19:22:32.847 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 5000000 +W (39609) DIAG: queue=1 enq_ws +W (39669) DIAG: queue=1 enq_ws +W (39729) DIAG: queue=1 deq +W (39799) DIAG: queue=1 enq_ws +W (39869) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=421 binary=1 free_heap=6843988 +I (39879) Application: .. AI: 我需要查询一下今天的天气情况呢~ +W (39969) DIAG: queue=1 enq_ws +W (40029) DIAG: queue=0 deq +W (40089) DIAG: queue=1 enq_ws +W (40149) DIAG: queue=0 deq +2026-05-15 19:22:33.434 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 62:1:72,in: jitter nor=268 reor=1060, wj=212, out: pkt=62 t_diff=139 seq_diff=7 buffer_ms=340 target_ms=100 expand_npkt=0 expand_loss=26 start_seq 235 end_seq 333 +W (40199) DIAG: queue=5 enq_ws +W (40249) DIAG: queue=9 deq +W (40309) DIAG: queue=10 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=427 binary=1 free_heap=6845288 +I (40329) Application: .. AI: 我需要查询一下今天的天气情况呢~正 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=433 binary=1 free_heap=6848888 +I (40329) Application: .. AI: 我需要查询一下今天的天气情况呢~正在 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=439 binary=1 free_heap=6845764 +I (40349) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=445 binary=1 free_heap=6838144 +I (40369) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网 +W (40369) DIAG: queue=10 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=451 binary=1 free_heap=6816640 +I (40379) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网查 +W (40399) DIAG: rssi=-28 ch=1 +W (40399) DIAG: free_int=57335 psram=6783964 largest_int=23552 frag=58.9% +W (40419) DIAG: queue=8 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=463 binary=1 free_heap=6849956 +I (40419) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网查询， +W (40489) DIAG: queue=8 enq_ws +2026-05-15 19:22:33.757 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 491, e2e_avg: 361, e2e_max: 687 +W (40549) DIAG: queue=4 deq +W (40609) DIAG: queue=3 deq +W (40669) DIAG: queue=1 deq +I (40689) VolcRtcProtocol: 上行音频统计: PCM帧=58 字节=18560, G711A帧=0 字节=0, 速率=73799 bps +I (40689) VolcRtcProtocol: 下行音频统计: PCM字节=19840, OPUS字节=0 +W (40729) DIAG: queue=0 deq +W (40789) DIAG: queue=1 deq +W (40849) DIAG: queue=1 enq_ws +W (40899) DIAG: queue=1 enq_ws +W (40949) DIAG: queue=1 enq_ws +W (41029) DIAG: queue=0 deq +2026-05-15 19:22:34.304 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (41089) DIAG: queue=0 deq +W (41209) DIAG: queue=1 enq_ws +W (41269) DIAG: queue=1 deq +W (41349) DIAG: queue=1 enq_ws +W (41399) DIAG: rssi=-29 ch=1 +W (41399) DIAG: free_int=59507 psram=6823180 largest_int=23552 frag=60.4% +W (41409) DIAG: queue=1 enq_ws +W (41469) DIAG: queue=3 deq +W (41529) DIAG: queue=1 deq +W (41579) DIAG: queue=1 enq_ws +W (41689) DIAG: queue=1 enq_ws +W (41739) DIAG: queue=1 enq_ws +W (41829) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=469 binary=1 free_heap=6857876 +I (41839) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网查询，请 +W (41969) DIAG: queue=1 enq_ws +W (42029) DIAG: queue=1 enq_ws +I (42059) Airhub1: ADC: 2339, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (42059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +W (42079) DIAG: queue=2 deq +W (42139) DIAG: queue=0 deq +2026-05-15 19:22:35.439 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 63:1:89,in: jitter nor=165 reor=1732, wj=168, out: pkt=67 t_diff=156 seq_diff=7 buffer_ms=260 target_ms=100 expand_npkt=0 expand_loss=36 start_seq 324 end_seq 432 +W (42199) DIAG: queue=0 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=475 binary=1 free_heap=6855024 +I (42219) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网查询，请稍 +W (42249) DIAG: queue=2 enq_ws +W (42309) DIAG: queue=6 deq +W (42369) DIAG: queue=3 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=481 binary=1 free_heap=6853688 +I (42389) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网查询，请稍等 +W (42399) DIAG: rssi=-30 ch=1 +W (42399) DIAG: free_int=58575 psram=6819772 largest_int=23552 frag=59.8% +W (42429) DIAG: queue=0 deq +W (42489) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=487 binary=1 free_heap=6857952 +I (42509) Application: .. AI: 我需要查询一下今天的天气情况呢~正在上网查询，请稍等一 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=504 binary=1 free_heap=6855588 +I (42519) Application: AI回复结束，表情恢复 neutral +I (42519) Application: 📝 AI: 我需要查询一下今天的天气情况呢~正在上网查询，请稍等一下哦。 +I (42519) AI_CHAT_UI: GIF表情切换: neutral +W (42539) DIAG: queue=3 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=311 binary=1 free_heap=7257120 +I (42569) Application: .. AI: # +2026-05-15 19:22:35.843 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 7 +W (42589) DIAG: queue=3 enq_ws +W (42649) DIAG: queue=3 enq_ws +2026-05-15 19:22:35.944 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 868, e2e_avg: 375, e2e_max: 595 +W (42709) DIAG: queue=3 enq_ws +W (42769) DIAG: queue=1 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=312 binary=1 free_heap=6799304 +I (42809) Application: .. AI: ## +I (42829) BG_GIF: GIF 已加载到 PSRAM: /spiflash/hiyori_m06.gif (441.8 KB) +W (42829) DIAG: queue=0 deq +W (42889) DIAG: queue=0 deq +I (42899) BG_GIF: ✓ 切换 GIF: /spiflash/hiyori_m06.gif +W (42949) DIAG: queue=2 enq_ws +W (43009) DIAG: queue=0 deq +I (43019) VolcRtcProtocol: 上行音频统计: PCM帧=46 字节=14720, G711A帧=0 字节=0, 速率=50411 bps +I (43019) VolcRtcProtocol: 下行音频统计: PCM字节=25920, OPUS字节=0 +2026-05-15 19:22:36.299 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=313 binary=1 free_heap=6770704 +I (43049) Application: .. AI: ### +W (43069) DIAG: queue=1 enq_ws +W (43129) DIAG: queue=1 deq +W (43349) DIAG: queue=1 enq_ws +W (43399) DIAG: rssi=-29 ch=1 +W (43399) DIAG: free_int=60203 psram=6774068 largest_int=23552 frag=60.9% +W (43519) DIAG: queue=1 enq_ws +W (43599) DIAG: queue=1 enq_ws +W (43689) DIAG: queue=1 enq_ws +W (43739) DIAG: queue=3 enq_ws +W (43809) DIAG: queue=0 deq +W (43869) DIAG: queue=1 enq_ws +W (43929) DIAG: queue=0 deq +W (43979) DIAG: queue=2 enq_ws +W (44069) DIAG: queue=1 enq_ws +2026-05-15 19:22:37.442 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 65:0:98,in: jitter nor=497 reor=1662, wj=500, out: pkt=65 t_diff=265 seq_diff=5 buffer_ms=240 target_ms=100 expand_npkt=0 expand_loss=15 start_seq 414 end_seq 524 +W (44289) DIAG: queue=1 enq_ws +W (44389) DIAG: queue=1 enq_ws +W (44399) DIAG: rssi=-29 ch=1 +W (44399) DIAG: free_int=60203 psram=6715944 largest_int=23552 frag=60.9% +W (44449) DIAG: queue=0 deq +W (44509) DIAG: queue=1 deq +I (44569) Application: dialog对话空闲倒计时剩余: 39 秒 +W (44569) DIAG: queue=1 enq_ws +W (44629) DIAG: queue=1 deq +W (44689) DIAG: queue=1 enq_ws +W (44749) DIAG: queue=0 deq +W (44809) DIAG: queue=1 deq +W (44859) DIAG: queue=1 enq_ws +W (44909) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=314 binary=1 free_heap=6792920 +I (44949) Application: .. AI: ### +2026-05-15 19:22:38.227 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 868, e2e_avg: 434, e2e_max: 1019 +W (44979) DIAG: queue=12 enq_ws +2026-05-15 19:22:38.278 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 5 +2026-05-15 19:22:38.287 [W] EventReportControl.c:195 PEventReportControl pAvailableLogdataQueue is empty, need drop this message, isStat 1 +W (45039) DIAG: queue=17 enq_ws +I (45049) VolcRtcProtocol: 上行音频统计: PCM帧=63 字节=20160, G711A帧=0 字节=0, 速率=79508 bps +I (45049) VolcRtcProtocol: 下行音频统计: PCM字节=21760, OPUS字节=0 +W (45089) DIAG: queue=19 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=320 binary=1 free_heap=6792916 +I (45119) Application: .. AI: ### 今 +W (45139) DIAG: queue=17 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=326 binary=1 free_heap=6786396 +I (45179) Application: .. AI: ### 今日 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=376 binary=1 free_heap=6789128 +I (45189) Application: .. AI: ### 今日（2026年5月15日 广州） +W (45199) DIAG: queue=19 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=382 binary=1 free_heap=6795320 +I (45209) Application: .. AI: ### 今日（2026年5月15日 广州）天 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=388 binary=1 free_heap=6796772 +I (45219) Application: .. AI: ### 今日（2026年5月15日 广州）天气 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=394 binary=1 free_heap=6800988 +I (45239) Application: .. AI: ### 今日（2026年5月15日 广州）天气： +W (45249) DIAG: queue=18 deq +2026-05-15 19:22:38.517 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 15 +W (45309) DIAG: queue=16 deq +W (45369) DIAG: queue=17 deq +W (45399) DIAG: rssi=-30 ch=1 +W (45399) DIAG: free_int=54219 psram=6774636 largest_int=23552 frag=56.6% +W (45429) DIAG: queue=15 deq +W (45479) DIAG: queue=15 enq_ws +W (45529) DIAG: queue=13 deq +W (45589) DIAG: queue=11 deq +W (45649) DIAG: queue=9 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=400 binary=1 free_heap=6786696 +I (45689) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有 +W (45709) DIAG: queue=9 enq_ws +W (45769) DIAG: queue=6 deq +W (45829) DIAG: queue=3 deq +W (45889) DIAG: queue=1 deq +W (45949) DIAG: queue=1 enq_ws +W (46029) DIAG: queue=1 enq_ws +W (46089) DIAG: queue=1 enq_ws +2026-05-15 19:22:39.459 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 68:4:95,in: jitter nor=148 reor=1827, wj=384, out: pkt=73 t_diff=180 seq_diff=5 buffer_ms=140 target_ms=100 expand_npkt=0 expand_loss=35 start_seq 497 end_seq 631 +W (46239) DIAG: queue=1 enq_ws +W (46289) DIAG: queue=2 enq_ws +W (46349) DIAG: queue=1 enq_ws +W (46399) DIAG: rssi=-30 ch=1 +W (46399) DIAG: free_int=60115 psram=6764616 largest_int=23552 frag=60.8% +W (46419) DIAG: queue=1 enq_ws +W (46509) DIAG: queue=1 enq_ws +I (46569) Application: dialog对话空闲倒计时剩余: 40 秒 +W (46569) DIAG: queue=1 enq_ws +W (46679) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=406 binary=1 free_heap=6791600 +I (46709) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵 +W (46729) DIAG: queue=0 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=412 binary=1 free_heap=6768528 +I (46779) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨 +W (46859) DIAG: queue=1 enq_ws +W (46909) DIAG: queue=2 deq +W (46969) DIAG: queue=0 deq +W (47029) DIAG: queue=2 enq_ws +I (47059) VolcRtcProtocol: 上行音频统计: PCM帧=51 字节=16320, G711A帧=0 字节=0, 速率=64885 bps +I (47059) VolcRtcProtocol: 下行音频统计: PCM字节=16960, OPUS字节=0 +W (47119) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=418 binary=1 free_heap=6804584 +I (47169) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨， +W (47169) DIAG: queue=1 enq_ws +W (47229) DIAG: queue=1 enq_ws +W (47289) DIAG: queue=2 enq_ws +2026-05-15 19:22:40.557 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 5 +W (47349) DIAG: queue=1 enq_ws +2026-05-15 19:22:40.639 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 284, e2e_avg: 457, e2e_max: 861 +W (47399) DIAG: rssi=-30 ch=1 +W (47399) DIAG: free_int=57691 psram=6779216 largest_int=23552 frag=59.2% +W (47399) DIAG: queue=8 enq_ws +W (47469) DIAG: queue=6 deq +W (47529) DIAG: queue=5 deq +W (47589) DIAG: queue=5 deq +W (47639) DIAG: queue=6 enq_ws +W (47689) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=424 binary=1 free_heap=6769320 +I (47719) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气 +W (47749) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=430 binary=1 free_heap=6780120 +I (47789) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温 +W (47809) DIAG: queue=1 deq +W (47869) DIAG: queue=1 enq_ws +2026-05-15 19:22:41.141 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 4 +W (47929) DIAG: queue=1 enq_ws +W (47989) DIAG: queue=1 enq_ws +W (48049) DIAG: queue=1 enq_ws +W (48109) DIAG: queue=3 enq_ws +W (48169) DIAG: queue=0 deq +2026-05-15 19:22:41.480 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 70:1:117,in: jitter nor=111 reor=1962, wj=252, out: pkt=69 t_diff=126 seq_diff=7 buffer_ms=180 target_ms=100 expand_npkt=0 expand_loss=46 start_seq 606 end_seq 730 +W (48229) DIAG: queue=0 deq +W (48279) DIAG: queue=3 enq_ws +W (48339) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=431 binary=1 free_heap=6812008 +I (48389) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温2 +W (48399) DIAG: rssi=-30 ch=1 +W (48399) DIAG: free_int=58283 psram=6778200 largest_int=23552 frag=59.6% +W (48409) DIAG: queue=2 deq +W (48529) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=432 binary=1 free_heap=6807412 +I (48579) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24 +W (48589) DIAG: queue=4 enq_ws +W (48649) DIAG: queue=1 deq +W (48889) DIAG: queue=1 enq_ws +W (48949) DIAG: queue=1 deq +W (49009) DIAG: queue=1 enq_ws +W (49069) DIAG: queue=0 deq +I (49069) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63694 bps +I (49069) VolcRtcProtocol: 下行音频统计: PCM字节=22080, OPUS字节=0 +W (49139) DIAG: queue=1 enq_ws +W (49189) DIAG: queue=0 deq +2026-05-15 19:22:42.477 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 889, e2e_avg: 359, e2e_max: 737 +W (49249) DIAG: queue=0 deq +W (49309) DIAG: queue=0 deq +W (49369) DIAG: queue=1 enq_ws +W (49399) DIAG: rssi=-28 ch=1 +W (49399) DIAG: free_int=59799 psram=6769564 largest_int=23552 frag=60.6% +W (49619) DIAG: queue=1 enq_ws +W (49709) DIAG: queue=1 enq_ws +W (49769) DIAG: queue=1 enq_ws +W (49829) DIAG: queue=1 enq_ws +W (49879) DIAG: queue=0 deq +W (49929) DIAG: queue=3 enq_ws +W (49989) DIAG: queue=7 deq +W (50049) DIAG: queue=13 deq +W (50109) DIAG: queue=10 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=433 binary=1 free_heap=6790644 +I (50119) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~ +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=434 binary=1 free_heap=6789432 +I (50129) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~3 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=435 binary=1 free_heap=6791400 +I (50149) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31 +W (50159) DIAG: queue=11 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=441 binary=1 free_heap=6795972 +I (50169) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃ +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=447 binary=1 free_heap=6795560 +I (50179) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃， +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=453 binary=1 free_heap=6797928 +I (50189) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=459 binary=1 free_heap=6793680 +I (50199) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=460 binary=1 free_heap=6794544 +W (50209) DIAG: queue=11 deq +I (50209) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度8 +2026-05-15 19:22:43.481 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 4 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=461 binary=1 free_heap=6795984 +I (50219) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82 +2026-05-15 19:22:43.492 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 66:0:103,in: jitter nor=131 reor=1683, wj=240, out: pkt=62 t_diff=292 seq_diff=9 buffer_ms=240 target_ms=100 expand_npkt=0 expand_loss=49 start_seq 719 end_seq 838 +W (50269) DIAG: queue=10 enq_ws +W (50329) DIAG: queue=8 deq +W (50389) DIAG: queue=9 enq_ws +W (50399) DIAG: rssi=-27 ch=1 +W (50399) DIAG: free_int=56983 psram=6750724 largest_int=23552 frag=58.7% +W (50449) DIAG: queue=8 enq_ws +W (50509) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=462 binary=1 free_heap=6791024 +I (50519) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82% +W (50569) DIAG: queue=3 deq +W (50629) DIAG: queue=2 deq +W (50689) DIAG: queue=0 deq +W (50749) DIAG: queue=1 deq +W (50809) DIAG: queue=0 deq +W (50869) DIAG: queue=1 enq_ws +2026-05-15 19:22:44.167 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 889, e2e_avg: 412, e2e_max: 825 +W (50929) DIAG: queue=2 enq_ws +W (50989) DIAG: queue=0 deq +W (51059) DIAG: queue=1 enq_ws +I (51079) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63737 bps +I (51079) VolcRtcProtocol: 下行音频统计: PCM字节=19520, OPUS字节=0 +W (51109) DIAG: queue=0 deq +W (51169) DIAG: queue=0 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=463 binary=1 free_heap=6813388 +I (51189) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~ +W (51229) DIAG: queue=0 deq +W (51359) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=464 binary=1 free_heap=6812060 +W (51399) DIAG: rssi=-27 ch=1 +W (51399) DIAG: free_int=59207 psram=6774996 largest_int=23552 frag=60.2% +I (51399) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~9 +2026-05-15 19:22:44.674 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 8 +W (51409) DIAG: queue=1 deq +W (51469) DIAG: queue=1 enq_ws +W (51559) DIAG: queue=1 enq_ws +W (51609) DIAG: queue=1 enq_ws +W (51669) DIAG: queue=1 enq_ws +W (51729) DIAG: queue=2 deq +W (51789) DIAG: queue=0 deq +W (51899) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=465 binary=1 free_heap=6795432 +I (51999) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91 +W (52009) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=472 binary=1 free_heap=6802112 +I (52049) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%， +I (52059) Airhub1: ADC: 2339, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (52059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=478 binary=1 free_heap=6794644 +I (52059) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东 +W (52069) DIAG: queue=9 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=484 binary=1 free_heap=6805200 +I (52069) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北 +W (52129) DIAG: queue=7 deq +W (52179) DIAG: queue=7 enq_ws +2026-05-15 19:22:45.497 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 64:2:99,in: jitter nor=113 reor=1381, wj=272, out: pkt=63 t_diff=145 seq_diff=7 buffer_ms=280 target_ms=100 expand_npkt=0 expand_loss=37 start_seq 837 end_seq 938 +W (52249) DIAG: queue=6 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=485 binary=1 free_heap=6788888 +I (52269) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/ +W (52309) DIAG: queue=4 deq +W (52369) DIAG: queue=7 enq_ws +W (52399) DIAG: rssi=-28 ch=1 +W (52399) DIAG: free_int=55879 psram=6771484 largest_int=23552 frag=57.9% +W (52429) DIAG: queue=5 deq +W (52489) DIAG: queue=5 deq +W (52549) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=491 binary=1 free_heap=6795716 +I (52559) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东 +2026-05-15 19:22:45.865 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 889, e2e_avg: 367, e2e_max: 741 +W (52609) DIAG: queue=7 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=497 binary=1 free_heap=6801120 +I (52619) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南 +W (52669) DIAG: queue=5 deq +W (52729) DIAG: queue=5 deq +W (52789) DIAG: queue=5 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=503 binary=1 free_heap=6802956 +I (52819) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风 +W (52849) DIAG: queue=5 deq +W (52909) DIAG: queue=5 deq +W (52969) DIAG: queue=5 deq +W (53019) DIAG: queue=5 enq_ws +W (53069) DIAG: queue=5 enq_ws +I (53089) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63680 bps +I (53089) VolcRtcProtocol: 下行音频统计: PCM字节=26240, OPUS字节=0 +W (53149) DIAG: queue=3 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=504 binary=1 free_heap=6777268 +I (53199) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2 +W (53199) DIAG: queue=5 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=505 binary=1 free_heap=6799296 +I (53229) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~ +2026-05-15 19:22:46.500 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 8 +W (53249) DIAG: queue=5 enq_ws +W (53309) DIAG: queue=3 enq_ws +W (53389) DIAG: queue=0 deq +W (53399) DIAG: rssi=-27 ch=1 +W (53399) DIAG: free_int=60103 psram=6761344 largest_int=23552 frag=60.8% +W (53449) DIAG: queue=1 enq_ws +W (53509) DIAG: queue=2 deq +W (53559) DIAG: queue=3 enq_ws +W (53629) DIAG: queue=3 deq +W (53689) DIAG: queue=1 deq +W (53749) DIAG: queue=0 deq +W (53809) DIAG: queue=0 deq +W (53879) DIAG: queue=1 enq_ws +W (53929) DIAG: queue=0 deq +W (53999) DIAG: queue=1 enq_ws +W (54079) DIAG: queue=1 enq_ws +W (54169) DIAG: queue=1 enq_ws +W (54229) DIAG: queue=0 deq +2026-05-15 19:22:47.543 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 77:0:100,in: jitter nor=124 reor=1304, wj=165, out: pkt=79 t_diff=101 seq_diff=3 buffer_ms=220 target_ms=100 expand_npkt=0 expand_loss=10 start_seq 937 end_seq 1036 +W (54349) DIAG: queue=1 enq_ws +W (54399) DIAG: rssi=-28 ch=1 +W (54399) DIAG: free_int=60103 psram=6745756 largest_int=23552 frag=60.8% +W (54409) DIAG: queue=1 enq_ws +W (54469) DIAG: queue=1 enq_ws +W (54529) DIAG: queue=0 deq +I (54569) Application: dialog对话空闲倒计时剩余: 39 秒 +W (54579) DIAG: queue=1 enq_ws +W (54639) DIAG: queue=1 enq_ws +W (54709) DIAG: queue=1 deq +W (54769) DIAG: queue=1 enq_ws +W (54819) DIAG: queue=2 enq_ws +W (54889) DIAG: queue=1 enq_ws +W (54949) DIAG: queue=0 deq +I (54959) Airhub1: 📤 准备上报设备状态，电量: 100% +I (54959) Airhub1: 📤 上报数据: {"mac_address":"d0:cf:13:03:bb:f2","is_online":true,"battery":100,"volume":80,"brightness":50} +I (54969) EspHttp: Opening HTTP connection to http://192.168.124.86:8000/api/v1/devices/report-status +W (55009) DIAG: queue=1 enq_ws +2026-05-15 19:22:48.290 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 889, e2e_avg: 327, e2e_max: 498 +W (55069) DIAG: queue=7 deq +I (55099) VolcRtcProtocol: 上行音频统计: PCM帧=51 字节=16320, G711A帧=0 字节=0, 速率=64932 bps +I (55099) VolcRtcProtocol: 下行音频统计: PCM字节=22400, OPUS字节=0 +W (55129) DIAG: queue=5 deq +W (55189) DIAG: queue=4 deq +W (55249) DIAG: queue=4 enq_ws +W (55309) DIAG: queue=2 deq +W (55369) DIAG: queue=4 enq_ws +W (55429) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=506 binary=1 free_heap=6794572 +I (55429) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=518 binary=1 free_heap=6793152 +I (55439) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级， +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=519 binary=1 free_heap=6794820 +I (55449) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，A +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=520 binary=1 free_heap=6792744 +I (55459) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQ +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=522 binary=1 free_heap=6793316 +I (55459) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=534 binary=1 free_heap=6800188 +I (55469) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优， +W (55489) DIAG: queue=4 enq_ws +W (55549) DIAG: queue=4 enq_ws +W (55609) DIAG: queue=2 deq +W (55669) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=540 binary=1 free_heap=6799984 +I (55709) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不 +W (55729) DIAG: queue=2 deq +W (55789) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=546 binary=1 free_heap=6798540 +I (55809) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适 +W (55849) DIAG: queue=2 deq +W (55909) DIAG: queue=2 deq +W (55969) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=552 binary=1 free_heap=6798152 +I (56009) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜 +W (56029) DIAG: queue=4 enq_ws +W (56089) DIAG: queue=2 deq +W (56149) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=558 binary=1 free_heap=6797500 +I (56209) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜户 +W (56209) DIAG: queue=4 enq_ws +W (56269) DIAG: queue=2 deq +2026-05-15 19:22:49.559 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 93:2:130,in: jitter nor=92 reor=1315, wj=22, out: pkt=88 t_diff=145 seq_diff=5 buffer_ms=340 target_ms=100 expand_npkt=0 expand_loss=26 start_seq 1037 end_seq 1142 +W (56329) DIAG: queue=2 deq +2026-05-15 19:22:49.619 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 433, e2e_avg: 260, e2e_max: 472 +W (56389) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=564 binary=1 free_heap=6801240 +I (56409) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜户外 +W (56449) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=570 binary=1 free_heap=6800788 +I (56509) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜户外运 +W (56509) DIAG: queue=2 deq +I (56569) Application: dialog对话空闲倒计时剩余: 40 秒 +W (56569) DIAG: queue=2 deq +W (56629) DIAG: queue=4 enq_ws +W (56689) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=576 binary=1 free_heap=6802440 +I (56709) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜户外运动 +W (56749) DIAG: queue=2 deq +W (56809) DIAG: queue=2 deq +W (56869) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=582 binary=1 free_heap=6799852 +I (56909) Application: .. AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜户外运动和 +W (56929) DIAG: queue=4 enq_ws +W (56989) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=599 binary=1 free_heap=6799408 +I (57009) Application: 📝 AI: ### 今日（2026年5月15日 广州）天气：有阵雨，气温24~31℃，湿度82%~91%，东北/东南风2~3级，AQI优，不适宜户外运动和洗车。 +W (57049) DIAG: queue=4 enq_ws +W (57109) DIAG: queue=2 deq +I (57109) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63664 bps +I (57109) VolcRtcProtocol: 下行音频统计: PCM字节=31040, OPUS字节=0 +E (57139) esp-tls: [sock=60] delayed connect error: Connection reset by peer +E (57139) transport_base: Failed to open a new connection: 32772 +E (57139) HTTP_CLIENT: Connection failed, sock < 0 +E (57139) EspHttp: Failed to perform HTTP request: ESP_ERR_HTTP_CONNECT +E (57139) Airhub1: ❌ 连接服务器失败: http://192.168.124.86:8000/api/v1/devices/report-status +W (57139) DIAG: rssi=-27 ch=1 +W (57139) DIAG: free_int=58855 psram=6771396 largest_int=23552 frag=60.0% +W (57139) DIAG: rssi=-27 ch=1 +W (57139) DIAG: free_int=58855 psram=6771396 largest_int=23552 frag=60.0% +W (57169) DIAG: queue=2 deq +W (57229) DIAG: queue=2 deq +W (57289) DIAG: queue=1 deq +W (57339) DIAG: queue=3 enq_ws +W (57389) DIAG: queue=3 enq_ws +W (57399) DIAG: rssi=-27 ch=1 +W (57399) DIAG: free_int=58903 psram=6741648 largest_int=23552 frag=60.0% +W (57449) DIAG: queue=2 enq_ws +W (57519) DIAG: queue=3 enq_ws +W (57589) DIAG: queue=0 deq +W (57649) DIAG: queue=0 deq +W (57699) DIAG: queue=3 enq_ws +2026-05-15 19:22:50.998 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 20 +W (57749) DIAG: queue=3 enq_ws +W (57819) DIAG: queue=2 enq_ws +W (57879) DIAG: queue=1 enq_ws +W (57949) DIAG: queue=1 enq_ws +W (58019) DIAG: queue=1 enq_ws +W (58069) DIAG: queue=0 deq +W (58119) DIAG: queue=2 enq_ws +W (58189) DIAG: queue=0 deq +W (58249) DIAG: queue=2 enq_ws +2026-05-15 19:22:51.537 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 19 +2026-05-15 19:22:51.566 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 80:1:84,in: jitter nor=75 reor=494, wj=239, out: pkt=87 t_diff=72 seq_diff=3 buffer_ms=200 target_ms=100 expand_npkt=0 expand_loss=2 start_seq 1143 end_seq 1236 +W (58309) DIAG: queue=3 enq_ws +W (58369) DIAG: queue=0 deq +W (58399) DIAG: rssi=-26 ch=1 +W (58399) DIAG: free_int=59547 psram=6780280 largest_int=23552 frag=60.4% +W (58429) DIAG: queue=1 enq_ws +W (58489) DIAG: queue=2 enq_ws +W (58539) DIAG: queue=1 enq_ws +I (58569) Application: dialog对话空闲倒计时剩余: 39 秒 +W (58619) DIAG: queue=1 enq_ws +2026-05-15 19:22:51.916 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 6, e2e_avg: 199, e2e_max: 297 +W (58669) DIAG: queue=2 enq_ws +W (58729) DIAG: queue=1 enq_ws +W (58789) DIAG: queue=1 deq +W (58849) DIAG: queue=1 enq_ws +W (58979) DIAG: queue=1 enq_ws +W (59029) DIAG: queue=1 deq +W (59079) DIAG: queue=1 enq_ws +I (59119) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63664 bps +I (59119) VolcRtcProtocol: 下行音频统计: PCM字节=22720, OPUS字节=0 +W (59139) DIAG: queue=2 enq_ws +W (59209) DIAG: queue=0 deq +W (59269) DIAG: queue=1 enq_ws +W (59329) DIAG: queue=1 enq_ws +W (59379) DIAG: queue=3 enq_ws +W (59399) DIAG: rssi=-27 ch=1 +W (59399) DIAG: free_int=58891 psram=6789824 largest_int=23552 frag=60.0% +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=317 binary=1 free_heap=6824452 +I (59419) Application: .. AI: 未 +W (59449) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=323 binary=1 free_heap=6825860 +I (59469) Application: .. AI: 未来 +W (59509) DIAG: queue=2 deq +W (59569) DIAG: queue=2 deq +W (59629) DIAG: queue=4 enq_ws +W (59689) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=329 binary=1 free_heap=6797540 +I (59709) Application: .. AI: 未来三 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=335 binary=1 free_heap=6802908 +I (59709) Application: .. AI: 未来三天 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=341 binary=1 free_heap=6799220 +I (59729) Application: .. AI: 未来三天均 +W (59749) DIAG: queue=2 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=347 binary=1 free_heap=6773620 +I (59779) Application: .. AI: 未来三天均有 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=353 binary=1 free_heap=6796796 +I (59789) Application: .. AI: 未来三天均有降 +W (59809) DIAG: queue=1 deq +W (59869) DIAG: queue=0 deq +W (59929) DIAG: queue=0 deq +W (59989) DIAG: queue=0 deq +W (60049) DIAG: queue=0 deq +W (60109) DIAG: queue=3 enq_ws +W (60169) DIAG: queue=0 deq +W (60229) DIAG: queue=0 deq +W (60289) DIAG: queue=1 enq_ws +2026-05-15 19:22:53.600 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 72:3:111,in: jitter nor=95 reor=773, wj=225, out: pkt=71 t_diff=116 seq_diff=5 buffer_ms=220 target_ms=100 expand_npkt=0 expand_loss=30 start_seq 1228 end_seq 1333 +W (60349) DIAG: queue=2 enq_ws +2026-05-15 19:22:53.641 [W] EngineImplX.c:517 callback pEngineImplX->eventHandler.on_audio_data used too many times 24 +W (60399) DIAG: rssi=-26 ch=1 +W (60399) DIAG: free_int=60087 psram=6750664 largest_int=23552 frag=60.8% +W (60419) DIAG: queue=1 enq_ws +W (60469) DIAG: queue=4 deq +2026-05-15 19:22:53.759 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 6, e2e_avg: 235, e2e_max: 532 +W (60529) DIAG: queue=3 deq +I (60569) Application: dialog对话空闲倒计时剩余: 40 秒 +W (60589) DIAG: queue=0 deq +W (60679) DIAG: queue=1 enq_ws +W (60729) DIAG: queue=0 deq +W (60799) DIAG: queue=1 enq_ws +W (60979) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=365 binary=1 free_heap=6822636 +I (61029) Application: .. AI: 未来三天均有降水， +2026-05-15 19:22:54.302 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 9 +W (61089) DIAG: queue=1 enq_ws +I (61129) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63636 bps +I (61139) VolcRtcProtocol: 下行音频统计: PCM字节=20160, OPUS字节=0 +W (61149) DIAG: queue=1 enq_ws +W (61299) DIAG: queue=1 enq_ws +W (61379) DIAG: queue=1 enq_ws +W (61399) DIAG: rssi=-27 ch=1 +W (61399) DIAG: free_int=59415 psram=6757304 largest_int=23552 frag=60.4% +W (61449) DIAG: queue=2 deq +W (61499) DIAG: queue=3 enq_ws +W (61549) DIAG: queue=2 deq +W (61609) DIAG: queue=0 deq +W (61669) DIAG: queue=0 deq +W (61719) DIAG: queue=4 enq_ws +W (61789) DIAG: queue=3 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=366 binary=1 free_heap=6807384 +I (61809) Application: .. AI: 未来三天均有降水，1 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=367 binary=1 free_heap=6805988 +I (61819) Application: .. AI: 未来三天均有降水，16 +2026-05-15 19:22:55.096 [W] EngineImplX.c:1047 callback pEngineImplX->eventHandler.on_message_received used too many times 9 +W (61849) DIAG: queue=1 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=373 binary=1 free_heap=6800604 +I (61859) Application: .. AI: 未来三天均有降水，16日 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=379 binary=1 free_heap=6806368 +I (61899) Application: .. AI: 未来三天均有降水，16日中 +W (61909) DIAG: queue=1 deq +W (61969) DIAG: queue=1 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=391 binary=1 free_heap=6798468 +I (61979) Application: .. AI: 未来三天均有降水，16日中雨， +W (62029) DIAG: queue=0 deq +I (62059) Airhub1: ADC: 2339, 原始电压: 2.34V, 计算电池电压: 10.15V, 电量: 100%, 满电电压: 4.20V +I (62059) BluetoothMAC: Bluetooth MAC Address: d0:cf:13:03:bb:f2 +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=392 binary=1 free_heap=6806248 +I (62069) Application: .. AI: 未来三天均有降水，16日中雨，1 +W (62089) DIAG: queue=4 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=393 binary=1 free_heap=6788380 +I (62119) Application: .. AI: 未来三天均有降水，16日中雨，17 +W (62149) DIAG: queue=1 deq +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=399 binary=1 free_heap=6789944 +I (62189) Application: .. AI: 未来三天均有降水，16日中雨，17日 +W (62209) DIAG: queue=1 deq +W (62279) DIAG: queue=1 enq_ws +2026-05-15 19:22:55.583 [I] rx_net_audio_jitterbuffer.c:1717 is burst ver, [a_jb] rtt_to_s: 38, e2e_avg: 242, e2e_max: 652 +W (62329) DIAG: queue=0 deq +2026-05-15 19:22:55.603 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 66:4:109,in: jitter nor=153 reor=1249, wj=183, out: pkt=58 t_diff=182 seq_diff=15 buffer_ms=380 target_ms=100 expand_npkt=0 expand_loss=48 start_seq 1322 end_seq 1434 +W (62379) DIAG: queue=6 enq_ws +W (62399) DIAG: rssi=-27 ch=1 +W (62399) DIAG: free_int=58307 psram=6760160 largest_int=23552 frag=59.6% +W (62449) DIAG: queue=3 deq +W (62509) DIAG: queue=1 deq +W (62569) DIAG: queue=1 enq_ws +W (62629) DIAG: queue=4 enq_ws +W (62689) DIAG: queue=0 deq +W (62749) DIAG: queue=0 deq +W (62979) DIAG: queue=1 enq_ws +I (63139) VolcRtcProtocol: 上行音频统计: PCM帧=51 字节=16320, G711A帧=0 字节=0, 速率=65040 bps +I (63139) VolcRtcProtocol: 下行音频统计: PCM字节=19200, OPUS字节=0 +W (63169) DIAG: queue=1 enq_ws +W (63319) DIAG: queue=1 enq_ws +W (63399) DIAG: rssi=-28 ch=1 +W (63399) DIAG: free_int=59391 psram=6771488 largest_int=23552 frag=60.3% +W (63529) DIAG: queue=1 enq_ws +[INF|volc_rtc.c:475]message received channel=aibotrtc_G711A_d0_cf_13_03_bb_f0_20260515112216000 src=bot_20260515112216000 size=415 binary=1 free_heap=6814472 +I (63539) Application: 📝 AI: 未来三天均有降水，16日中雨，17日中雨。 +W (63599) DIAG: queue=1 enq_ws +W (63679) DIAG: queue=1 enq_ws +2026-05-15 19:22:56.963 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 3 packets . Send time history too small? +W (63759) DIAG: queue=1 enq_ws +2026-05-15 19:22:57.261 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 4 packets . Send time history too small? +W (64079) DIAG: queue=1 enq_ws +2026-05-15 19:22:57.358 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 145000 +W (64129) DIAG: queue=8 deq +W (64189) DIAG: queue=5 deq +W (64249) DIAG: queue=2 deq +W (64309) DIAG: queue=1 deq +2026-05-15 19:22:57.623 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 22:2:28,in: jitter nor=229 reor=1398, wj=439, out: pkt=38 t_diff=319 seq_diff=2 buffer_ms=40 target_ms=100 expand_npkt=0 expand_loss=69 start_seq 1435 end_seq 1459 +W (64399) DIAG: rssi=-28 ch=1 +W (64399) DIAG: free_int=60031 psram=6795032 largest_int=23552 frag=60.8% +2026-05-15 19:22:57.747 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 196750 +I (64569) Application: dialog对话空闲倒计时剩余: 39 秒 +2026-05-15 19:22:58.049 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 256262 +I (65149) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63669 bps +I (65149) VolcRtcProtocol: 下行音频统计: PCM字节=6080, OPUS字节=0 +W (65399) DIAG: rssi=-27 ch=1 +W (65399) DIAG: free_int=60031 psram=6796480 largest_int=23552 frag=60.8% +2026-05-15 19:22:58.747 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 1 packets . Send time history too small? +2026-05-15 19:22:58.847 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 145000 +2026-05-15 19:22:59.417 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 3 packets . Send time history too small? +2026-05-15 19:22:59.618 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 4 packets . Send time history too small? +2026-05-15 19:22:59.626 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 0:0:0,in: jitter nor=0 reor=0, wj=439, out: pkt=0 t_diff=0 seq_diff=0 buffer_ms=40 target_ms=100 expand_npkt=0 expand_loss=26 start_seq 0 end_seq 0 +2026-05-15 19:22:59.628 [W] rx_net_transport_feedback_adapter.c:329 Failed to lookup send time for 2 packets . Send time history too small? +2026-05-15 19:22:59.662 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 145000 +W (66399) DIAG: rssi=-26 ch=1 +W (66399) DIAG: free_int=60031 psram=6799428 largest_int=23552 frag=60.8% +I (66569) Application: dialog对话空闲倒计时剩余: 37 秒 +2026-05-15 19:23:00.059 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 196750 +2026-05-15 19:23:00.403 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 256262 +I (67159) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63714 bps +I (67159) VolcRtcProtocol: 下行音频统计: PCM字节=0, OPUS字节=0 +W (67399) DIAG: rssi=-29 ch=1 +W (67399) DIAG: free_int=60031 psram=6779096 largest_int=23552 frag=60.8% +2026-05-15 19:23:00.772 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 324701 +2026-05-15 19:23:01.549 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 145000 +2026-05-15 19:23:01.613 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +2026-05-15 19:23:01.614 [E] EventReportSDK.c:596 operation returned status code: 0x00000022 +2026-05-15 19:23:01.630 [I] rx_net_audio_jitterbuffer.c:1537 [a_jb]insert ok:dup:total 0:0:0,in: jitter nor=0 reor=0, wj=439, out: pkt=0 t_diff=0 seq_diff=0 buffer_ms=40 target_ms=100 expand_npkt=0 expand_loss=147 start_seq 0 end_seq 0 +W (68399) DIAG: rssi=-26 ch=1 +W (68399) DIAG: free_int=59375 psram=6799976 largest_int=23552 frag=60.3% +I (68569) Application: dialog对话空闲倒计时剩余: 35 秒 +2026-05-15 19:23:01.856 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 196750 +2026-05-15 19:23:02.158 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 256262 +I (69169) VolcRtcProtocol: 上行音频统计: PCM帧=50 字节=16000, G711A帧=0 字节=0, 速率=63678 bps +I (69169) VolcRtcProtocol: 下行音频统计: PCM字节=0, OPUS字节=0 +2026-05-15 19:23:02.549 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 324701 +W (69399) DIAG: rssi=-29 ch=1 +W (69399) DIAG: free_int=60031 psram=6802004 largest_int=23552 frag=60.8% +2026-05-15 19:23:02.852 [I] rx_net_lite_cc_bandwidth_estimation.c:200 lite-cc bandwidth up bandwidth = 403406 +2026-05-15 19:23:03.449 [I] rx_net_lite_cc_bandwidth_estimation.c:200 \ No newline at end of file diff --git a/main/application.cc b/main/application.cc index a6ea689..c2e1d3d 100644 --- a/main/application.cc +++ b/main/application.cc @@ -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 +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 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 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++;