b212 线上 blade-agent 卡顿调查日志

2026-07-02 · 目标机（box-ba）· 多用户真实流量 + 压测

Issue #1132 主 issue Issue #1142 投影节流 PR #1138 本次修复

一页结论

不是机器负载问题：32 核只用了零头、内存 15G/123G。瓶颈始终是 blade-agent 单进程 asyncio 事件循环跑满一个核，所有请求排队。
第一阶段根因（已修）：事件循环上的同步 SQLite 风暴——每个流式 delta 新开连接查 agent-board 归属、每 patch 一次序号落库、每 commit 强制 fdatasync、llm_payloads 大数据写入，再叠加每 turn 重建 TokenizerClient。
第二阶段瓶颈（待修，#1142）：SQLite 修完后，投影构建成为最大单点——工作量与 token delta 数 成正比，并发一多总量饱和。
成果：轻量接口 TTFB 从最差 40.7s → 0.5~1.9s（低负载）/ 4~6s（高并发压测，待 #1138 与 #1142 落地继续压降）；.sessions.db 从 4.4G+4.5G WAL → 26M。

调查时间线

20:24 第一轮

初步定位：单进程事件循环饱和

宿主机 32 核 load 4.75、内存 15G/123G、100+ 个沙盒容器——机器有余量
GET /api/config/models：TCP connect 1.4ms，TTFB 4.5~9s——延迟全在服务端排队
box-ba 单进程 CPU ~77%（单事件循环 ≈ 一个核的天花板）
py-spy ①（15s / 81003 样本）主线程叶子帧：connect_sqlite 29.1%、TokenizerClient.__init__ 20.2%、投影 on_event 8.9%、agent_board _connection 6.5%、next_sequence 3.8%；栈上 _maybe_emit_agent_board_file_op 33.7%、_build_compactor 21.1%
→ 提 issue #1132，给出 3 条修复建议

21:0x 第二轮

恶化到 40s，strace 实锤 GIL + fsync 风暴

TTFB 恶化到 40.7s；线程 64 → 95（其中 48 个 bg-stream docker 流读取线程，随后台任务线性增长）
strace -c 8s：futex 占 91.26%（95 线程抢 GIL/锁）；fdatasync 3041 次 ≈ 380 次/秒（每次 SQLite commit 强制刷盘）；openat ~2500 次、fcntl ~28800 次
py-spy ②：agent_board _connection 30% + connect_sqlite 26.1% + next_sequence 13%；52.9% 样本在 starlette 请求栈内——async REST 路由在事件循环上直接做同步 SQLite

13:28 重启第三轮

关掉 llm_payloads 写入后压测仍卡 → 锁定 bridge 热路径

#1133（停写 llm_payloads）部署后 TTFB 回到 5~7s，payload_log 从热点消失——但它从来不是主热点
py-spy ③：51.8% 集中在一条路径：bridge._maybe_emit_agent_board_file_op → get_by_session(47.2%) → 每次新开 SQLite 连接(46.5%)。触发源是 llm:tool_call:created——流式 tool call 的每个参数 delta 都查一次库，且代码是"先查库、后判断事件类型"

13:16~13:52 修复潮

四个 PR 合并 + 本次 PR #1138

#1133 暂停写 llm_payloads 调试日志表
#1134 全部 SQLite 连接默认 synchronous=NORMAL 等 pragma（消 fdatasync 风暴）
#1135 AgentBoardStore 复用单条持久连接
#1137 TokenizerClient 按 (model, enable_thinking) 缓存，压缩预检查移出事件循环
#1138（本次） bridge 先过滤事件类型再查库 + 归属结果按 session 缓存 30s（None 也缓存）；next_sequence 改区间预留（一次提交预留 512 个序号，DB 写降为 1/512）

14:07 重启 v1.0.7 第四轮

大幅好转；投影构建浮出成为新单点

TTFB 0.5~1.9s，load 1.9，SQLite 占比 ~70% → ~9%
py-spy ④：projections.builder.on_event 叶子帧 29.4%（栈上 42.2%）成为最大单点——每个流式 delta 的纯 Python 计算

22:21 第五轮

高并发压测再次变卡：总量饱和，无单一热点

TTFB 4~6s，box-ba CPU 101%；主线程 ~60% 流式聊天（投影 11.1% + JSON 解析 7.0%）、~29% REST 处理
agent-board 流量风暴：3 分钟内项目 120 任务列表被 GET 239 次（≈80 次/分轮询）、9 个任务被 PATCH 共 ~340 次（沙盒智能体高频更新状态，每次还触发 auto-run 检查 + 写库）
新发现：host/llm/client.py:590 每次流式请求新建 httpx.AsyncClient——每请求重建 SSL context（ssl.create_default_context 叶子帧 2.4%）、重新 TLS 握手、零连接复用
→ 提 issue #1142（delta 合并节流 + httpx client 复用）

关键指标对比

指标	最差时（第二轮）	修复部署后（第四轮）	高并发压测（第五轮）
轻量接口 TTFB	40.7s	0.5~1.9s	4~6s
主线程 SQLite 占比	~70%	~9%	~12%
fdatasync 频率	≈380 次/秒	正常（synchronous=NORMAL 后仅 checkpoint 刷盘）
宿主机 load（32 核）	4.75	1.9	2.5
.sessions.db 体积	4.4G + 4.5G WAL	26M + 0 WAL

根因解析：为什么会卡

blade-agent 是有状态单进程（Engine 内存态 + Socket.IO in-process），无法横向加 uvicorn worker，所以事件循环主线程就是全局串行点。任何同步阻塞都会让所有用户一起排队。本次按占比从大到小依次挖出：

每个流式 delta 一次 SQLite 建连查询——bridge._maybe_emit_agent_board_file_op 先查 agent-board 归属、后判断事件类型；配合 store 每次 connect+pragma+close。智能体流式写文件时每个参数分片都要走一遍。（#1135 连接复用 + #1138 事件过滤/缓存）
每次 commit 强制 fdatasync——SQLite 默认 synchronous=FULL，380 次/秒刷盘把事件循环钉在磁盘上。（#1134）
每个 chat turn 重建 TokenizerClient——读多 MB tokenizer.json + sha256 + 解析，全同步。（#1137）
llm_payloads 调试日志大数据写入——与 sessions 等业务表同库，放大所有锁竞争。（#1133 + 本次数据清理）
每个投影 patch 一次序号落库——UPDATE+SELECT+COMMIT×每 patch。（#1138 区间预留）
投影构建与 delta 数成正比——修完上面之后的新天花板。（#1142 待修：30~60ms 聚合节流）

llm_payloads 表清理记录

表位于 /opt/box-deploy/workspace/.sessions.db（全业务共享库：users / sessions / agent_board 等 40+ 张表都在里面），23894 行占了 4.4G 的 99.4%
DELETE FROM llm_payloads 耗时 32s；但 wal_checkpoint(TRUNCATE) 被 box-ba 内一个长期不结束的读事务钉住（反复重试都卡在同一帧位），WAL 反涨到 4.5G
14:07 重启 v1.0.7 释放读事务后收尾：checkpoint 成功 → 确认活数据仅 ~25MB（freelist 1136557/1143036 页）→ VACUUM 实际 0.1s → 再 checkpoint 截断
最终 4.4G + 4.5G WAL → 26M + 0 WAL，服务全程在线
📌 经验：WAL 模式下 VACUUM 后文件不会立刻缩小，要等 checkpoint 把结果写回主文件；长读事务会让 checkpoint 永远追不上

附带调查：沙盒装包为什么走 host.docker.internal:30020

这是 Blade 盒子离线交付的预期设计，不是配置错误。链路：/opt/box-deploy/.env 的 SANDBOX_PIP_INDEX_URL / SANDBOX_NPM_CONFIG_REGISTRY → compose 传给 box-ba → blade-agent 创建沙盒时注入 PIP_INDEX_URL / NPM_CONFIG_REGISTRY 环境变量（sandbox/docker_utils.py）。30020 是 box-nexus-index（自研前置索引），背后是 Sonatype Nexus 的 pypi-proxy / npm-proxy 代理仓库：断网时命中预热缓存，有网时代理上游并缓存，几十个沙盒的下载流量收敛到本机。环境变量优先级高于 .npmrc，所以沙盒里写的 npmmirror 不生效。

后续待办（按优先级）

合并并部署 PR #1138（预计再削主线程 ~10%）
修 #1142：流式 delta 按 30~60ms 窗口聚合再构建/广播（结构性手段，砍数量级）；顺带热路径去 deepcopy
httpx.AsyncClient 按 profile 复用（连接池 + 免重复 SSL context / TLS 握手）
agent-board 前端任务列表轮询降频或改 Socket.IO 推送；智能体 PATCH 任务状态降频
bg-stream 后台任务读线程无上限增长治理
天花板仍不够时：#1109 多 worker / 水平扩展架构

本次用到的排查手法（备忘）

延迟归因：curl -w "connect=%{time_connect} ttfb=%{time_starttransfer}" —— connect 快 + TTFB 慢 = 服务端排队，与网络无关。

Python 热点：宿主机装 py-spy 直接 attach 容器内进程 PID（pip3 install py-spy --user --break-system-packages），record -f speedscope 采样后按主线程聚合叶子帧（self time）与栈上占比（total time）。采样文件留存于 b212 /tmp/.json，可拖入 speedscope.app 看火焰图。

syscall 佐证：timeout 8 strace -c -f -p PID —— futex 占比看 GIL/锁竞争，fdatasync/openat/fcntl 频次看 SQLite 行为模式。

SQLite 空间：PRAGMA page_count / freelist_count 先估活数据量再决定 VACUUM；checkpoint 返回 busy|log|checkpointed 三元组判断是否被读事务阻塞。