Per-iteration Time stamp in the managed Developer message (index 1) defeats prompt caching — ~40× input-token amplification measured

[JoshuaBearup]

Summary

The agent loop re-renders the managed Developer message (index 1, ahead of all conversation history) on every iteration, and its # Environment section embeds a second-resolution timestamp:

// crates/norn/src/system_prompt/environment.rs (format_environment_section)
let _ = writeln!(
    out,
    "Time: {}",
    chrono::Utc::now().format("%Y-%m-%dT%H:%M:%SZ"),
);

Agent turns are seconds apart, so this line differs on every request. Because the managed Developer message sits at MANAGED_DEV_INDEX = 1 — "immediately after the System message at index 0, ahead of all persisted history" (crates/norn/src/loop/dev_context.rs) — the request prompt diverges from the provider's prefix cache at message[1] on every turn. The entire conversation history behind it (which grows to 150k+ tokens in long sessions) is re-tokenised and billed as uncached input on every single request.

This defeats norn's own caching design: the loop deliberately keeps the System message expansion-stable "so the instructions field stays stable for caching" (R5 comment in crates/norn/src/loop/runner.rs), and open_session wires the session id as prompt_cache_key (crates/norn/src/agent/builder.rs:445). The Time line one message later undoes both.

Refs are against f37f992.

Measured impact

From norn's own session logs (~/.norn/sessions/*.jsonl; every AssistantMessage records usage), across 147 sessions / 7,342 turns on two worker hosts over ~1 week (model gpt-5.5, OpenAI Responses API):

	input tokens	cache-hit rate	uncached
host A (108 sessions)	370,476,498	13%	322,855,634
host B (39 sessions)	184,069,846	14%	158,076,630
combined	554,546,344	~13%	480,932,264

Output tokens are 0.5% of input (2.8M combined) — the spend is almost entirely history re-send.

Signature trace (one 150-turn dev session, 40 min): input_tokens grows 19k → 163k per turn while cache_read_tokens sits frozen at exactly 15,488 the entire session — the static System+tools prefix is the only thing that ever cache-hits.

Counterfactual: with a stable prefix (only each turn's new delta uncached), the same work would have cost ~12.1M uncached tokens instead of ~481M — a ~40× input-token amplification.

Suggested fix

Any of (in increasing order of thoroughness):

1. Coarsen the timestamp to date-only (%Y-%m-%d) so the Developer message is stable within a session.
2. Render the environment/time once at session start and only re-sync the managed Developer message when its content (beyond time) actually changes.
3. Structural: keep per-iteration dynamic context out of the cacheable prefix — append it at the conversation tail (as the latest user-turn context) instead of mutating message[1], which is what the major agent CLIs do to keep prefix caching effective.

Note read_git_branch in the same section can also mutate mid-session (branch switches), but the per-second Time line is the one that changes every turn.

Verification

After the fix, a session's cache_read_tokens should grow with input_tokens (>80% of input by mid-session) instead of freezing at the static-prefix size.

[richardchen874-sys]

I like how concrete this is. Measuring a 40x input-token amplification makes the cost problem much easier to reason about than a generic “prompt caching is not working” report.

A practical fix is to keep volatile runtime metadata out of the stable prefix, or move it behind the cached section so the provider can reuse the long system/developer context. Then log cache-hit eligible tokens versus billed input tokens per iteration to verify the improvement.

If this is still active, is the main goal reducing billed tokens, improving latency, or making cache behavior visible per agent loop? I am testing an OpenAI-compatible multi-model API layer focused on official Chinese models, and cache behavior is one of the areas where real provider comparisons can be surprising.