v3.12 — instrumentation (lot 1): make inference observable - #17
Merged
Conversation
A 400 from llama-server stringifies through requests as "400 Client
Error: Bad Request for url: ..." and nothing else. The body -- which
names the actual cause -- was dropped on the floor.
That is what made the malformed-grammar failure so expensive to
diagnose: llama-server rejected the GBNF on every completion, so every
step failed instantly, and the run finished in 16ms looking like a
fast one rather than a total failure. The answer ("error parsing
grammar: expecting newline or end at _call") was sitting in the
response body the whole time; it took reading llama-server's own log
by hand to find it.
Splits the post from the raise_for_status in all three providers so
the two cases stay distinguishable -- a request that never reached the
server has no body to report and must not grow an empty suffix -- and
adds providers.error_body() to format what the backend actually said.
Truncated at 500 bytes, and defensive by construction: a response with
no readable .text yields "" rather than turning an error report into a
second error.
Every backend already reports what a completion cost -- llama.cpp under tokens_evaluated/tokens_predicted, ollama under prompt_eval_count/eval_count, openrouter under usage -- and Forge parsed some of it (for the cache log) and then threw all of it away at the provider boundary, because call() returned a bare str. Providers now return Completion(text, usage). call_llm keeps returning a plain str, so the orchestrator contract and every caller are unchanged; the blast radius is exactly the seven provider-boundary tests, which is the point of having a single dispatch module. Usage fields are None-by-default rather than 0: a count the backend did not report and a count that was genuinely zero must not become indistinguishable once summed over a run, since that sum is what the token-based compaction threshold and the quota indicator will read. This is the primitive only -- nothing consumes the usage yet beyond the llm.response log line.
The Observable phase: usage now exists (previous patch) but nothing could see it, because the object that would hold it -- AgentState -- is unreachable from where a completion happens. compaction, the router and every graph node call call_llm directly, with no state in hand. Same answer as subtrace.py, for the same reason: a contextvar side channel rather than a wider contract that five modules depend on, and a contextvar rather than a module global so concurrent API requests do not sum into each other's totals. The lifecycle stays explicit -- orchestrator.run() opens the scope, call_llm records, trace reads -- and start_run() resets rather than creating-if-absent, without which every run after the first inherits the previous one's bill. The scope opens before _recall(), since recall can trigger compaction and that compaction call belongs to this run. Each trace record gains an "llm" block: calls, milliseconds, prompt and completion tokens, and the largest single prompt -- the total alone cannot tell one bloated prompt from ten small ones, which is exactly the question when deciding whether a run is expensive because the context grew or because it took many steps. !trace now shows inference time as a share of the run, which is what says whether a slow run is the model's fault or a tool's. Absent rather than zeroed when no scope was opened: a missing measurement must never read as a free run.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Base:
main@2a69db6. Branch:v3.12-instrumentation.577 tests green (baseline 560),
ruff checkclean, validated on realhardware before opening this PR.
Why
Forge could not answer "what did that run cost" about itself.
Every backend already reports token counts — llama.cpp under
tokens_evaluated/tokens_predicted, ollama underprompt_eval_count/eval_count, openrouter underusage. Forgeparsed some of them for the cache log and then discarded all of them
at the provider boundary, because
call()returned a barestr.Nothing downstream could see them.
Separately, a provider rejection surfaced as a bare HTTP status.
That is what made the malformed-grammar failure so expensive to
diagnose: llama-server rejected the GBNF on every completion, every
step failed instantly, and the run finished in 16ms looking like a
fast one rather than a total failure. The reason was sitting in the
response body the whole time.
This is the Observable phase and nothing else. The counts exist
and land in the trace; no consumer reads them yet. Jumping straight
to a compaction threshold or a quota indicator in the same PR would
be the 1 → 3 skip the architecture rule forbids.
What changed
fix(providers): report the backend's error body, not just the statusraise_for_status()stringifies to the status line and the URL; thebody is dropped. The
postis now split from theraise_for_statusin all three providers, so the two failure modes stay
distinguishable — a request that never reached the server has no body
to report and must not grow an empty suffix.
providers.error_body()formats what the backend actually said,truncated at 500 bytes, and is defensive by construction: a response
with no readable
.textyields""rather than turning an errorreport into a second error.
feat(providers): return a typedCompletioncarrying token usageProviders now return
Completion(text, usage).call_llm()keepsreturning a plain
str, so the orchestrator contract and everycaller are unchanged — the blast radius is exactly the seven
provider-boundary tests, which is what having a single dispatch
module is for.
Usagefields default toNone, never0. A count the backend didnot report and a count that was genuinely zero must not become
indistinguishable once summed over a run, since that sum is what a
compaction threshold and a quota indicator will eventually read.
feat(metrics): account for inference per run and put it in the traceThe problem here is reach, not measurement.
compaction, the routerand every graph node call
call_llmdirectly, with noAgentStatein hand and no way to thread one through without widening a contract
five modules depend on.
Same answer as
subtrace.py, for the same reason: a contextvar sidechannel rather than a wider contract, and a contextvar rather than a
module global so concurrent API requests do not sum into each other's
totals. The lifecycle is explicit —
orchestrator.run()opens thescope,
call_llmrecords,tracereads — andstart_run()resetsrather than creating-if-absent, without which every run after the
first inherits the previous one's bill.
The scope opens before
_recall(), since recall can triggercompaction and that compaction call belongs to this run.
Each trace record gains an
llmblock: calls, milliseconds, promptand completion tokens, and the largest single prompt. The total alone
cannot tell one bloated prompt from ten small ones, which is exactly
the question when deciding whether a run is expensive because the
context grew or because it took many steps.
!tracenow showsinference time as a share of the run.
The block is absent rather than zeroed when no scope was opened: a
missing measurement must never read as a free run.
Verified on real hardware
Two assumptions could not be proven from the test suite, and both
were checked against llama-server before merging.
Token semantics.
tokens_evaluatedmeasures prompt size, nottokens recomputed. Two identical calls with
cache_promptand apinned
id_slotboth report 36, whileprompt_msdrops from 2342msto 372ms. So
prompt_tokensandmax_prompt_tokensgenuinely mean"context size" and are usable as a compaction signal — had they been
incremental, a threshold built on them would have fired precisely
when the cache was working best.
Error bodies. An invalid grammar returns HTTP 400 with
{"error":{"code":400,"message":"Failed to initialize samplers: failed to parse grammar",...}}. The body carries the category butnot the offending rule; that detail stays in llama-server's own log.
Worth stating plainly, since this PR does not remove the need to read
that log for grammar work — it only removes the need to guess that
the grammar is the problem at all.
Trace output across five real runs. Per-run reset confirmed
(consecutive single-call runs stay at one call each, no accumulation)
and pre-deploy runs correctly carry
llm: nullrather than zeros.Sum and max diverge as intended on multi-step runs
(
prompt_tokens: 5059,max_prompt_tokens: 3925).What the numbers already say
A routing call costs roughly 3800–3980 prompt tokens and about 50
seconds, and inference accounts for 99–100% of wall-clock run time
(one run: 114 524ms total, 112 928ms of it in the model). Runtime is
therefore never tool-bound; it is bound by the constant floor of the
router prompt, paid in full at every step.
That reorders the next lot: shrinking what is constant in the router
prompt matters more than compacting history.
One measurement also contradicts a known open defect. The sysadmin
discovery step was assumed to bloat the prompt with 500+ units, but
the synthesis call weighs 1134 tokens against 3925 for routing. The
units are not reaching the prompt as assumed, and the planned
.servicefilter should be re-examined before it is written.Deliberately out of scope
call_llmreturns to its callers.cached_tokensis recorded but stays informational: it is not atrustworthy cache signal across llama.cpp builds and forks, and the
timing-based signal from v3.8 remains the one to read.
Known limits
milliseconds but no tokens. That is recorded honestly rather than
filled in with an estimate.
max_prompt_tokensis per-run, not per-conversation. Trackingcontext growth across turns needs the consumer that this PR
deliberately does not add.