Skip to content

feat(core): log why a step missed the prompt cache (debug) - #58801

Open
kitlangton wants to merge 4 commits into
devfrom
feat/prompt-cache-miss-log
Open

kitlangton wants to merge 4 commits into
devfrom
feat/prompt-cache-miss-log

Conversation

@kitlangton

@kitlangton kitlangton commented Oct 24, 2026 •

Copy link
Copy Markdown
Contributor

With debug logging on, the server now says why a step missed the prompt cache.
When a step suddenly re-sends the whole prompt instead of reading it from the provider's cache, there was no way to tell why. Set OPENCODE_LOG_LEVEL=DEBUG and each missed step logs one line naming the cause. Requests and caching behavior are unchanged, and nothing runs at other log levels.

message="prompt cache miss" sessionID=ses_… step=4 model=anthropic/claude-sonnet-4-5 missed=41210 read=2048 write=41210 reason=tools-changed detail="+mcp_linear_create -edit"
message="prompt cache miss" sessionID=ses_… step=1 model=anthropic/claude-sonnet-4-5 missed=58004 read=0 write=58004 reason=idle-ttl idle=7m12s

Reasons: model-switch, options-changed, tools-changed, instructions-changed, compaction, history-rewritten, idle-ttl, provider-eviction.

💡 Why
Cache misses are expensive and silent; knowing whether a tool change, an edit to history or just a long pause caused one tells you what to fix.

🆕 Now you can
Read the reason for each miss in the debug log: what changed, where (tool names, message index, role), and by how many tokens.

🚦 How it ships
Debug-only. Otherwise the per-step cost is one log-level check.

+ if (debug) print = fingerprint(request)      // hash per system part, tool, message; media by type and size
+ onUsage(tokens): miss = prevInput + read + write - read_now
+   if miss > 1024: log first difference in order model, options, tools, system, messages
+   else idle-ttl if gap > 5 min, else provider-eviction

A miss only counts above 1,024 tokens and once an earlier step showed cache activity, so providers without caching, and the first partial hit of implicit caches, stay quiet. State is the last step per session in memory, capped at 256 sessions. Logs hold tool names, indices, roles and counts, never prompt content.

📊 Numbers: per-step cost

Case Cost
Debug off ~0.3 µs
Debug on, 200 messages (400 KB) + 8 MB image 0.61 ms
Debug on, 600 messages (2.4 MB) + 8 MB image 2.37 ms

New fixture tests cover each reason, an image cut inside a tool result, a same-length edit, an implicit cache's first hit and media hashed by size. Runner tests check the line appears at Debug and not at Info.

👀 Read: cache-probe.ts, the miss arithmetic and the order differences are checked in. A wrong diagnosis only gives a misleading debug line. The rebase moved the probe's type imports to the @opencode/ai/effect entry. The rest is routine.

Related to #58459 · numbers from a local micro-benchmark

Checks run

After rebase onto current dev:

  • bun test test/session-cache-probe.test.ts test/session-runner.test.ts (packages/core): 256 pass
  • bun typecheck (packages/core): no errors

Added by the opencode bot (AI-generated).

Related: #58459

@opencode-agent opencode-agent Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The change looks sound to me. The probe only runs when debug logging is on, keeps a bounded amount of memory, and never affects requests. The miss count uses uncached input (nonCachedInputTokens) plus cache read and write, so cached tokens aren't counted twice. I read the diff and ran the cache-probe, runner and step tests (259 pass) and tsc -b (passes). I couldn't see the log line by running OpenCode from source because the simulated model doesn't report cache usage.

Public API: unchanged. The output is only an in-memory debug log line, using the existing OPENCODE_LOG_LEVEL.

One small inline comment about the hashing step dropping cache/metadata keys at any depth, which can produce a wrong diagnosis.

Related: #58459

// Cache hints only steer breakpoints and metadata never reaches the provider, so neither affects the cached prefix.
// Inline media is summarized by type and size so hashing stays fast; replacing or cutting it still changes the hash.
const replacer = (key: string, value: unknown) => {
if (key === "cache" || key === "metadata") return undefined

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The JSON replacer applies at every depth, so it also drops any property named cache or metadata inside tool inputSchemas, tool-call inputs and tool results. A tool whose schema has a metadata property changing (common in MCP tools), or an edited tool-call input containing metadata, would hash the same and be reported as provider-eviction. Would it work to strip these only on content parts and messages, for example by checking the parent object's shape or only stripping at the known levels?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed in fcb19ae: cache and metadata are now stripped only at message and content-part level, and a nested schema metadata change reports tools-changed (test added).

@opencode-agent opencode-agent Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The new commit addresses my earlier comment: cache and metadata are now removed only at the top level of each message and its content parts, so the same key names inside tool schemas, tool inputs and tool results count towards the hash again. The new test for a nested schema metadata change covers it. The cache-probe, runner and step tests pass (260) and tsc -b passes. Public API: unchanged. No new concerns.

At OPENCODE_LOG_LEVEL=DEBUG the runner fingerprints each primary request (model, options, tools, system, messages) and, when a step reads back over 1,024 fewer cached tokens than the previous step made cacheable, logs the first prefix segment that changed: model-switch, options-changed, tools-changed (+added -removed ~changed), instructions-changed, compaction, history-rewritten, idle-ttl or provider-eviction. Unchanged messages reuse the previous step's hashes. Above debug level nothing is fingerprinted.
@kitlangton
kitlangton force-pushed the feat/prompt-cache-miss-log branch from fcb19ae to f915523 Compare October 26, 2026 17:45

@opencode-agent opencode-agent Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The rebase onto dev and the new import commit look fine. range-diff shows the earlier commits unchanged apart from moving their imports to @opencode/ai/effect, and the probe still runs at debug level only, on the final prepared request. The cache-probe, runner and step tests pass (260) and tsc -b passes. Public API: unchanged. No new concerns.

This branch has not been deployed

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

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant