一次 Ollama 工具调用缓存问题的排查

nanobot #4867 最初看起来已经解决了。

The-Markitecht 报告说，同一个 llama3.1:8b，直接通过 Ollama 调用很快；经过 nanobot 后，一轮对话却可能多花几十秒。日志中最明显的差别来自缓存：直接调用时，第二个请求能复用大部分 prompt；nanobot 的第二轮主请求只能复用四成左右。

我最初把原因定位到运行时上下文。时间、channel、sender 等临时信息会在下一轮重新生成，导致旧消息的前缀发生变化。#4891 修复了这部分逻辑；在我的复现中，缓存复用率从 14.2% 提高到 95.5%。到这里，问题似乎已经收束。

一周后，The-Markitecht 拉取包含修复的 main 再测，耗时和之前基本一样，第二轮主请求的命中率仍然只有约 42%。

这条反馈让我重新审视先前的结论。#4891 的对照实验足以说明它消除了一类前缀变化，却没有解释用户实际遇到的全部性能损耗。修复后仍然只有约 42% 的命中率，究竟是因为修复没有覆盖真实路径，还是同一份日志里还叠着另一个问题？

在另一台机器上复现约 42% 的命中率

测试环境如下：

• nanobot main，commit e3de01c9
• Ollama 0.32.1
• llama3.1:8b
• context window 16384
• OLLAMA_NUM_PARALLEL=1
• RTX 5090 32 GB

我先绕过 nanobot，直接向 Ollama 发送两个带有相同长前缀的请求。第二次 prompt evaluation 从 563.9 ms 降到 11.9 ms，说明 Ollama 的 KV cache 本身工作正常。

接着通过 nanobot CLI，在同一个 session 里依次发送：

answer 2+2
answer 4+7

两轮中，llama3.1:8b 都选择先调用 exec，再根据工具结果生成最终答案。Ollama 日志中的请求顺序如下：

44.06% 与 The-Markitecht 复测时看到的 42% 很接近。第二轮主请求需要重新计算 4752 tokens；RTX 5090 只用了约 390 ms，所以绝对延迟并不显眼，但换到 prompt evaluation 较慢的本地硬件上，这部分计算就可能拖到几十秒。

请求一长一短地交替，很容易让人想到 cache slot：工具调用后的短 prompt 占据当前 slot，下一轮的长请求因此只能从它开始复用。但这只能解释缓存为什么停在 3.7k tokens，不能解释短 prompt 本身从何而来。仅凭 task.n_tokens，也无法判断它究竟在哪一步变短。

JSON 变长，prompt 却变短

为了确认 nanobot 实际发出了什么，我打开 Ollama 的请求日志：

OLLAMA_DEBUG_LOG_REQUESTS=1

两次原始 HTTP 请求的结构分别是：

第一次：2 条 messages，19 个 tools，40109 个 JSON 字符
第二次：4 条 messages，19 个 tools，40363 个 JSON 字符

第二次多出的两条消息正是 assistant tool_call 和 tool result，两次工具定义序列化后的 SHA-256 也完全相同。OpenAI-compatible API 这一层没有丢历史，也没有替换工具定义；nanobot 发出的 messages 确实只增不减。

然而，Ollama 渲染给模型的 prompt 长度却是：

第一次：38415 字符
第二次：16064 字符

原始 JSON 增长了，最终 prompt 反而缩短一半以上。变化发生在 API 请求之后、模型推理之前，范围由此收窄到模型的 chat template。

工具定义在 chat template 中移动了

Ollama 当时为 llama3.1:8b 提供的模板里有这样一个判断：

{{- if and $.Tools $last }}
  ... render tool definitions ...
{{- end }}

这段逻辑位于 user message 分支。只有当前 user message 同时也是整个 messages 列表的最后一条时，模板才会展开完整的工具定义。

因此，同一段对话会被渲染成三种不同的 token 布局。

第一轮主请求的最后一条消息是 user：

system
工具定义
问题 2+2

模型调用工具后，最后一条消息变成 tool，先前的 user 不再是 $last，工具定义随之消失：

system
问题 2+2
assistant tool_call
tool result

下一轮用户消息到来，工具定义重新出现，但位置已经移到第二个问题之前：

system
上一轮消息与工具结果
上一轮最终回答
工具定义
问题 4+7

nanobot 的 JSON 始终保持 append-only，模型实际看到的 token 序列却没有简单追加：工具定义先出现，再消失，随后又在新位置出现。

KV cache 只能复用从开头连续一致的 token，无法从旧请求中拼接几个不连续的片段。工具定义的位置一旦发生分叉，后续状态就必须重新计算。这正好解释了第二轮主请求为什么只能命中约 3.7k tokens。

把工具定义固定在 system 中

为了验证模板是否正是主要损耗来源，我没有修改 nanobot，而是基于 llama3.1:8b 创建了一个新的 Ollama tag：只把 .Tools 移到固定的 system block 中，user 分支仍然只渲染用户内容。

原模板：tools 只在 user 为最后一条消息时展开
修改后：tools 始终在 system 中展开

新 tag 与原模型共享同一份 4.9 GB 权重，实际只增加了 2757 字节的模板和 manifest。随后，我用同一版本的 nanobot、相同的 context 和单 slot 配置重新跑了两轮。

结果如下。表格中的数字是“初始缓存 tokens / Prompt tokens”：

第二轮主请求的初始命中率从 44.22% 升到 99.82%，需要重新计算的 tokens 从 4752 降到 15。两套模板都实际调用了两次 exec，也都正确回答了 4 和 11。

这个 A/B 实验基本确认：在 llama3.1:8b、Ollama 0.32.1 和单 cache slot 这组配置中，剩余的大部分缓存损耗来自 chat template 对工具定义位置的处理。

完整的诊断步骤和 Modelfile 整理在 nanobot #4998 中。这份模板目前只验证了简单的 exec 工具回合，还不能直接当作所有 Ollama 模型的通用配置。

两处前缀变化，两次不同的修复

回到 #4867 ， 现在可以把缓存损耗拆成两个彼此独立的环节。

第一处在 nanobot。时间等临时信息会注入当前 user message，却没有按模型实际看到的形式持久化；下一轮重建历史时，旧前缀随之改变。#4891 修复了这个持久化问题，命中率从 14.2% 升到 95.5%，反映的正是这项改动带来的改善。

第二处在 llama3.1:8b 的 Ollama 模板。正常的 agent tool loop 会改变最后一条消息的角色，模板因此省略工具定义，或把它移到新的位置。issue 提交者更新后继续看到的约 42%，主要来自这里。

两组结果并不矛盾。#4891 消除了一处前缀变化；但在这个模型上，模板造成的重新计算仍然很大，足以掩盖前一项修复的收益。硬件性能决定重新计算 4752 tokens 需要 390 ms 还是几十秒，却不会改变缓存命中率本身。

日志能说明什么

这次排查中，最容易造成误判的是把 OpenAI-compatible API 里的 messages 等同于模型最终看到的 prompt。JSON 保持 append-only，只能证明 nanobot 没有删改消息；经过 chat template 后，token 序列仍可能完全变形。

同样，task.n_tokens 从 8k 降到 3k，只能说明渲染后的 prompt 变短，无法直接证明调用方删除了历史。排查这类问题时，需要把 API 请求、模板渲染结果和推理引擎的缓存日志分开观察。

Ollama 日志本身还有一个容易踩的坑：每个 new prompt 之后，紧接着的第一条 cached n_tokens 才代表初始命中；后面逐步增长的同名日志只是 prompt evaluation 的进度。

最终让判断落定的仍是对照实验：不改 nanobot，不换模型权重，只移动工具定义的位置，命中率就从 44.22% 升到 99.82%。这组结果把变量收窄到了模板。

这篇记录只覆盖 Ollama 0.32.1、llama3.1:8b、单 slot 和简单工具调用。其他模型的 tool-call 格式、多个并行工具、工具错误和长会话，仍需要分别验证。