Skip to content

[Codex CLI][v0.1.213] slow-ingest delta still exhibits a 10.3s synchronous storage spike (follow-up verification of #574 | [Codex CLI][v0.1.213] slow-ingest delta 仍出现 10.3 秒同步存储尖峰(#5744/#5756 后续实测) #6169

Open

Description

@xiaozhu1337

环境与证据口径

Windows,bili codex,Codex CLI 0.166.0/0.167.0;以下近期代理日志标记为 bili v0.1.213。

从 2026-11-04 起更新的 95 个本机 CLI 会话中筛选,排除审计自身。代理日志实际仅保留 2026-11-09 22:50:42.152 至 2026-11-11 11:41:24.397(UTC+8);仅计入能关联这些 CLI 会话的记录。条数是日志记录数,不等于独立故障数或全周故障率。会话 ID 已脱敏,未上传完整任务内容。

这是事后日志证据,尚无最小复现;下述测试为建议,未声称已实现或通过。

关联 #5744、#5756(提交本报告时已关闭),PR #5755 已于 2026-11-07 合并。本次未核对运行包的完整构建提交及 CPU profile,不是断言旧根因回归,请按剩余瓶颈归并。

1. 同步存储仍有秒级尖峰,包括 delta 路径

slow-ingest 29 条 / 2 个会话,最大 10,342ms,另有 5,346ms 和 5,144ms。slow-session 另有 5 条 / 3 个会话,最大 local=2801ms;两类时间不能简单相加。

同一保留窗口内的代表性日志(UTC+8,省略重复前缀):

2026-11-10T23:13:47.606 [v=0.1.213] [storage] slow-ingest: session-A path=delta took=10342ms, 65.4 MiB WAL lastCheckpoint=(busy=0 log=284 checkpointed=284 took=12ms)
2026-11-10T23:13:34.560 [v=0.1.213] [storage] slow-ingest: session-B path=full took=5346ms, 61.8 MiB WAL lastCheckpoint=(busy=0 log=2073 checkpointed=2073 took=0ms)
2026-11-10T23:08:45.922 [v=0.1.213] [session-C] slow-session: 65 msgs / inbound=1.3MiB took local=2801ms

日志说明同步工作占用事件循环;但没有 CPU 采样,不能从这些时间单独推出具体 SQL/函数,也不能认定 10.3 秒来自 checkpoint——该条记录里的上次 checkpoint 只有 12ms。索引库当时约 3.2GB,库大小不等于损坏或因果证据。

修复/定位建议:

  1. 先核对发布包与 [PR] fix(storage): refs ledger diffs instead of full-replace per save (#5744) #5755、[perf] delta-fallback saves still sweep O(full history) per turn (sliding-window / folded-resident views) #5756 的实际修复包含关系,再定位剩余路径,不把已修复的旧实现当作当前根因。
  2. 将 slow-ingest 分解为序列化、差异计算、各表读写、事务提交、checkpoint 的耗时和实际处理/修改行数;同时记录历史规模 H、增量 K、delta 回退原因。限量采样即可,避免诊断本身重扫历史。
  3. 用长会话、小增量、delta/full/滑动窗口/折叠窗口分别验证复杂度。只对确认的重复扫描或同值写入做增量化,并保留编辑、删除、媒体引用、refs/blocks/CCR 的一致性语义。
  4. 若仍有不可避免的同步长事务,再评估单写入队列或工作线程;必须有有界队列、背压、提交顺序和失败恢复,不能把同步 API 包一层 Promise 就视为异步修复。

**验收建议:**同时运行长会话与短会话,记录延迟分布和事件循环延迟;固定 K 增加 H 时,已支持的 delta 路径不应重新出现与 H 成比例的无效写入;崩溃恢复和历史编辑测试仍通过。不以单次 warm-cache 平均耗时作为全部验收。

Activity

  1. changed the title [-][Codex CLI][v0.1.213] slow-ingest delta 仍出现 10.3 秒同步存储尖峰(#5744/#5756 后续实测)[/-] [+][Codex CLI][v0.1.213] slow-ingest delta still exhibits a 10.3s synchronous storage spike (follow-up verification of #574 | [Codex CLI][v0.1.213] slow-ingest delta 仍出现 10.3 秒同步存储尖峰(#5744/#5756 后续实测)[/+] on Nov 11, 2026
  2. ranxianglei commented on Nov 11, 2026

    @ranxianglei
    Owner

    🤖 Powered by ework · qwen3.8-27b

    [bot]
    (ai: vllm-qwen/qwen3.8-27b)

    查重:不重复 —— #6169 是该问题族唯一开放条目:#5744(O(history) ingest)与 #5756(delta 回退全历史扫描)均已关闭,PR #5755 已于 2026-11-07 合并;本单是它们的后续实测,按「同症状同线程」原则并入本线程处理,不另开新项。

    标签:bug + codex + scope/storage + p2 —— 长会话下慢同步存储写入造成秒级事件循环卡顿,性能退化类,可用但问题明显。

    版本核对(issue 建议 #1,已完成):tag v0.1.213 的发布提交晚于 #5755 的合并提交与 #5756 的修复提交,两者均为该 tag 祖先 ⇒ 发布包包含这两处修复,10.3s 尖峰是剩余瓶颈,不是旧根因回归。同时确认 master 上 src/storage/ingest.ts 与 v0.1.213 逐字节一致(store.ts 仅多一个 #6029 的只读方法),master 上的静态分析结论对 v0.1.213 同样成立。

    剩余瓶颈静态分析(以下各条每次保存必然执行;无 CPU 采样,具体占比待打点确认):

    plan 侧 finishPlan(src/storage/ingest.ts):

    • O(B²):per-block .map 内每块调用一次 completeBlockContents(...)(ingest.ts:403),其内部每次都全量 blocks.every(...) 扫描(ingest.ts:519)——纯浪费,可提出循环且严格等价;
    • 每块 JSON.stringify×4 + sha256×3(ingest.ts:406-436);refs O(H_refs) 全量重建(ingest.ts:372-377);CCR 逐条 stringify+sha256(ingest.ts:460-465)。

    store 侧 ingestSession 事务(src/storage/store.ts):

    • blocks 全量 SELECT 含 payload_json(store.ts:1135),每块 JSON.parse 两次,covered msg ids 全量 IN 查询(store.ts:1173-1187);
    • refs 全量 SELECT(store.ts:1337-1339 —— [PR] fix(storage): refs ledger diffs instead of full-replace per save (#5744) #5755 只优化了写侧,读侧仍每次扫全部 H 行);ccr_entries 全量 SELECT(store.ts:1395);dead_refs DELETE+INSERT-all(store.ts:1298/1302)。

    排除项:watermark/boundary 探针是点查询(store.ts:1605/1679/1694);你日志里 lastCheckpoint took=12ms busy=0,不是 checkpoint 突发;剩余耗时归因于上述 O(H) 同步工作 + Windows fsync/GC(每次保存数十 MB 临时垃圾),长会话下出现秒级尾部合理。

    另发现一个观测缺口:delta 回退原因目前是静默的 —— ingestDelta 的所有 return-false 点都没有命名,现有日志无法区分走了 full 路径是因为 watermark 缺失、boundary 不匹配、head 不匹配还是 store 拒绝。这正是打点要补的。

    方案(一个 PR,本线程):

    • A 安全修复:completeBlockContents 提出循环(O(B²)→O(B)),字节等价 + 回归测试钉住 completion 行为;
    • B 可观测性(issue 建议 fix: address all code review findings (condense, routing, session-id, dead code) #2):slow-ingest warn 行分解为 plan=/store= ms、K=新消息数、Hrefs/Hblocks/Hccr、planBytes、各表读写行数,path=full 时带 fallback=<原因>;常驻计数器(整数+performance.now()),仅 >500ms 时拼字符串,不新增任何 config/env;
    • C 更深的 O(H) 消除(ref/CCR/block 水位增量)属设计决策,不进本 PR,待打点数据落地后列候选。

    进度说明:上一轮会话因环境卡死被强制重启(32 分钟无输出),期间未做任何代码改动(工作树干净);现在继续实现 A+B,完成后推 PR 并给结构化结论。

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions