Skip to content

Long Claude Code session re-caches ~140-175K tokens per turn (cache read stuck at the fixed prefix) #5385

New issue
New issue
Open
#5386
Open
Long Claude Code session re-caches ~140-175K tokens per turn (cache read stuck at the fixed prefix)#5385
#5386
Labels
bugSomething isn't workingclaude-codep1scope/wiring

Description

@mannypolus-tech
mannypolus-tech
opened on Oct 31, 2026

Version: billion-context 0.1.208 (b261c33), Windows 11, Claude Code via ANTHROPIC_BASE_URL=http://127.0.0.1:8787/bili/https://api.anthropic.com, model claude-opus-5-5 (1M context).

What happens: In one long session (3,420 assistant turns over 4 days, still open), 947 turns wrote more than 100K cache-creation tokens. On 791 of them cache_read_input_tokens was exactly 38,013, which is only the fixed system-prompt + tools prefix. So almost the whole conversation after that prefix is re-cached on those turns.

It gets worse as the session grows (cache-creation tokens per turn, daily average):

Day | Turns | Cache write / turn | Cache read / turn -- | -- | -- | -- 1 | 968 | 43,013 | 247,592 2 | 854 | 32,442 | 364,049 3 | 687 | 131,140 | 203,742 4 | 911 | 174,308 | 235,598

Idle time doesn't explain it: 914 of the 947 big writes came less than 5 minutes after the previous turn.

Impact: Across 10 long sessions in the week, bili cut input-side tokens per turn by 64% vs. our pre-bili baseline, but the price-weighted cost fell only 18%. Without this one session the cost saving is 47%.

bili.log lines for that session (same window):

[snapshot-shadow] mechanical mismatch on <session> (lost-tail:5) — diagnostics: /__bili/diagnostics?topic=snapshot-shadow
thinking-pair-violated: 22 tool_use block(s) lost their inbound thinking block in the outbound rebuild
request: 827 msgs, inbound=21.5MiB, outbound=1.8MiB, local=925ms
nudge idle: usage=46% (459727/1000000), growth=58565/22500 (ref=401162, interval=50000), pendingT1=38911/50000

Other sessions in the same log showed no mechanical mismatch lines.

Guess (not proven): the rewritten outbound history changes somewhere early in the conversation each turn, so the prompt-cache breakpoint after the fixed prefix never matches.

Ask: is there a diagnostic for which message index first differs between consecutive outbound requests? Glad to run it.

Activity

  1. ranxianglei commented on Oct 31, 2026

    @ranxianglei
    ranxianglei
    on Oct 31, 2026
    Owner

    🤖 Powered by ework · qwen3.8-27b

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

    查重：不重复。 检索了 open+closed 全部 issue（按症状关键词：cache read 卡在固定前缀、thinking-pair-violated、snapshot-shadow mechanical mismatch、长会话每轮重缓存 / 成本上升），无同机制条目。

    标签： bug claude-code scope/wiring p1 —— 缺陷类；Claude Code 车道；请求重建管道；缓存命中崩坏导致成本失控（owner 2026-10-19 修订明确把这类列为 p1）。

    版本核对： 你报的 b261c333 就是 tag v0.1.208，我按这个版本的代码路径审的（master 现已到 0.1.209，结论不受影响——相关代码这段没动）。

    先给判断，再说做了什么。 你的猜测方向对了一半：出站历史确实在某处变了、导致前缀缓存在固定前缀之后就断了。但我把出站组装的关键路径读了一遍，排除了两个最像的嫌疑：

    • 断点标记（cache_control）是按消息 id 钉死的，不是按数组下标（wire 层 anthropicToCore/coreToAnthropic 用 Map<id, control> 存取）。所以折叠删掉中间消息不会让标记「挪位」——「标记错位」这条不成立。
    • system 头被锚定成字节稳定（[Feature] Optimize the cache by reorganizing the context. #1085 sticky anchor），不会每轮变。

    你 log 里那两行我也核过了：snapshot-shadow 现在 render rollout 是 0%、shadow 只是旁路观察；thinking-pair-violated 那条也只是对比入站/出站、不改字节。它们本身不制造字节变化，但都指向同一件事——尾部确实有分歧，得看清是从哪条开始的。

    真正剩下的两个候选，只能靠「连续两次出站请求从第几条消息开始不一样」来区分。所以我把你要的诊断做了：

    已开 PR #5386（#5386 ）：加了一条 opt-in 观测日志 outbound-prefix。它逐条给出站消息打指纹（role｜内容形状｜块类型｜有无 thinking｜有无 cache_control｜长度｜内容 hash），和上一轮比对算最长公共前缀，直接打出第一次分叉的消息下标＋所有 cache_control 位置。只写日志、绝不动线上字节；开关默认关，关的时候一行不执行、零开销、零行为变化（复用现成的 ACP_DUMP_BODY / diagnostics.dumpBody 开关，没有新配置项）。

    怎么拿数据： 在出问题的那个会话上设 ACP_DUMP_BODY=1（或 config 文件 diagnostics.dumpBody:true），装一个含此改动的构建，复现几轮，把 bili.log 里的 outbound-prefix: 行贴回来就行。两种典型结果分别指向不同修法：

    • 若 lcp 每次都偏短、BREAK@k 的 k 落在会话中部且反复跳 → 中段折叠 churn：快速增长（thinking 块多）频繁越过 50K nudge 间隔，每次折叠改动折叠点之后的字节，下一轮就得从那重新缓存。这部分是「折叠＋显式缓存」随会话变长的固有代价，修法是调折预算/断点策略而非逐字节追。
    • 若连没折叠的轮次也 lcp≈0 反复崩 → 存在额外的每轮字节不稳定（例如 reasoning-drop 门在 signed thinking 被折叠出视野时翻转、或注入的临时字节），那就是要直接修的 bug。

    数据一到我就能钉死具体机制再给修复方案。

    八问：

    1. 是什么问题： 超长 Claude Code 会话里，固定前缀（system+tools ≈ 38,013 tokens）之后几乎整段对话每轮被重新写入缓存，cache_read 卡死在前缀，且随会话变长越来越贵（第 4 天单轮写 174K）。
    2. 什么原因导致的： 尚未最终定位——已排除「断点标记按数组下标漂移」和「system 头漂移」；剩下「中段折叠 churn」与「额外每轮字节不稳定」二选一，需 PR [PR] feat: outbound-prefix LCP triage line for prompt-cache-break diagnosis (#5385) #5386 的 LCP 诊断确认从哪条消息开始分叉。
    3. 影响范围与严重程度： 影响跑超长（数千轮）、thinking 密集、走纯代理模式直连 Anthropic 的用户；你测到 10 个长会话里这一个把整体成本节省从 47% 拖到只剩 18%。严重度 p1：不是不能用，而是核心卖点（省 token/省钱）在这类会话上基本失效、成本显著上涨。
    4. 怎么修复的： 本轮交付的是诊断工具（PR [PR] feat: outbound-prefix LCP triage line for prompt-cache-break diagnosis (#5385) #5386），不是修复本身——先拿到「从哪条消息开始变」这枚证据，再对症修。
    5. 是否有回归问题： 无。默认关时一行不执行；开着时只追加一条 debug/info 日志，不改任何出站字节、不改任何默认行为。
    6. 是否破坏缓存： 不影响。只读、只记日志，不碰 cache_control、不碰消息内容、不碰账本。
    7. 是否改了设计方向： 没有。纯观测面新增，复用既有 dump 开关，不动架构/边界/数据流。
    8. 是否引入了新的配置： 没有新配置项/env var——复用现成的 ACP_DUMP_BODY（env）/ diagnostics.dumpBody（config file），两者本就已文档化、默认关。

    状态判定： 诊断 PR #5386 已就绪、待 review（全量回归交给 CI 在 push 头把关）；#5385 根因仍 open。等你开了开关、贴回 outbound-prefix: 行后，我再定具体修复并跟进。

  2. ranxianglei
    added
    bugSomething isn't working
    claude-code
    p1
    scope/wiring
    on Oct 31, 2026

  3. bernhardberger commented on Nov 1, 2026

    @bernhardberger
    bernhardberger
    on Nov 1, 2026

    I'm seeing something similar with Bili 0.1.210 on Linux, using OpenCode 2.2.5 and OpenChamber's @openchamber/opencode-claude 1.7.0 with Claude Opus 5.5.

    Even in a fresh session, cache reads got stuck at exactly 40,909 tokens. Each request kept writing another 30–42K tokens into cache instead of reusing the conversation.

    After setting:

    "compress": {
  "messageTimestamps": false
}

    and restarting, cache reads started advancing normally again. So far, 21 consecutive requests have hit 85.4–99.8%, with recent ones around 98–99%.

    This wasn't a controlled A/B test, so I can't pin the improvement on timestamps alone. I haven't re-enabled them to reproduce it because the repeated cache writes were burning through subscription quota.

    Could timestamp rendering interacting with session reload or history reconciliation be worth checking? Disabling it seems to have helped here, but I can't yet say it caused the problem.

    Update: the problem recurred with compress.messageTimestamps: false still confirmed active. Cache reads froze at 40,967 tokens again, with roughly 33–42K cache writes per request, so disabling timestamps wasn’t sufficient.

    I then rolled back only the package from 0.1.210 to 0.1.209, keeping timestamps off and the existing session/database. So far, cache reads have started advancing again: 40,967 → 67,010 → 83,106 → 93,094, with hit rates improving to about 81%, 89%, and 90%. Encouraging, but only a few requests—not enough to establish a fix or isolate the cause.

  4. ranxianglei commented on Nov 1, 2026

    @ranxianglei
    ranxianglei
    on Nov 1, 2026
    Owner

    🤖 Powered by ework · qwen3.8-27b

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

    这条数据很关键，谢谢——它把嫌疑从「未知」收窄到了 bili 侧一个具体的特性上。先给结论：你的方向感对了，但根因大概率不在第三方插件，而在 bili v0.1.210 默认开启的一个新特性。

    关系定位：和原报告同一个症状（cache read 卡在固定前缀），但版本不同、机制不同——原报告在 v0.1.208（那时还没有这个特性），你这条指向另一条机制。按「同症状留一个 issue」的规则，两条都留在 #5385 里分条记，不开新帖。

    关键发现（已在你说的 v0.1.210 tag 上逐行核实）：

    为什么你的现象值得警惕：你看到的是每一轮都多写 30–42K（连新会话都卡在 40,909，21 连击），这跟「一次之后就稳定」直接矛盾。也就是说那个「不可变戳」很可能在你的环境里没跨轮/跨重载保持住——要么每轮被重铸了新时间戳，要么 time= 在连续两次出站请求之间不一致。只要它不稳，前缀缓存就会在每个被打戳的消息处断开、整段重算，正好对上「读卡在固定前缀 + 写随会话增长」。这是个真实的 bug 候选。

    诚实的置信度：你自己也说了不是受控 A/B——改开关的同时重启了，而重启本身就会重置/重种缓存，所以还锁不死就是它；也没复现。但版本完全对齐（特性恰好在你这个版本默认开）让它成为头号嫌疑，比「第三方插件」的解释有力得多。@openchamber/opencode-claude 仍是未排除的干扰项。

    怎么确认（两步任选，都不用等我）：

    1. 最快最干净：在现在的 v0.1.210 上打开请求体落盘（ACP_DUMP_BODY=1 或配置 diagnostics.dumpBody: true），抓同一会话连续两次出站请求体做 diff。判定点很具体：取同一个消息 ref（mNNNNN）的 <acp …> 标签，比较两次的 time="…" 值。同一消息的 time= 两轮不一致 = 坐实不可变戳没稳住（feat: Support precise timestamps for each message, allowing the model to recognize which messages are outdated and which | feat: 给每个消息支持精确时间,以让模型认识到什么消息是过期的什么是当前的新的 #4313 的 bug）；若 time= 稳而别处变，再往别处查。
    2. 单变量 A/B：只改 messageTimestamps、其余一律不动，看每轮写入是否回高位。缺点是这个开关要重启才生效，重启又引入变量，所以方法 1 更干净。

    我的 LCP 诊断（PR #5386）会把上面这事变成日志里的一行 [sessionId] outbound-prefix: lcp=… BREAK@N …，省得手动 diff。它目前基于旧 master，我正在 rebase 到含 #4313 的最新 master，让特性和诊断能一起测，rebase 完更新 PR。

    行为变更提示：#4313 把默认值翻成「开」本身是不小的行为变更——所有升到 v0.1.210 的用户都会在 wire 字节里突然多出 time=。按设计每人只付一次前缀重写；但若不可变性在重载/对账这类路径上不成立（正是你观察到的），就变成持续成本。这点建议一并复核。

    确认坐实后，这会是 #5385 下的另一条子机制（关联 #4313），我在本 issue 里补清单并跟进修复，在那之前不动代码。麻烦你先把方法 1 的 diff 结果、或同一消息两轮的 time= 值贴上来，我来判。

  5. ranxianglei
    added a commit that references this issue on Nov 1, 2026

    feat: add outbound-prefix LCP triage line to localize prompt-cache br…

    7ca0011

  6. ranxianglei commented on Nov 1, 2026

    @ranxianglei
    ranxianglei
    on Nov 1, 2026
    Owner

    🤖 Powered by ework · qwen3.8-27b

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

    跟进一条：PR #5386 已 rebase 到当前 master（现 v0.1.211，含 #4313），新 head = 7ca00113。本地定向测试 6/6 通过、typecheck 干净，全量回归交给推送后跑的 CI。现在这个分支同时带时间戳特性和 LCP 诊断——你要复现可以直接用它；或者按上一条「方法 1」在你现有 v0.1.210 上手动 diff 连续两次出站体，不用等这个分支。两条路都能把「同一消息的 time= 是否跨轮稳定」这件事判出来。

  7. ranxianglei commented on Nov 1, 2026

    @ranxianglei
    ranxianglei
    on Nov 1, 2026
    Owner

    🤖 Powered by ework · qwen3.8-27b

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

    补一条定位，把「方法 1」的判读变成决策表，也给后续修的人钉死代码位置：

    time= 的值就是每条消息的 message.ts（kernel/src/render-refs.ts:131），只在开关开时渲染。铸戳逻辑在 kernel/src/compress.ts:1096 的 createStampTimestampsNode：用一份持久化的 state.tsStamps（raw-id → 首次出现墙钟毫秒）当唯一来源——已存戳永远赢、渲染只读存值不调 Date.now()；只有「byRaw 里还没有的新 id」才铸一次 Date.now()；老消息绝不回填（注释原话：给旧消息伪造今天的时间是谎言）。而 tsStamps 在状态水合（src/state-hydration.ts:71）、状态克隆里都有处理，kernel 侧还有测试断言「存值优先于墙钟」「折叠不得丢首见戳」。所以这套设计本身看起来是对的、有测试兜底——我通读没找到明显的持久化漏写。

    推论：如果方法 1 真坐实了 #4313，那更可能是交互问题而非特性自身的持久化 bug。把连续两次出站体的 diff 对到下面三种之一：

    1. 同一消息 ref 的 time= 两轮一致、但别处字节变了 → 不是 feat: Support precise timestamps for each message, allowing the model to recognize which messages are outdated and which | feat: 给每个消息支持精确时间,以让模型认识到什么消息是过期的什么是当前的新的 #4313，往折叠 / 推理块 / 注入方向查；
    2. 同一条逻辑消息每轮 ref 号都在变（id 抖动）→ 上游内容不稳定，被 time= 放大暴露。你这套是 OpenCode 2.2.5 + @openchamber/opencode-claude，这个第三方插件每轮改写用户/助手内容是最可疑的变量（关掉时间戳后渲染不再依赖这个抖动的 id，字节就稳了，正好对上你的现象）；
    3. 同一 ref 但 time= 值每轮不同 → 你这条宿主车道的 tsStamps 没在轮间存活（host 侧持久化缺口，非 kernel）。

    无论命中哪种，修复都落在 kernel/ 或对应 host 车道，属人工门禁域，确认前我不动代码。麻烦你抓两次出站体，贴出同一条消息两轮的 ref 号 + time= 值，我来判定走哪条。

  8. ranxianglei
    added 5 commits that reference this issue on Nov 11, 2026

    Merge origin/master into 2026-11-01_outbound-prefix-lcp-triage — reso…

    0bcdabf

    Merge origin/master into 2026-11-01_outbound-prefix-lcp-triage — sync…

    7bd548e

    fix: list outbound-prefix.ts in the reference/architecture.md module …

    cef0993

    fix: log outbound-prefix observation failures instead of swallowing t…

    f8015e7

    test: pin the history-shrinkage break boundary in the outbound-prefix…

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingclaude-codep1scope/wiring

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions