From e78006e48f0ede5ed458b9e515e6179d15cc7566 Mon Sep 17 00:00:00 2001 From: Itay-Nakash Date: Tue, 11 Aug 2026 15:13:30 +0300 Subject: [PATCH] fix(extract_llm): size the per-call budget for a loaded server, and count the calls it abandons MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 15s per-call ceiling was a client-side assumption about server latency. On a shared on-prem vLLM under KV-cache pressure the server-side QUEUE WAIT alone was p50 17.2s / p95 78.8s, so the deadline expired before the model started on more than half of all calls. Measured across one 50-task SWE-bench arm at equal request volume: leg proxy requests llm_calls calls/request cg_added_ms_avg low (idle server) 2,513 2,093 0.83 5,530 high (KV-pressured) 2,387 255 0.11 8,563 8.2x fewer calls at 5% fewer requests while per-request overhead ROSE 55%: the component was starting calls, blocking, hitting the ceiling and discarding the work. Because it fails open silently, the arm degraded into a partial no-op that read as a 42-point latency IMPROVEMENT on every dashboard. So: - CONTEXT_GURU_LLM_TIMEOUT (Go duration; bare integers are seconds) now sets the budget, defaulting to 90s. Fail-open behaviour is unchanged; what changes is that a loaded server gets to answer. - llm_timeouts / llm_errors / llm_call_timeout_ms are served at /stats, merged by the host with the same layering as the Frozen* counters. A non-zero timeout count means this arm's savings are an UNDERCOUNT, not a measurement. The budget travels with the counts because a timeout total is meaningless without it. - The counters are recorded from ctx.Err(), INDEPENDENTLY of whether a result came back: RunExtractionSummary returns ("","","none") for every failure mode, and in `code` mode the deterministic fallback can still shrink an output whose LLM leg timed out. Counting only in an else-branch would therefore record nothing in exactly the case that matters. And one interaction with #28's economic gate, which is why this could not be a straight bump of the constant: a timed-out call with no result is no longer fed to the ratio tracker. Counting it as ratio 0 means "the model could not shrink this output", but a deadline is evidence about server latency, not compressibility. minRatioSampleTokens is 1500, so ONE timed-out medium output both ends that session's exploration and starts pulling ratio() below the 0.12 prior; a few more and evaluateGate suppresses every call. The tracker lives on the Pipeline for the proxy's lifetime, so nothing revises it — the self-justifying prior that extract_econ.go's exploration budget exists to prevent, re-entered through the timeout path. Timeouts still brake exploration via slowCallMs, which is the layer that decides BEFORE spending the wall clock. This is a live regime: 13 timeouts in one 50-task arm at the 90s budget on a KV-pressured TP=1 server. Tests pin both halves of the contract (fail-open preserved AND the abandoned call counted), the tracker guard, and the env parsing; each is built through newExtractLLM rather than a struct literal, so #28's per-session maps are initialized as in production. Verified the tracker test fails without the guard (total=715 of poisoned evidence from a single timeout). The three new /stats keys are registered in statsGoldenTopLevel. Assisted-By: Claude Opus 5 (1M context) Signed-off-by: Itay-Nakash --- components/offload/extract_llm.go | 132 +++++++- .../offload/extract_llm_timeout_test.go | 294 ++++++++++++++++++ metrics/metrics.go | 15 + proxy/proxy.go | 9 + proxy/stats_golden_test.go | 9 + 5 files changed, 453 insertions(+), 6 deletions(-) create mode 100644 components/offload/extract_llm_timeout_test.go diff --git a/components/offload/extract_llm.go b/components/offload/extract_llm.go index b277333..fd71dd7 100644 --- a/components/offload/extract_llm.go +++ b/components/offload/extract_llm.go @@ -2,11 +2,14 @@ package offload import ( "context" + "errors" "log/slog" "os" "regexp" + "strconv" "strings" "sync" + "sync/atomic" "time" bschemas "github.com/maximhq/bifrost/core/schemas" @@ -22,11 +25,85 @@ import ( // debugExtractLLM logs per-request candidate accounting when CONTEXT_GURU_DEBUG is set. var debugExtractLLM = os.Getenv("CONTEXT_GURU_DEBUG") != "" -// llmCallTimeout bounds a SINGLE in-request extract model call. Kept tight so a slow -// or rate-limited compaction model fails open FAST (leave the output verbatim this -// turn) instead of stalling the agent's request — synchronous compaction is on the -// hot path, so a long timeout here can push the agent's own request past its deadline. -const llmCallTimeout = 15 * time.Second +// llmCallTimeout bounds a SINGLE in-request extract model call. Kept bounded so a slow +// or rate-limited compaction model fails open (leave the output verbatim this turn) +// instead of stalling the agent's request — synchronous compaction is on the hot path, +// so an unbounded wait here could push the agent's own request past its deadline. +// +// 15s WAS TOO TIGHT ON A LOADED SELF-HOSTED SERVER, and the failure was invisible. +// MEASURED on an on-prem vLLM under KV-cache pressure: server-side queue wait alone was +// p50 17.2s / p95 78.8s, i.e. THE OLD CEILING EXPIRED BEFORE THE MODEL EVEN STARTED on +// more than half of all calls. Observed over one 50-task SWE-bench arm at equal request +// volume: +// +// leg proxy requests llm_calls calls/request cg_added_ms_avg +// low (idle server) 2,513 2,093 0.83 5,530 +// high (KV-pressured) 2,387 255 0.11 8,563 +// +// 8.2x fewer calls at 5% fewer requests, while per-request overhead ROSE 55% — the +// component was starting calls, blocking, hitting the ceiling, and discarding the work. +// Because it fails open silently, the arm degraded into a partial no-op that READ AS AN +// IMPROVEMENT on every dashboard (its "time penalty" shrank 42 points). +// +// The constant was a CLIENT-SIDE assumption about server latency. A hosted gateway +// answers in ~400ms; a shared on-prem GPU under load does not. So it is now configurable +// and defaults high enough that a *loaded* server still gets an answer: +// +// CONTEXT_GURU_LLM_TIMEOUT=90s (Go duration; bare integers are seconds) +// +// Tuning note: this is a per-call ceiling, not a target. Raising it trades "silently +// does nothing" for "measurably costs latency" — which is the correct trade, because the +// cost then SHOWS UP in the numbers instead of hiding. Watch `llm_timeouts` in /stats: a +// non-zero value means the budget is still too small for the server's current load. The +// economic gate's own latency brake (slowCallMs, extract_econ.go) is what stops +// speculative calls when the server is genuinely slow — that is the right layer for it, +// because it decides BEFORE spending the wall clock rather than after. +const defaultLLMCallTimeout = 90 * time.Second + +// llmCallTimeout is resolved once at process start from the environment. +var llmCallTimeout = resolveLLMCallTimeout() + +func resolveLLMCallTimeout() time.Duration { + v := strings.TrimSpace(os.Getenv("CONTEXT_GURU_LLM_TIMEOUT")) + if v == "" { + return defaultLLMCallTimeout + } + // Accept a bare number as seconds so "90" works as well as "90s". + if n, err := strconv.Atoi(v); err == nil { + if n > 0 { + return time.Duration(n) * time.Second + } + return defaultLLMCallTimeout + } + if d, err := time.ParseDuration(v); err == nil && d > 0 { + return d + } + return defaultLLMCallTimeout +} + +// Timeout/error counters. The fail-open path is CORRECT — compaction must never break +// the agent's request — but it must not be SILENT: an arm that quietly stops compacting +// looks like an arm that got faster. These are served at /stats (merged by the host, the +// same layering as FrozenStats) so `llm_calls` collapsing is visible as a timeout count +// rather than being mistaken for efficiency. +var ( + llmTimeouts int64 + llmErrors int64 +) + +// LLMTimeouts returns the number of extract_llm calls abandoned on the per-call +// deadline. Non-zero means CONTEXT_GURU_LLM_TIMEOUT is too small for the current +// server load, and any token-savings number from this arm is an UNDERCOUNT of what +// the pipeline would have done on an unloaded server. +func LLMTimeouts() int64 { return atomic.LoadInt64(&llmTimeouts) } + +// LLMErrors returns non-timeout failures of extract_llm model calls (transport, +// HTTP status, unparseable body, or a cancelled parent request). +func LLMErrors() int64 { return atomic.LoadInt64(&llmErrors) } + +// LLMCallTimeout exposes the resolved per-call budget so /stats can report the +// configuration next to the counters (a timeout count is meaningless without it). +func LLMCallTimeout() time.Duration { return llmCallTimeout } // llmConcurrency bounds how many of a request's candidate compactions run at once. // Independent per-output calls run concurrently so a turn's parallel tool outputs cost @@ -490,15 +567,58 @@ func (e *ExtractLLM) Offload(req *bschemas.BifrostChatRequest, rep *components.R start := time.Now() res, sum, _ := extract.RunExtractionSummary(ctx, cands[k].content, goal, keepIDs, before, extCfg, model) metrics.RecordExtractionCall(float64(time.Since(start).Milliseconds())) + // CLASSIFY THE SILENT FAILURE — and classify it INDEPENDENTLY of whether + // a result came back. RunExtractionSummary returns ("", "", "none") for every + // failure mode, so timeout / sandbox rejection / "nothing shrank" are + // indistinguishable in its return value. Our own ctx is the one reliable + // signal: if its deadline expired, THIS call was abandoned. + // + // Do NOT fold this into an `else` of the success check. In `code` mode the + // deterministic strategy runs as a fallback (extract.go:367-368), so a call + // whose LLM leg timed out can still return a smaller `res` — and an `else` + // would then record nothing. That is exactly the shape of the bug these + // counters exist to expose: the arm keeps compacting a little, so no + // dashboard looks broken while the expensive path has silently stopped. + // + // Fail-open behaviour is unchanged either way — this only records. + timedOut := errors.Is(ctx.Err(), context.DeadlineExceeded) + if ctx.Err() != nil { + if timedOut { + atomic.AddInt64(&llmTimeouts, 1) + } else { + atomic.AddInt64(&llmErrors, 1) + } + } if res != "" && res != cands[k].content { out[k] = outT{res, sum} // Feed the observed ratio so the gate prices future calls on what this // workload actually achieves, not on an assumption. e.ratios.observe(before-schema.TextTokens(res), before) metrics.RecordExtractionSaving(before - schema.TextTokens(res)) - } else { + } else if !timedOut { e.ratios.observe(0, before) // a miss is real evidence: ratio 0 } + // TIMED OUT WITH NOTHING BACK => DELIBERATELY NOT OBSERVED. A ratio-0 + // observation means "the model looked at this output and could not shrink + // it", which is real evidence about the workload. A deadline means the call + // never finished — evidence about SERVER LATENCY, not compressibility — and + // feeding it to the tracker makes the gate shut itself permanently on + // exactly the deployment where the budget is already too small: + // + // minRatioSampleTokens is 1500, so ONE timed-out medium output both ends + // this session's exploration (r.total >= the sample floor => exploring() + // returns false) and starts dragging ratio() down from the 0.12 prior. A + // few more and expectedRemoved falls below call cost for everything, so + // evaluateGate suppresses every call — and the tracker lives on the + // Pipeline for the proxy's LIFETIME, so nothing revises it afterwards. + // + // That is the self-justifying prior extract_econ.go's exploration budget + // exists to prevent, re-entered through the timeout path. MEASURED: 13 + // timeouts in one 50-task arm at the 90s budget on a KV-pressured TP=1 + // server, i.e. this is a live regime, not a hypothetical. Skipping the + // observation leaves the gate's estimate untouched; the timeouts are still + // counted (above) and still brake exploration via slowCallMs, which is the + // latency-aware layer that SHOULD react to a slow server. }(k) } wg.Wait() diff --git a/components/offload/extract_llm_timeout_test.go b/components/offload/extract_llm_timeout_test.go new file mode 100644 index 0000000..b8886ab --- /dev/null +++ b/components/offload/extract_llm_timeout_test.go @@ -0,0 +1,294 @@ +package offload + +import ( + "context" + "os" + "strings" + "sync/atomic" + "testing" + "time" + + bschemas "github.com/maximhq/bifrost/core/schemas" + "github.com/rossoctl/context-guru/components" + "github.com/rossoctl/context-guru/store" +) + +// slowModel blocks until its context is cancelled, i.e. it always exhausts whatever +// per-call deadline extract_llm imposes. That is the behaviour of a real compaction +// model queued behind a saturated GPU. +type slowModel struct{ calls int64 } + +func (m *slowModel) Complete(ctx context.Context, _ string) (string, error) { + atomic.AddInt64(&m.calls, 1) + <-ctx.Done() + return "", ctx.Err() +} + +func toolResultMsg(text string) bschemas.ChatMessage { + t := text + return bschemas.ChatMessage{ + Role: bschemas.ChatMessageRoleTool, + Content: &bschemas.ChatMessageContent{ContentStr: &t}, + } +} + +// A USER message is mandatory in the fixture: Offload derives its relevance +// `goal` from the first/last user turn (common.go:214) and returns early with +// rep.Skipped when `keywords(goal)` is empty. A request of only tool messages +// therefore never calls the model, and the timeout assertion would silently +// vacuously "pass" (it skipped) — which is how this test first fooled me. +func userMsg(text string) bschemas.ChatMessage { + t := text + return bschemas.ChatMessage{ + Role: bschemas.ChatMessageRoleUser, + Content: &bschemas.ChatMessageContent{ContentStr: &t}, + } +} + +// newTimeoutTestComponent builds the component through its REGISTERED CONSTRUCTOR and +// then injects the model client. +// +// Do not hand-roll `&ExtractLLM{...}` here. The struct carries maps that only +// newExtractLLM initializes (llmSeen, prevTokens), so a struct literal panics with +// "assignment to entry in nil map" the moment #28's per-session size tracking runs — +// which is how this test broke when it was rebased onto the economic-gate work. Going +// through the constructor also means a future field cannot silently leave this fixture +// in a shape production never has. +// +// `economic_gate: false` keeps the test about the DEADLINE: with the gate on, a +// suppressed call would leave the output verbatim too, so a gate change could make this +// test pass for the wrong reason. +func newTimeoutTestComponent(t *testing.T, model components.Model) *ExtractLLM { + t.Helper() + c, err := newExtractLLM([]byte("min_tokens: 1\nstrategy: code\neconomic_gate: false\n")) + if err != nil { + t.Fatalf("newExtractLLM: %v", err) + } + e, ok := c.(*ExtractLLM) + if !ok { + t.Fatalf("newExtractLLM returned %T, want *ExtractLLM", c) + } + e.modelClient = model + e.mode = markerFull + return e +} + +// THE REGRESSION THIS GUARDS AGAINST +// +// extract_llm wraps each model call in a per-call deadline and then DISCARDS the +// error (`res, sum, _ :=`), leaving the tool output verbatim. Failing open is +// correct — compaction must never break the agent's request — but it used to be +// SILENT, and that silence is what made a real measurement unreadable: +// +// On a KV-pressured on-prem vLLM (server-side queue wait p50 17.2s against a 15s +// budget) the component's llm_calls fell 2,093 -> 255 at equal request volume while +// per-request overhead ROSE 55%. The arm had partially switched itself off, and every +// dashboard read that as a 42-point latency IMPROVEMENT. +// +// So this asserts BOTH halves of the contract: +// 1. the tool output is unchanged (fail-open preserved), and +// 2. the abandoned call is COUNTED (llm_timeouts increments). +// +// If the ctx.Err() branch is ever "simplified" away, (1) still passes and only (2) +// catches it — which is exactly why (2) exists. +func TestExtractLLMTimeoutIsCountedAndFailsOpen(t *testing.T) { + timeoutsBefore := LLMTimeouts() + errorsBefore := LLMErrors() + + // A short budget keeps the test fast; the code path is identical at 90s. + t.Setenv("CONTEXT_GURU_LLM_TIMEOUT", "150ms") + prev := llmCallTimeout + llmCallTimeout = resolveLLMCallTimeout() + defer func() { llmCallTimeout = prev }() + if llmCallTimeout != 150*time.Millisecond { + t.Fatalf("timeout override not applied: got %v", llmCallTimeout) + } + + model := &slowModel{} + e := newTimeoutTestComponent(t, model) + + original := strings.Repeat("src/mod/file.py:12: def handler(request, context):\n", 200) + req := &bschemas.BifrostChatRequest{ + Input: []bschemas.ChatMessage{ + userMsg("Fix the failing handler in src/mod/file.py and run the tests."), + toolResultMsg(original), + }, + } + c := &components.Ctx{ + Session: "timeout-test", + Store: store.NewMemory(store.Options{}), + Ctx: context.Background(), + Model: components.ModelSpec{Static: model, Incoming: model}, + } + + rep := &components.Report{} + if _, err := e.Offload(req, rep, c); err != nil { + // Fail-open means the component must not surface an error either. + t.Fatalf("Offload returned an error on timeout; it must fail open: %v", err) + } + + // The model must actually have been called, or the test proves nothing: a + // component that declined for an unrelated reason also leaves the text alone. + if atomic.LoadInt64(&model.calls) == 0 { + t.Fatal("model was never called, so the timeout path was never exercised. " + + "Check that the fixture has a USER message (goal/keywords) and a tool " + + "output above the floor.") + } + + // (1) FAIL-OPEN: the request must remain VALID and no content may be lost + // irrecoverably. Note it need not be byte-identical: `code` mode falls back to + // the `deterministic` strategy when the LLM call dies (extract.go:229-234, + // AllowDeterministic), so a timed-out LLM call can still yield a smaller output + // via pure rules. That is correct behaviour — and it is also precisely why + // llm_calls collapsing under load was so hard to see: the arm keeps compacting a + // little, so nothing looks broken. + got := "" + if m := req.Input[1]; m.Content != nil && m.Content.ContentStr != nil { + got = *m.Content.ContentStr + } + if got == "" { + t.Fatal("tool output was emptied after a timed-out call; fail-open broken") + } + if len(got) < len(original) { + // Reversibility is the invariant that matters when content did shrink. + if !strings.Contains(got, "< %d) with NO <> marker: the original "+ + "is unrecoverable, which violates the reversibility invariant", + len(original), len(got)) + } + t.Logf("deterministic fallback shrank the output %d -> %d (marker present, "+ + "reversible) even though the LLM call timed out", len(original), len(got)) + } + + // (2) OBSERVABILITY: the abandoned call must be counted, not swallowed. + gotT := LLMTimeouts() - timeoutsBefore + gotE := LLMErrors() - errorsBefore + if gotT == 0 { + t.Fatalf("a deadline-exceeded call was NOT counted: llm_timeouts +%d, llm_errors +%d.\n"+ + "This is the silent fail-open regression: an arm that stops compacting under "+ + "load would again read as an efficiency win.", gotT, gotE) + } + t.Logf("counted correctly: llm_timeouts +%d, llm_errors +%d, model calls=%d, budget=%v", + gotT, gotE, atomic.LoadInt64(&model.calls), llmCallTimeout) +} + +// trackerState reads the ratio tracker's accumulators under its own lock. Safe to call +// after Offload returns: it wg.Wait()s its call goroutines before writing back. +func trackerState(r *ratioTracker) (removed, total int64) { + r.mu.Lock() + defer r.mu.Unlock() + return r.removed, r.total +} + +// A TIMEOUT IS NOT EVIDENCE ABOUT COMPRESSIBILITY. +// +// #28's gate learns this workload's compression ratio from outcomes, and counts a call +// that produced nothing as ratio 0 — correct when the MODEL looked at the output and +// could not shrink it. A call abandoned on the deadline never got that far: it says the +// server is slow, not that the content is incompressible. +// +// Feeding it in anyway makes the gate shut itself permanently on exactly the deployment +// whose budget is already too small, and minRatioSampleTokens (1500) makes that cheap: +// ONE timed-out medium output ends this session's exploration and starts pulling ratio() +// below the 0.12 prior, until evaluateGate suppresses everything. The tracker lives on +// the Pipeline for the proxy's lifetime, so nothing revises it afterwards — the +// self-justifying prior that extract_econ.go's exploration budget exists to prevent, +// re-entered through the timeout path. +// +// This is a live regime, not a hypothetical: 13 timeouts in one 50-task arm at the 90s +// budget on a KV-pressured TP=1 server. +func TestExtractLLMTimeoutDoesNotPoisonRatioTracker(t *testing.T) { + t.Setenv("CONTEXT_GURU_LLM_TIMEOUT", "150ms") + prev := llmCallTimeout + llmCallTimeout = resolveLLMCallTimeout() + defer func() { llmCallTimeout = prev }() + + timeoutsBefore := LLMTimeouts() + model := &slowModel{} + e := newTimeoutTestComponent(t, model) + + // Deliberately UNDER sampleChars (4000). The `code` strategy falls back to + // `deterministic`, which returns a relevance WINDOW of maxChars — on a larger body + // that window is smaller than the input, so the timed-out call still yields a result + // and the tracker is then observed legitimately (that is the other test's logged + // path). Keeping the body under the window size makes the fallback unable to shrink + // it, which is the only way to reach the "timed out with nothing back" branch. + original := strings.Repeat("src/mod/file.py:12: def handler(request, context):\n", 55) + req := &bschemas.BifrostChatRequest{ + Input: []bschemas.ChatMessage{ + userMsg("Fix the failing handler in src/mod/file.py and run the tests."), + toolResultMsg(original), + }, + } + c := &components.Ctx{ + Session: "ratio-poison-test", + Store: store.NewMemory(store.Options{}), + Ctx: context.Background(), + Model: components.ModelSpec{Static: model, Incoming: model}, + } + if _, err := e.Offload(req, &components.Report{}, c); err != nil { + t.Fatalf("Offload must fail open, got error: %v", err) + } + + // Guard against a vacuous pass three ways: the model must have been called, the + // deadline must have fired, and the fallback must NOT have produced a result (or we + // are in the legitimately-observed branch and prove nothing). + if atomic.LoadInt64(&model.calls) == 0 { + t.Fatal("model was never called; the timeout path was not exercised") + } + if got := LLMTimeouts() - timeoutsBefore; got == 0 { + t.Fatalf("expected the deadline to fire and be counted, got +%d", got) + } + got := "" + if m := req.Input[1]; m.Content != nil && m.Content.ContentStr != nil { + got = *m.Content.ContentStr + } + if got != original { + t.Skipf("the deterministic fallback shrank this body (%d -> %d), so the tracker "+ + "was observed legitimately; this case needs a body the fallback cannot "+ + "reduce (under sampleChars=%d)", len(original), len(got), 4000) + } + + removed, total := trackerState(&e.ratios) + if total != 0 || removed != 0 { + t.Fatalf("a timed-out call with NO result was fed to the ratio tracker "+ + "(removed=%d, total=%d, want 0/0).\nThat records 'this workload compresses "+ + "0%%' from a server-latency failure, which drives ratio() below the %.2f "+ + "prior and — past minRatioSampleTokens=%d — ends exploration for good. The "+ + "component then switches ITSELF off on the loaded server, silently, which is "+ + "the exact failure llm_timeouts exists to expose.", + removed, total, defaultCompressionRatio, minRatioSampleTokens) + } +} + +// The default must stay generous enough for a loaded self-hosted server, and the +// override must accept both "90s" and a bare "90". +func TestResolveLLMCallTimeout(t *testing.T) { + cases := []struct { + env string + want time.Duration + }{ + {"", defaultLLMCallTimeout}, + {"90s", 90 * time.Second}, + {"90", 90 * time.Second}, // bare integer = seconds + {"2m", 2 * time.Minute}, + {"garbage", defaultLLMCallTimeout}, + {"0", defaultLLMCallTimeout}, // zero would disable compaction entirely + {"-5s", defaultLLMCallTimeout}, + } + for _, tc := range cases { + if tc.env == "" { + os.Unsetenv("CONTEXT_GURU_LLM_TIMEOUT") + } else { + t.Setenv("CONTEXT_GURU_LLM_TIMEOUT", tc.env) + } + if got := resolveLLMCallTimeout(); got != tc.want { + t.Errorf("CONTEXT_GURU_LLM_TIMEOUT=%q: got %v, want %v", tc.env, got, tc.want) + } + } + // The 15s value that caused the measured failure must not become the default again. + if defaultLLMCallTimeout <= 15*time.Second { + t.Errorf("default budget %v is back at or below the 15s that silently "+ + "disabled the component under load", defaultLLMCallTimeout) + } +} diff --git a/metrics/metrics.go b/metrics/metrics.go index 4aa7eb8..a9f4041 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -450,6 +450,21 @@ type Snapshot struct { LLMCalls int64 `json:"llm_calls"` LLMInputTokens int64 `json:"llm_input_tokens"` LLMOutputTokens int64 `json:"llm_output_tokens"` + // LLMTimeouts/LLMErrors make the FAIL-OPEN PATH VISIBLE. A component that + // abandons its model call leaves the output verbatim (correct — compaction must + // never break the agent's request) but reports nothing, so an arm that quietly + // stops compacting under load looks like an arm that got faster. MEASURED on a + // KV-pressured on-prem server: llm_calls fell 2,093 -> 255 at equal request + // volume while per-request overhead ROSE 55%, and the resulting "42-point + // improvement" was the treatment partially switching itself off. + // + // Read them together with LLMCallTimeoutMs: a non-zero timeout count means the + // budget is too small for the server's current load, and this arm's savings are + // an UNDERCOUNT rather than a measurement. Filled by the host at serve time + // (offload owns the deadline and lives below metrics), same as the Frozen* fields. + LLMTimeouts int64 `json:"llm_timeouts"` + LLMErrors int64 `json:"llm_errors"` + LLMCallTimeoutMs int64 `json:"llm_call_timeout_ms"` // Extract is extract_llm's own economics (#28 part F), including NET savings after // its LLM cost — the honest headline for the one component that spends to save. // Purely ADDITIVE: no field above was renamed or removed, so deploy/harbor/*.py diff --git a/proxy/proxy.go b/proxy/proxy.go index 525e02a..7738c2d 100644 --- a/proxy/proxy.go +++ b/proxy/proxy.go @@ -781,6 +781,15 @@ func (h *Handler) stats(w http.ResponseWriter, _ *http.Request) { // Fill the CG components' own LLM cost (cheap-model usage) — kept out of the // metrics package (layering) and merged here at serve time. snap.LLMCalls, snap.LLMInputTokens, snap.LLMOutputTokens = cheapmodel.Usage() + // Same layering rationale: the deadline and its counters live in the component + // package, merged here rather than making `metrics` depend on `components/offload`. + // Without llm_timeouts, a run whose compaction model kept hitting its ceiling is + // indistinguishable from a run that had little to compact — the arm reads as fast + // because it silently stopped working. llm_call_timeout_ms travels with the counts + // because a timeout total is meaningless without the budget it was measured against. + snap.LLMTimeouts = offload.LLMTimeouts() + snap.LLMErrors = offload.LLMErrors() + snap.LLMCallTimeoutMs = offload.LLMCallTimeout().Milliseconds() // Freeze-replay health, same layering: the counters live with the code that owns // them (offload for the replay path, the store for dropped/repaired decisions). snap.FrozenHits, snap.FrozenMisses = offload.FrozenStats() diff --git a/proxy/stats_golden_test.go b/proxy/stats_golden_test.go index 4fe63cd..47fed8c 100644 --- a/proxy/stats_golden_test.go +++ b/proxy/stats_golden_test.go @@ -35,8 +35,17 @@ var statsGoldenTopLevel = []string{ "frozen_repaired", "frozen_tokens", "llm_calls", + // llm_call_timeout_ms / llm_errors / llm_timeouts make the compaction model's + // fail-open path countable. Without them an arm whose extract_llm kept hitting its + // per-call deadline is indistinguishable from an arm with little to compact — it + // reads as FASTER, because it silently stopped working. The budget travels with the + // counts because a timeout total means nothing without the ceiling it was measured + // against. (llmd_smoke's collect.py parses all three into cg_llm_* row fields.) + "llm_call_timeout_ms", + "llm_errors", "llm_input_tokens", "llm_output_tokens", + "llm_timeouts", "mode", "observe_hypothetical_requests",