Files
contentm_agent/daemon-内存观察-复现单.md
T

113 lines
6.8 KiB
Markdown
Raw Normal View History

# daemon 内存观察 · 复现单(A 方案)
> 用途:坐实「会话活跃 ⇒ 事件洪峰 ⇒ daemon 内存暴涨」这条链是否成立。
> 起因:2026-10-09 一次后台会话被终止,根因链为「daemon 内存 957MB 被杀 ⇒ 连带 cli exit:1 ⇒ 会话 terminated」。
> 完整背景见同目录 `daemon-异常终止取证-20261009.md`。
> 触发时机:**下次派「大文件产出」类执行会话时顺带做**,不专门安排。
---
## 一、第一组对照已经拿到(2026-10-09 06:4x,意外收获)
两次观测的**事件速率同量级,内存表现却差五倍** —— 这条直接推翻了我原来的半个假设。
**暴涨组**(daemon `53940`,2026-10-09 00:4x–00:5x,会话在写 133KB 的 HTML):
- 内存:`160MB → 444MB → 957MB`(三分钟近六倍,rss 1162MB),随后被杀。
- 事件增量:`+9097 → +16869 → +18727`(每分钟)。
**平稳组**(daemon `73936`,2026-10-09 06:32–06:38,会话在跑闸门、复制工具):
- 内存:`116MB → 157MB → 190MB → 202MB`,**呈锯齿**(95–202MB 来回,GC 一直在回收)。
- 事件增量:`+20758 → +11422`(每分钟)。
**结论一**:事件速率不是充分因 —— 平稳组的事件速率**不比暴涨组低**,内存却稳在 200MB 以内。
**结论二(已在本组第二轮观察后被削弱,见下)**:暴涨组的独有动作是**一次写入 133KB 大文件**(`ui/mcn-workbench.html`,133459 B),且当时连着出现 5 条 `[ResourceReport] artifact observed`。当时以为「大文件写入」是唯一可疑触发点。
**结论三(2026-10-09 06:43 追加,推翻结论二)**:第二轮对照里,那个会话**同样写了大文件**(`mcn-workbench.html` 从 133459 B 改到 135041 B,另有 146341 B 的 dom dump),内存峰值却只有 **260MB**,还被 GC 收回了 64MB。⇒ **连"写大文件"也不是充分因。**
**结论四(当前定性)**:三次观测的峰值分别是 **609MB(收回)/957MB(未收回)/260MB(收回)**,差异看起来更像**随机振幅**。所以问题不是"哪个动作撑爆它",而是 **daemon 内存本来就在高振幅锯齿,能不能收回取决于 GC 时机;957MB 那次是"没赶上"的尾部事件**。
---
## 二、下一组要采什么(三样,缺一条就说不清)
1、**内存曲线** —— `[DaemonMemWatch]` 的 `heapUsed / heapTotal / rss`,一分钟一条。
2、**事件计数** —— `Conversation event push summary` 的 `received` 增量,一分钟一条。
3、**会话动作时间线** —— 该会话在什么时刻用了 `Write` / `Edit`、写了多大的文件。
第 3 样最关键:**没有它就无法判断"暴涨发生在写大文件的那一刻还是别处"**。
---
## 三、现成命令(可直接复制)
**实时盯内存与事件(采样器已备好)**:
```
E:/ProgramData/.workbuddy/binaries/python/versions/3.13.12/python.exe mem_watch.py
```
脚本在工作区根(`mem_watch.py`,与其它 py 脚本同级;⛔ 别放 `tmp/`,那里会被清理)。改时长与间隔就改脚本开头的 `DURATION` / `INTERVAL`;输出追加到 `tmp/mem-watch-<日期>.csv`。脚本**只读 `daemon.log`**,不碰任何进程。
**补第 3 样(会话动作时间线)**:
```
ls -la --time-style=+"%H:%M" <目标目录>/ui/
```
```
grep -E "<时间窗>" <logs>/daemon.log | grep "<sessionId>" | grep -oE '"message":\[[^]]{0,120}' | sort | uniq -c | sort -rn
```
**拉完整内存曲线**:
```
grep "DaemonMemWatch" <logs>/daemon.log | sed -E 's/.*timestamp":"([^"]+)".*heapUsed=([0-9]+MB).*rss=([0-9]+MB).*/\1 heap=\2 rss=\3/'
```
---
## 四、判据(怎么算"验证成立")
- **若成立**:内存暴涨的时刻应与某次 `Write` / `Edit` 大文件**同秒或紧随**,且该时段 `received` 增量同步跳升。
- **若不成立**:出现内存暴涨但当时**没有大文件写入** ⇒ 嫌疑转向 `artifact` 快照、`modify-backup` 或别的东西,需要抓堆快照才能继续。
- **无论成立与否都要记的**:这一轮内存峰值是否被 GC 收回(对照第一组:第一轮 609MB 收回了、第二轮 957MB 没赶上)。
---
## 五、落点
- 采样数据:`tmp/mem-watch-<日期>.csv`
- 观察结论:追加到本文件「六、观察记录」一节,并同步进 `daemon-异常终止取证-20261009.md`
- ⛔ 不做的事:不调 daemon 启动参数、不重启 daemon、不打断在跑的会话(那是候选 B 的代价,已否掉)
---
## 六、观察记录
### 第 1 组 · 2026-10-09 06:32–06:38(在执行会话 `cc07347c` 现场)
- 会话:`[执行]-[产品规划]-重做界面补闸门与上报(第二棒)`,06:32:15 起,observed 时在 `working`。
- daemon:`73936`(起于 2026-10-09 00:53:38)。
- 内存:`116MB → 157MB → 132MB → 190MB → 154MB → 202MB → 191MB`(锯齿,峰值缓升)。
- 事件:`received` 从 `420014`(06:35)涨到 `452194`(06:37),增量 `+20758` / `+11422`。
- 该时段会话动作:读旧工具目录、建 `ui/_tools`/`ui/_scratch`(06:37),**尚未写大文件**。
- 判定:**内存未失控**。与暴涨组形成有效对照 ⇒ 见第一节「结论一」。
### 第 2 组 · 2026-10-09 06:38:38–06:43:38(同一会话,20 秒一条采样)
- daemon:`73936`。数据源:`tmp/mem-watch-20261009.csv`。
- 内存全程:`191 → 193 → 260 → 196 → 205MB`(rss `450 → 501 → 524 → 443 → 450MB`)。
- 🔴 **`06:39:58` 涨到 260MB,`06:40:58` 掉回 196MB** —— **GC 收回 64MB**,与暴涨组第一轮(609→132)同型。
- 事件:`received` 从 `452194`(06:38)涨到 `494281`(06:43),**5 分钟 +42087,平均 8417/分钟**。
- 🔴 **该时段会话确实写了大文件**:`ui/mcn-workbench.html` 由 133459 B 改到 **135041 B**(06:39),另产出 **146341 B** 的 `ui/_scratch/p1-1440-dom.html`(06:36)与 133459 B 的 `.bak-before-gatefix.html`(06:38)。
- 判定:**写了同量级的大文件,内存却只到 260MB 且被收回** ⇒ 第一节「结论二」被推翻,改按「结论三 / 结论四」定性。
### 三次观测并排(当前全部数据点)
- 第 1 次 · daemon `53940`:峰值 **609MB**,**被 GC 收回**(→132MB);随后又涨到 **957MB**,**未收回,被杀**。
- 第 2 次 · daemon `73936`(06:32–06:38):峰值 **202MB**,锯齿未失控。
- 第 3 次 · daemon `73936`(06:38–06:43):峰值 **260MB**,**被 GC 收回**(→196MB),期间写了大文件。
**汇总判定**:目前**没有任何单一动作能解释 957MB 那次的失控**。三次的峰值差异更像振幅随机;能稳定观察到的只有"涨上去、GC 再收回"这个锯齿本身。**要继续找因,唯一可靠的办法是堆快照**(看增长集中在哪类对象),而不是再攒曲线点。