Skip to content

[Bug] 会话中途 cacheReadTokens 反复回落到 ~6,144（只剩静态前缀），2–3 万 token 被重新预填充 #64

Open
Open
[Bug] 会话中途 cacheReadTokens 反复回落到 ~6,144（只剩静态前缀），2–3 万 token 被重新预填充#64

Description

@smartxm
smartxm
opened on Sep 25, 2026

先叠个甲

我是一个学生，这是我第一次在Github上发issues，以下内容和调研过程基本都是由AI完成的，内容大部分我也看不太懂，如果有任何不合适的地方或者错误请宽容一下，谢谢🌹🌹，如果需要更详细的数据随时联系我

环境

  • dsh 0.1.7-rc.2，@mars-sea/dsh-commandcode-provider 0.11.12（web profile）
  • 模型：commandcode/deepseek/deepseek-v4.1-flash；套餐 Go（Provider API 返回 403，走 /alpha/generate）
  • Windows 11 + Node v24.14.1；cordis.patch.yml 中 requestTimeoutMs: 60000
  • 网络经 Clash TUN → 新加坡节点，实测节点到 api.commandcode.ai 延迟 71–136ms

现象

同一会话内，cacheReadTokens 会间歇性掉回 ~6,144（量级与"系统提示 + 26 个工具 schema"这段共享静态前缀相当），
此时未缓存输入达 2.1–3.2 万 token，需要重新预填充；该步耗时从热缓存时的 5–7 秒涨到 20–100 秒。
一个 14 步的会话里出现 4 次。

数据（session 370f0615，14 步，最大提示 46,865 tok，失败尝试 0 次、引擎重试 0 次）

step 总提示 已缓存 未缓存 命中率 首token 输出
1/4 27,464 23,296 4,168 84.8% 27.8s 92
1/5 28,062 6,656 21,406 23.7% 5.0s 276
1/6 29,408 28,288 1,120 96.2% 6.5s 4,865
1/7 34,341 34,176 165 99.5% 6.6s 104
1/8 34,496 6,144 28,352 17.8% 19.9s 57
1/9 35,613 34,432 1,181 96.7% 6.5s 1,634
1/10 37,326 6,784 30,542 18.2% 22.4s 104
1/11 37,459 37,120 339 99.1% 5.5s 57
1/12 38,601 6,144 32,457 15.9% 55.2s 7,774
1/14 46,865 46,336 529 98.9% 36.7s 1,895

同账号同模型的对照：官方 CLI 1.65.2 连跑 60 次调用，累计 10,083,417 提示 token、命中 9,779,712（97.0%），
稳态 99.7–99.9%，全程只有 1 次掉到 3.4%。插件侧同期三个会话分别是 68.2% / 85.6% / 91.7%。

已排除（附证据）

  1. 网络/代理：流式正常（单请求 1000+ 事件、最大事件间隔 2.1s），本会话 0 次 TRANSPORT/连接错误
  2. 超时与重试：上表这些慢步的失败尝试和引擎重试均为 0
  3. 会话标识：做过 A/B（随机 threadId vs 固定 threadId + x-session-id），两者缓存行为一致
  4. 统计口径：确认 dsh 会话日志里 inputTokens 是"未缓存"、cacheReadTokens 是"已缓存"，相加才是总提示

怀疑点

  • 插件 buildCliBody 的请求体顶层字段：config / memory / taste / skills / params / threadId
  • 官方 CLI 1.65.2 的请求体：config / memory / taste / skills / permissionMode / threadId / promptCache，
    且 system 以分节数组发送（systemSections）。插件这两项都没有发送。
  • Command Code 官方仓库 issue #346（p1，已关闭）承认过"deepseek-v4 缓存命中率远低于同一 DeepSeek 官方 provider"，
    并在 CLI 0.33.0 修复，修复说明为 "dynamic prefix cache thrashing by relocating volatile dynamic context block"，
    官方称可省 2.9x–21x 成本。插件是自己拼请求体，可能没有继承这个"易变内容块位置"的修复。

请求

  1. 对比插件与 CLI ≥0.33.0 的请求体布局（尤其易变/动态内容落在哪个字段、哪个位置），确认是否会把前缀切开
  2. 考虑像 CLI 一样发送 promptCache / permissionMode
  3. 为请求体/响应元数据增加抓取开关（DSH_COMMANDCODE_TRACE 目前只抓响应流）；
    另外插件目前不持久化 provider 侧的 trace/generation ID（dsh 会话日志里 generationId /
    providerRequestId / x-trace-id / promptCacheHitTokens 均为 0 处），而官方 CLI 会把 traceIds
    写进 ~/.commandcode/projects/.meta.json。有 ID 服务端才能定位到具体请求。

补充说明（诚实起见）

本会话也存在"缓存热但依然慢"的步（1/4 命中 84.8% 仍耗时 27.8s、输出仅 92 token；1/14 命中 98.9% 耗时 36.7s），
所以这个 issue 主要针对"请求体构造是否触发前缀缓存失效"，并不声称解释了全部延迟。

复现方法

解压 ~/.dsh/sessions/**/session.v4.jsonl.zstd，逐条读取 assistant/message 事件里的 usage.cacheReadTokens / usage.inputTokens
（注意 inputTokens 是未缓存部分）。

Activity

  1. Mars-Sea commented on Sep 27, 2026

    @Mars-Sea
    Mars-Sea
    on Sep 27, 2026
    Owner

    已经更新0.11.17版本，你再试试看看还有没有问题

    dsh plugin --profile web add @mars-sea/dsh-commandcode-provider@0.11.17

  2. smartxm commented on Sep 27, 2026

    @smartxm
    smartxm
    on Sep 27, 2026
    Author

    我已经更新到了​@mars-sea/dsh-commandcode-provider@0.11.17+​@deepseek-ai/dsh@0.1.7-rc.2现在仍然复现，现在不是“回落到 0”，而是回落到一个固定前缀，今天中午看到更新以后我立刻又跑了一段长对话，总token24M，一口气跑完的，没有长时间中断，上下文用了242k,未命中1.7M，命中22M，下面是数据：
    161 次请求里 15 次命中量被卡在 66,432–66,688，其余全部正常。这 15 次是：

    本地时间 step 上一步 prompt 总长 cacheRead 被重新预填充 本步花费 相比命中多花
    12:02:29 46 115,995 66,688 49,307 $0.00876 $0.00725
    12:02:50 48 118,888 66,688 52,200 $0.00818 $0.00767
    12:03:07 49 119,221 66,688 52,533 $0.00863 $0.00772
    12:03:48 51 120,555 66,688 53,867 $0.00953 $0.00792
    12:05:11 55 124,622 66,688 57,934 $0.00943 $0.00852
    12:05:54 56 125,763 66,432 59,331 $0.00965 $0.00872
    12:15:36 78 162,096 66,688 95,408 $0.01507 $0.01402
    12:16:27 80 163,642 66,688 96,954 $0.01599 $0.01425
    12:23:46 94 182,107 66,688 115,419 $0.01844 $0.01697
    12:24:53 96 186,713 66,688 120,025 $0.02094 $0.01764
    12:38:25 115 210,013 66,688 143,325 $0.02186 $0.02107
    12:38:56 116 210,536 66,688 143,848 $0.02235 $0.02115
    12:49:59 143 227,190 66,688 160,502 $0.02458 $0.02359
    12:50:31 144 227,990 66,432 161,558 $0.02476 $0.02375
    12:54:00 149 233,293 66,688 166,605 $0.02569 $0.02449

    会话总计（非高峰价：未命中 $0.15/M、命中 $0.003/M、输出 $0.6/M）：

    • 未命中输入 1,779,216 tok / 命中 22,884,096 tok → 聚合命中率 92.79%（所以 UI 上只看到“93%”，很正常）
    • 这 1,779,216 未命中里 87% 来自上述 15 步
    • 正常 146 步平均命中 98.9%；这 15 步平均命中 39.3%
    • 会话总花费 $0.4144，其中 15 步占 $0.2439，纯多花 $0.2261（占全会话 54.6%）
    • 注意被重算的量随会话增长（4.9 万 → 16.7 万 tok），即越到后期来一张新图越贵

    关键线索：15/15 都发生在“上一步的工具结果新增一张图片”之后的下一个请求

    含图工具结果所在 step 下一步 下一步状态
    45 46 重算 49,307 tok
    47 48 重算 52,200 tok
    48 49 重算 52,533 tok
    50 51 重算 53,867 tok
    54 55 重算 57,934 tok
    55 56 重算 59,331 tok
    77 78 重算 95,408 tok
    79 80 重算 96,954 tok
    93 94 重算 115,419 tok
    95 96 重算 120,025 tok
    114 115 重算 143,325 tok
    115 116 重算 143,848 tok
    142 143 重算 160,502 tok
    143 144 重算 161,558 tok
    148 149 重算 166,605 tok
    • 全会话共 16 个“新增图片”的步骤，15 个后面立刻掉缓存，0 例外；反向也成立：没有任何一次掉缓存不是发生在图片新增之后。
    • 唯一例外是第一张图（step 24，11:51:57）：它之后只重算了 35 tok。而当时 prompt 总长 66,467→67,212 —— 恰好就是那个 66,432–66,688 的固定底。也就是说，此后每次掉缓存都退回到“第一张图之前”的边界，第一张图之后的所有上下文（图 + 文本 + 后续工具结果）全部按原价重算。
    • 掉缓存步的耗时也同步变长（约 30–39s vs 正常 23–28s），与“整段重新预填充”一致。

    但是：图片本身不是充分条件（反例）

    2026-09-20 有个会话，138 步，12:32–13:59，同样是 commandcode / deepseek-v4.1-flash）：新增 7 张图，掉缓存 0 次，聚合命中率 99.23%。

    两次的差别（供参考，可能是混淆因素）：

    • 插件版本：09-20 是 0.11.6，09-27 是 0.11.17；dsh 也从 0.1.6-alpha 升到 0.1.7-rc.2
    • 0.11.16 新增了 toolUpdate: 'addition-only' 能力（允许在既有会话中把新增工具投射进当前请求）—— 若某次请求的 tool 声明列表发生变化，值得怀疑；但本次掉缓存时命中量不是掉到 0 而是掉到 66k，且下一步立刻恢复，暂时无法只靠会话日志判定
    • 图片字节是否在不同请求间保持稳定：0.11.2 起图片按 route 目标重新编码下发（1568px 长边、≤1MiB）并由附件服务缓存复用；本次表现（“从第一张图处断前缀、下一步立即恢复”）与图片块字节在某次请求中发生变化高度吻合

    已排除的客户端因素

    • 161 次请求的 surfaceOp 全是 append，DSH 从未改写/压缩历史，前缀是纯追加
    • 161 次全部走同一条 cli 传输，没有中途 fallback 到 /provider/v1/chat/completions
    • 掉缓存步与“上一步工具输出体积”无关（反而偏小：中位数 688 vs 正常 1353 字符）
    • 与 agent/inbox/spliced（后台任务通知注入）的时间点对不上

    想问问你使用的时候出现过这种情况吗，我对这种情况没有任何头绪。

  3. Mars-Sea commented on Sep 28, 2026

    @Mars-Sea
    Mars-Sea
    on Sep 28, 2026
    Owner

    感谢补充数据。确认 0.11.17 仍有这个问题；我用合成图片真实调用 Command Code 服务端，也复现了新增图片后缓存回落。

    我已完成一个缓解方案：模型看过旧图并回复后，可选择在后续请求中不再重复发送旧图。它会影响模型回看旧图，因此默认关闭。这个改动会加入下一个版本；发布后我会在这里通知你测试。服务端缓存回落的根因仍未确认，issue 会保持打开。

  4. Mars-Sea commented on Sep 28, 2026

    @Mars-Sea
    Mars-Sea
    on Sep 28, 2026
    Owner

    补充一次官方 CLI 的真实调用结果：我用 command-code 1.66.0、deepseek/deepseek-v4.1-flash，在隔离会话中让 read_file 依次返回两张合成图片，中间加入长文本。第二张图片进入请求前，cacheReadTokens 为 55,040（总输入 55,431）；进入后降到 11,776（总输入 56,164）；下一轮纯文本恢复到 56,064（总输入 56,183）。本次会话记录里有两次含图工具结果，没有压缩记录。

    所以官方 CLI 在这个条件下也会出现同类缓存回落；这不是本插件独有的现象。但这次合成测试不能解释你那段 161 次请求的全部细节，也尚不能确认具体触发机制。你此前 CLI 1.65.2 的对照结果依然有效，说明并非每个会话都会触发。issue 继续保持打开，我会继续追查请求前缀与缓存行为。

  5. smartxm commented on Sep 28, 2026

    @smartxm
    smartxm
    on Sep 28, 2026
    Author

    收到。需要帮助请随时提出

  6. xiaijiangxue commented on Sep 30, 2026

    @xiaijiangxue
    xiaijiangxue
    on Sep 30, 2026

    我今天也出现这个问题了，版本：v0.12.0，不知道是不是上游的问题，最近command调整了模型的东西。

  7. GT-610 commented on Oct 16, 2026

    @GT-610
    GT-610
    on Oct 16, 2026
    Contributor

    按仓库源码核对了一下，供参考：

    0.12.0 加了 offloadSeenImagesForCache——模型看过某张图并回复后，后续请求用文字占位替代旧图，你描述的「新增图片后缓存回落」在实机 A/B 里因此消失。但它是默认关闭、且只在 CLI 传输生效，属于缓解而非修复。

    仍未解决：

    • 你怀疑的 CLI promptCache 请求字段没有采纳（permissionMode 在 0.12.2 补上了，x-taste-learning 也调过，但都不是这条根因）。
    • 根因始终没有确认。维护者用官方 CLI 1.66.0 也复现了同类回落（第二张图进入前 55,040 → 进入后 11,776，下一轮纯文本恢复到 56,064），所以这不一定是本插件独有的问题。
    • 你提到的请求体/响应元数据抓取开关、以及持久化 provider 侧 trace / generation ID，也没有落地。

    （我是普通用户，以上按仓库源码与 CHANGELOG 核对，没有真机实测。）

  8. GT-610 commented on Oct 16, 2026

    @GT-610
    GT-610
    on Oct 16, 2026
    Contributor

    更正我上一条回复里的一个错误，抱歉。

    我说「持久化 provider 侧 trace / generation ID 没有落地」，这是错的。经核实，v0.12.3 起适配器会把响应级标识通过 replayState.response 交给宿主，而 ReplayEnvelope.response 是持久化的（dsh-llm 类型里写明是「adapter-private metadata」，会随 assistant/message 的 source 一起落盘）。

    本机实测证据（解压 .dsh/sessions/**/session.v4.jsonl.zstd，注意是多帧 zstd，单帧解压只会拿到文件头）：

    "source":{"kind":"model","provider":"commandcode","model":"deepseek/deepseek-v4.1-flash",
 "replayState":{"response":{
   "protocol":"openai",
   "headers":{"x-trace-id":"0bce4d7c532206d60af706f3e185fd35"},
   "responseId":"45bf448f86339aa3af70dfb881274093"}}}

    所以现在能从会话日志里拿到 x-trace-id / responseId 了，你要的「有 ID 服务端才能定位到具体请求」这半条已经满足。抓取的是 x-request-id、request-id、x-trace-id、x-generation-id、traceparent 这些响应头（src/stream-response.ts）。

    仍然没落地的是：CLI promptCache 请求字段、你建议的请求体侧抓取开关（DSH_COMMANDCODE_TRACE 目前仍只抓响应流，请求侧只记结构计数与 SHA-256 指纹，不记正文）。

    再次为那条错误信息致歉——它是跨版本比对时把「当时没有」当成了「现在也没有」。

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

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions