diff --git a/components/offload/common.go b/components/offload/common.go index ec9ee13e..86460dc8 100644 --- a/components/offload/common.go +++ b/components/offload/common.go @@ -2,14 +2,43 @@ package offload import ( "math" + "os" "regexp" + "strconv" "strings" + "time" "unicode/utf8" bschemas "github.com/maximhq/bifrost/core/schemas" "github.com/rossoctl/context-guru/schema" ) +// resolveTimeoutEnv reads a per-call model-timeout budget from the environment, +// falling back to def when unset or unparseable. A bare number is seconds, so "180" +// works as well as "180s". +// +// Shared by the two NeedsModel components (extract_llm, summarize) because their +// budgets are the same KIND of knob — a client-side assumption about how long a +// loaded server takes to answer — and the parse rules must not drift between them: +// one accepting "180" while the other silently fell back to its default would be +// invisible in a run and would look like the component not firing. +func resolveTimeoutEnv(name string, def time.Duration) time.Duration { + v := strings.TrimSpace(os.Getenv(name)) + if v == "" { + return def + } + if n, err := strconv.Atoi(v); err == nil { + if n > 0 { + return time.Duration(n) * time.Second + } + return def + } + if d, err := time.ParseDuration(v); err == nil && d > 0 { + return d + } + return def +} + // resolveBudget converts an absolute token knob + an optional fraction-of-window // into an effective token count: the fraction (ceil(frac*window)) wins when set and // the window is known, else the absolute. Lets size knobs (collapse.max_tokens) diff --git a/components/offload/extract_llm.go b/components/offload/extract_llm.go index fd71dd71..21b670cd 100644 --- a/components/offload/extract_llm.go +++ b/components/offload/extract_llm.go @@ -6,7 +6,6 @@ import ( "log/slog" "os" "regexp" - "strconv" "strings" "sync" "sync/atomic" @@ -64,21 +63,7 @@ const defaultLLMCallTimeout = 90 * time.Second 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 + return resolveTimeoutEnv("CONTEXT_GURU_LLM_TIMEOUT", defaultLLMCallTimeout) } // Timeout/error counters. The fail-open path is CORRECT — compaction must never break diff --git a/components/offload/summarize.go b/components/offload/summarize.go index 0739fe72..a23615a3 100644 --- a/components/offload/summarize.go +++ b/components/offload/summarize.go @@ -3,7 +3,9 @@ package offload import ( "context" "encoding/json" + "errors" "strings" + "sync/atomic" "time" bschemas "github.com/maximhq/bifrost/core/schemas" @@ -15,10 +17,69 @@ import ( func init() { components.Register("summarize", newSummarize) } -// summarizeCallTimeout bounds the single summarizer call. It is higher than +// defaultSummarizeCallTimeout bounds the single summarizer call. It is higher than // extract's ceiling because summarize makes ONE call over a large span, and a // big trajectory legitimately takes the model longer to read and compress. -const summarizeCallTimeout = 150 * time.Second +// +// 150s was sized against an IDLE server. MEASURED on a 50-task SWE-bench arm there, +// this component spent 26,890,609 ms over 1,372 calls — a ~19.6s mean, so 150s was +// ~7.6x the mean and never binding. Two things make that headroom evaporate under +// load, and they ADD: +// +// - queue wait, which is what a loaded server actually charges: p50 17.2s / p95 +// 78.8s measured under KV pressure, before the model starts work at all; +// - this component's own prefill, which is large by construction — the same arm +// sent 78,155,276 input tokens across those 1,372 calls, i.e. ~57k prompt tokens +// per call (it summarizes the whole middle of the transcript). +// +// So the budget must cover queue + a 57k-token prefill + generation, and only the +// last of those three is what the idle-server mean measured. 300s is a CEILING, not +// a target: on an idle server nothing changes, because the call still returns in +// ~20s. +// +// ⚠️ Unlike extract_llm this is bounded ONCE for the whole component, not per call — +// s.summarize retries up to 3x against THIS SAME ctx (see the loop), so the total is +// this value, not 3x it. Raising it therefore raises the worst-case stall on ONE +// agent turn by exactly this much, and that stall is billed against the benchmark's +// own [agent] timeout_sec. +// +// CONTEXT_GURU_SUMMARIZE_TIMEOUT=300s (Go duration; bare integers are seconds) +const defaultSummarizeCallTimeout = 300 * time.Second + +// summarizeCallTimeout is resolved once at process start from the environment. +var summarizeCallTimeout = resolveSummarizeCallTimeout() + +func resolveSummarizeCallTimeout() time.Duration { + return resolveTimeoutEnv("CONTEXT_GURU_SUMMARIZE_TIMEOUT", defaultSummarizeCallTimeout) +} + +// Timeout/error counters, the summarize counterpart of extract_llm's llmTimeouts / +// llmErrors and served at /stats beside them. +// +// summarize's fail path is LOUDER than extract_llm's — it returns the error, the +// pipeline reverts the component, and that shows up as a per-component `reverted` +// count. But `reverted` cannot say WHY, and the two causes call for opposite +// responses: a blown deadline means the budget is too small for this load (the arm's +// savings are an undercount), while a model/transport error means the route is wrong +// (the arm is not measuring summarization at all). Separating them is the difference +// between "raise the ceiling" and "fix the -nothink route". +var ( + summarizeTimeouts int64 + summarizeErrors int64 +) + +// SummarizeTimeouts returns the number of summarize calls abandoned on the per-request +// deadline. Non-zero means CONTEXT_GURU_SUMMARIZE_TIMEOUT is too small for the current +// server load, and this arm compacted less than the method would on an idle server. +func SummarizeTimeouts() int64 { return atomic.LoadInt64(&summarizeTimeouts) } + +// SummarizeErrors returns non-timeout failures of summarize model calls (transport, +// HTTP status, empty/unparseable body, or a cancelled parent request). +func SummarizeErrors() int64 { return atomic.LoadInt64(&summarizeErrors) } + +// SummarizeCallTimeout exposes the resolved budget so /stats can report the +// configuration next to the counters (a timeout count is meaningless without it). +func SummarizeCallTimeout() time.Duration { return summarizeCallTimeout } // maxTrajectoryChars caps the trajectory text sent to the summarizer so a very // large span still fits the model's context window (≈70k tokens, well under a @@ -129,6 +190,14 @@ func (s *Summarize) Offload(req *bschemas.BifrostChatRequest, rep *components.Re defer cancel() summary, err := s.summarize(ctx, model, span, conversationGoal(req)) if err != nil { + // Classify before returning. Our own ctx is the reliable signal: the parent + // request may still be healthy while THIS component's budget expired, and the + // http client wraps the cause, so errors.Is walks to it. + if errors.Is(err, context.DeadlineExceeded) || errors.Is(ctx.Err(), context.DeadlineExceeded) { + atomic.AddInt64(&summarizeTimeouts, 1) + } else { + atomic.AddInt64(&summarizeErrors, 1) + } return nil, err // fail-open: the pipeline reverts this component } if strings.TrimSpace(summary) == "" { @@ -240,6 +309,12 @@ func (s *Summarize) summarize(ctx context.Context, model components.Model, span out, err := model.Complete(ctx, prompt) if err != nil { lastErr = err + // The three attempts share ONE deadline (the ctx is built by the caller, + // outside this loop), so once it has expired every retry fails instantly + // and only obscures the cause. Stop and report the deadline. + if ctx.Err() != nil { + break + } continue } return ensureSummaryTags(out), nil diff --git a/components/offload/summarize_timeout_test.go b/components/offload/summarize_timeout_test.go new file mode 100644 index 00000000..43bfdcf6 --- /dev/null +++ b/components/offload/summarize_timeout_test.go @@ -0,0 +1,145 @@ +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" +) + +// newSummarizeTestComponent builds summarize through its REGISTERED CONSTRUCTOR (same +// reason as newTimeoutTestComponent: the constructor is where defaults and the legacy +// start_from_message fold happen) with thresholds low enough that the fixture below +// clears every gate. Anything higher and the component SKIPS, which would make the +// timeout assertion vacuously pass. +func newSummarizeTestComponent(t *testing.T, model components.Model) *Summarize { + t.Helper() + c, err := newSummarize([]byte( + "keep_last: 1\nmin_tokens: 10\nresummarize_tokens: 0\n" + + "trigger:\n min_messages: 3\n min_request_tokens: 10\n")) + if err != nil { + t.Fatalf("newSummarize: %v", err) + } + s, ok := c.(*Summarize) + if !ok { + t.Fatalf("newSummarize returned %T, want *Summarize", c) + } + s.modelClient = model + s.mode = markerFull + return s +} + +// THE REGRESSION THIS GUARDS AGAINST +// +// summarize's budget was a hardcoded 150s sized against an IDLE server (measured ~19.6s +// mean per call there). Under load the same call must also absorb server-side queue wait +// (p50 17.2s / p95 78.8s under KV pressure) on top of a ~57k-token prefill, so the +// budget has to be raisable per run — and when it IS exceeded that has to be +// distinguishable from the component declining. +// +// Two halves of the contract: +// 1. no content is mutated (the caller can forward the original request), and +// 2. the abandoned call is COUNTED as a TIMEOUT, not as a generic error — the two +// mean opposite things ("budget too small for this load" vs "the cheap-model route +// is broken") and the per-component `reverted` count cannot tell them apart. +func TestSummarizeTimeoutIsCountedAndLeavesInputIntact(t *testing.T) { + timeoutsBefore := SummarizeTimeouts() + errorsBefore := SummarizeErrors() + + // A short budget keeps the test fast; the code path is identical at 300s. + t.Setenv("CONTEXT_GURU_SUMMARIZE_TIMEOUT", "150ms") + prev := summarizeCallTimeout + summarizeCallTimeout = resolveSummarizeCallTimeout() + defer func() { summarizeCallTimeout = prev }() + if summarizeCallTimeout != 150*time.Millisecond { + t.Fatalf("timeout override not applied: got %v", summarizeCallTimeout) + } + + model := &slowModel{} + s := newSummarizeTestComponent(t, model) + + span := strings.Repeat("ran pytest tests/test_handler.py, 3 failures in src/mod/file.py\n", 40) + req := &bschemas.BifrostChatRequest{ + Input: []bschemas.ChatMessage{ + userMsg("Fix the failing handler in src/mod/file.py and run the tests."), + toolResultMsg(span), + toolResultMsg(span), + userMsg("keep going"), + }, + } + before := len(req.Input) + + c := &components.Ctx{ + Session: "summarize-timeout-test", + Store: store.NewMemory(store.Options{}), + Ctx: context.Background(), + Model: components.ModelSpec{Static: model, Incoming: model}, + } + + rep := &components.Report{} + _, err := s.Offload(req, rep, c) + + // The model must actually have been called, or the test proves nothing: a component + // that skipped on a trigger/floor also leaves the messages alone. + if atomic.LoadInt64(&model.calls) == 0 { + t.Fatal("model was never called, so the timeout path was never exercised. " + + "Check the fixture clears trigger.min_messages / min_request_tokens and " + + "that the span is above min_tokens.") + } + if err == nil { + t.Fatal("Offload returned nil on a blown deadline; the pipeline needs the error " + + "to revert this component") + } + // The message list must be untouched: summarize is the one component that changes + // the message COUNT, so a partial rebuild on the error path would leave the caller + // holding a transcript with no summary in it. + if len(req.Input) != before { + t.Fatalf("req.Input rebuilt on the error path: %d messages, want %d", + len(req.Input), before) + } + + if got := SummarizeTimeouts() - timeoutsBefore; got != 1 { + t.Errorf("summarize_timeouts += %d, want 1 — an abandoned call must be visible "+ + "in /stats, or an arm that stops summarizing under load reads as an arm "+ + "that got faster", got) + } + if got := SummarizeErrors() - errorsBefore; got != 0 { + t.Errorf("summarize_errors += %d, want 0 — a deadline is not a transport error, "+ + "and conflating them hides which knob to reach for", got) + } +} + +// resolveTimeoutEnv is shared by both NeedsModel components, so its parse rules must +// hold identically for either name — a value accepted for one and silently ignored for +// the other is invisible in a run and looks like the component not firing. +func TestResolveTimeoutEnv(t *testing.T) { + const def = 300 * time.Second + for _, tc := range []struct { + name, val string + want time.Duration + }{ + {"unset", "", def}, + {"bare integer means seconds", "240", 240 * time.Second}, + {"go duration", "4m", 4 * time.Minute}, + {"whitespace tolerated", " 90s ", 90 * time.Second}, + {"zero falls back", "0", def}, + {"negative falls back", "-5", def}, + {"garbage falls back", "soon", def}, + } { + t.Run(tc.name, func(t *testing.T) { + t.Setenv("CG_TEST_TIMEOUT_KNOB", tc.val) + if tc.val == "" { + os.Unsetenv("CG_TEST_TIMEOUT_KNOB") + } + if got := resolveTimeoutEnv("CG_TEST_TIMEOUT_KNOB", def); got != tc.want { + t.Errorf("resolveTimeoutEnv(%q) = %v, want %v", tc.val, got, tc.want) + } + }) + } +} diff --git a/metrics/metrics.go b/metrics/metrics.go index a9f40419..a3bc4a30 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -465,6 +465,18 @@ type Snapshot struct { LLMTimeouts int64 `json:"llm_timeouts"` LLMErrors int64 `json:"llm_errors"` LLMCallTimeoutMs int64 `json:"llm_call_timeout_ms"` + // Summarize* are the same three figures for `summarize`, which owns a SEPARATE + // budget (its call is one big span, not one tool output, so the two cannot share a + // ceiling). Reported separately rather than folded into LLM* above because the + // components run in different arms: a summarize-only pipeline would otherwise + // report llm_timeouts 0 with its own deadline expiring on every request. + // + // summarize's failure is already visible as a per-component `reverted`, but that + // cannot distinguish "budget too small for this load" (savings are an undercount) + // from "the model call is failing" (the arm is not measuring summarization at all). + SummarizeTimeouts int64 `json:"summarize_timeouts"` + SummarizeErrors int64 `json:"summarize_errors"` + SummarizeCallTimeoutMs int64 `json:"summarize_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 7738c2db..d386a3f0 100644 --- a/proxy/proxy.go +++ b/proxy/proxy.go @@ -790,6 +790,12 @@ func (h *Handler) stats(w http.ResponseWriter, _ *http.Request) { snap.LLMTimeouts = offload.LLMTimeouts() snap.LLMErrors = offload.LLMErrors() snap.LLMCallTimeoutMs = offload.LLMCallTimeout().Milliseconds() + // summarize owns a separate budget (one call over a whole span, not one tool + // output), so it reports separately — folded together, a summarize-only pipeline + // would show llm_timeouts 0 while its own deadline expired on every request. + snap.SummarizeTimeouts = offload.SummarizeTimeouts() + snap.SummarizeErrors = offload.SummarizeErrors() + snap.SummarizeCallTimeoutMs = offload.SummarizeCallTimeout().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 47fed8c1..a16f53b6 100644 --- a/proxy/stats_golden_test.go +++ b/proxy/stats_golden_test.go @@ -64,6 +64,14 @@ var statsGoldenTopLevel = []string{ "sse_streamed", "sse_ttfb_ms_avg", "sse_ttfb_ms_avg_buffered", + // summarize_* are the same three figures for `summarize`, which owns a SEPARATE + // budget: its call covers the whole middle of the transcript (~57k prompt tokens + // measured) rather than one tool output, so the two components cannot share a + // ceiling — and a summarize-only pipeline reports llm_timeouts 0 however badly its + // own deadline is being hit. (collect.py parses these into cg_summarize_* fields.) + "summarize_call_timeout_ms", + "summarize_errors", + "summarize_timeouts", "sync_enforced", "tokens_after", "tokens_before",