diff --git a/dash/api.go b/dash/api.go index 0a3e2b07..3cc972af 100644 --- a/dash/api.go +++ b/dash/api.go @@ -10,6 +10,8 @@ import ( "strconv" "strings" "sync" + + "golang.org/x/sync/singleflight" "time" "github.com/rossoctl/context-guru/apply" @@ -49,27 +51,91 @@ type API struct { // its own 5 queries (Components, DecomposeComponentSavedUSD, EstimateComponentSavedUSD) // measured ~4.4s cold on a comparable corpus, uncached, on the dashboard's most-read tab. statsCache, facetsCache, componentsCache jsonCache + // toolsCache and toolFilterCache cover the Inventory tab's two aggregate reads. They are here + // for the same reason as the three above and were found the same way: both read over + // tool_declarations (2.18M rows) with no cache at all, and both returned 503 on 100% of + // requests to the default all-time view — /api/tools and /api/toolfilter each appear in the + // outage's nginx log. /api/prompt is deliberately NOT cached beside them; see routeBounds. + toolsCache, toolFilterCache jsonCache + // jsonInflight collapses concurrent COLD reads of the same cache key onto one computation. + // Keyed by the same principal-scoped cacheKey as the caches, so two tenants never share a + // computation and a manager never shares one with a tenant. + jsonInflight singleflight.Group } -// dashCacheTTL bounds how stale a cached /api/stats or /api/facets body may be. Short enough -// that a real change shows up almost immediately; long enough that a page's own auto-refresh, -// or a second tab open on the same window, does not each pay for a separate expensive read. -const dashCacheTTL = 5 * time.Second - -// dashHandlerTimeout bounds /api/stats, /api/facets and /api/components — the three DB-heaviest -// dashboard reads. The connection pool they share (dash/store.go) is now bounded, so a burst -// past it queues for a connection rather than growing unbounded — better than the OOM crash -// that replaced, but unbounded on its own: without this, a queued request hangs the caller -// indefinitely instead of returning. Matches Prometheus's own scrape_timeout, so a slow tab and -// a slow scrape fail the same way. +// dashCacheTTL bounds how fresh a cached /api/stats, /api/facets or /api/components body is before +// a request triggers a refresh. +// +// It was 5s, which was SHORTER THAN THE WORK IT CACHED and therefore cached almost nothing. On the +// production corpus Components() alone measures ~6s and the stats set ~5s, so an entry expired at +// or before the moment the next reader arrived: nearly every request was a miss and paid full +// price, and with no collapsing, nineteen readers meant nineteen concurrent multi-second scans +// competing for one connection pool — which is how a query that fits inside the 10s timeout on its +// own produced 503s all day. /metrics had the identical bug against its scrape interval +// (proxy/promexport.go); this is the same mistake in the same codebase, so it gets the same fix. +// +// 30s is chosen against the CLIENT's behaviour, not picked round: the dashboard's own auto-refresh +// defaults to 5 minutes and its SSE feed tells it when anything actually changed +// (dash/ui/app.js), so a rollup up to 30s old is well inside what the page already displays. The +// numbers here are aggregates over hours or a month; none of them turns on a single second. +const dashCacheTTL = 30 * time.Second + +// dashCacheStale is how far PAST the TTL a body may still be served while its replacement is being +// computed. Beyond it a reader waits for fresh numbers instead. +// +// The cap is what keeps stale-while-revalidate honest. Without one, a deployment that goes quiet +// serves the last body it ever built, indefinitely, and the page reports it as current — the +// dashboard's freshness line is stamped when the BROWSER fetched, so it cannot see server-side +// staleness. 30s past a 30s TTL bounds the worst case at one minute, which is smaller than the +// client's own refresh interval, so no reader can be shown anything older than they would have +// been shown anyway by not clicking refresh. +const dashCacheStale = 30 * time.Second + +// dashHandlerTimeout bounds every dashboard read except the four in unboundedRoutes. It used to +// bound three of them, named by hand at their route entries — see Mount, which now applies it by +// default, and unboundedRoutes for why the default is the safe direction. // -// This bounds the CALLER's wait, not the query itself: Overview() and Facets() run on plain -// d.sql.Query/QueryRow (context.Background()), so a canceled request context does not cancel -// the in-flight query or release its pooled connection early — the goroutine keeps running -// until the query finishes on its own. A caller gets a fast, honest timeout instead of hanging; -// backend pressure from a genuinely stuck query is not relieved by this alone. +// It bounds the QUERY as well as the caller's wait, which it did not before and which is the +// difference between an honest error and an outage. http.TimeoutHandler cancels the request +// context when it fires; reads now run under that context (a.db(r) -> WithContext -> readCtx, +// dash/store.go), so a caller who has given up takes their query and its pooled connection with +// them. Previously Overview() and Facets() ran on context.Background(): the caller got a fast 503 +// and the query kept going, so a browser retrying a failing load accumulated concurrent scans +// nobody was waiting for until the pool and the memory cap were both exhausted. That is the shape +// this constant now prevents rather than merely reports. +// +// Still matches Prometheus's own scrape_timeout, so a slow tab and a slow scrape fail alike. const dashHandlerTimeout = 10 * time.Second +// dashHeavyTimeout bounds the three cached aggregate reads — /api/stats, /api/facets and +// /api/components — which the default is simply too short for on a large database. +// +// The default's own comment used to justify 10s as "matches Prometheus's own scrape_timeout, so a +// slow tab and a slow scrape fail the same way". That was the wrong reason for these three: nothing +// scrapes them. Prometheus reads /metrics. Tying a HUMAN's page load to a scraper's patience is how +// /api/components came to fail 100% of the time on its default view — measured on the production +// database, the UNFILTERED all-time Components() aggregate takes 10.2-10.4s, so it crossed a bound +// set for an unrelated reason by a fraction of a second and returned 503 on every single request. +// +// The honest bound is what the CALLER can tolerate. This one is a person who has just clicked a tab +// showing every component over all history, and who is not helped by being told to try again. 45s is +// well inside nginx's 600s proxy_read_timeout, so the answer reaches them rather than dying in the +// hop. It is not a licence for slow queries: the same view is ~2.9s over 24 hours and ~7.5s over 7 +// days, the cache and its single-flight mean at most one reader per interval ever waits at all, and +// cg_metrics_render_seconds and the X-Cache header make the real cost visible instead of hidden +// behind a retry. +const dashHeavyTimeout = 45 * time.Second + +// dashComputeTimeout bounds the SHARED, detached computation behind serveJSON — the work itself +// rather than any one caller's wait for it. +// +// It has to exist and it has to be larger than the callers' bounds: the computation is deliberately +// not tied to a request (see serveJSON), so nothing else would ever stop it, and a read that hangs +// forever holds a pooled connection forever. Larger than dashHeavyTimeout because the point of +// detaching is that the work survives the reader who triggered it and lands in the cache for the +// next one; a bound below theirs would kill it just as it became useful. +const dashComputeTimeout = 2 * time.Minute + const dashTimeoutMsg = "dashboard query timed out; try again in a moment" // jsonCache is a short-TTL cache for one expensive, filter-keyed JSON response. Unlike @@ -96,6 +162,26 @@ func (c *jsonCache) get(key string) ([]byte, bool) { return e.body, true } +// load returns the entry whether or not it is still fresh, which get cannot express and +// stale-while-revalidate needs: the difference between "no body" and "a body worth serving while a +// better one is computed" is the difference between a reader waiting six seconds and not waiting. +// +// A body past dashCacheTTL+dashCacheStale is reported as absent, so the staleness cap is enforced +// here rather than trusted to each caller. +func (c *jsonCache) load(key string) (body []byte, fresh bool) { + c.mu.Lock() + defer c.mu.Unlock() + e, ok := c.entries[key] + if !ok { + return nil, false + } + age := time.Since(e.at) + if age >= dashCacheTTL+dashCacheStale { + return nil, false + } + return e.body, age < dashCacheTTL +} + func (c *jsonCache) set(key string, body []byte) { c.mu.Lock() defer c.mu.Unlock() @@ -111,6 +197,109 @@ func (c *jsonCache) set(key string, body []byte) { c.entries[key] = jsonCacheEntry{at: time.Now(), body: body} } +// serveCached writes a cached body if there is one, and labels every response either way. +// +// X-Cache exists because this cache is a masking layer over a real cost, and an unlabelled +// response makes that cost unmeasurable. /api/facets survived at ~1.5s per call precisely +// because the 5s TTL hid it: it is requested on every tab switch (app.js calls loadFacets() +// from every go() but setup/settings), so one miss followed by eleven hits reads as a fast +// endpoint. Any before/after taken through this API without knowing which side of the TTL each +// sample landed on can compare a miss against a hit and report the ratio as an optimisation -- +// measured on this corpus, /api/facets is 380ms on a miss and 2.4ms on a hit, a 158x difference +// that no code change produced. The header costs one line per response and makes the harness +// able to tell the two apart. +func serveCached(w http.ResponseWriter, c *jsonCache, key string) bool { + if body, ok := c.get(key); ok { + writeCachedJSON(w, body, "hit") + return true + } + w.Header().Set("X-Cache", "miss") + return false +} + +func writeCachedJSON(w http.ResponseWriter, body []byte, state string) { + w.Header().Set("Content-Type", "application/json") + w.Header().Set("X-Cache", state) + _, _ = w.Write(body) +} + +// serveJSON answers one expensive, cacheable dashboard read. +// +// Three cases, and only the third is allowed to cost the reader anything: +// +// - FRESH: serve it. X-Cache: hit. +// - STALE but inside dashCacheStale: serve it immediately and compute the replacement behind the +// response. X-Cache: stale. This is the case that was missing, and it is the common one — with +// a TTL shorter than the query, essentially every request landed here and was treated as cold. +// - COLD: compute, and collapse every concurrent request for the same key onto ONE computation. +// Without collapsing, N readers arriving together each ran the whole query; they then contended +// for the same pool and every one of them got slower, so the busiest moment was the slowest — +// the shape that turns a 6s query into a 10s timeout. +// +// compute is given its own *DB rather than closing over one, because the two cases need different +// lifetimes: a foreground computation must die with its caller, and a background refresh must NOT +// — r.Context() is already cancelled by the time the refresh runs, so a refresh bound to it would +// be killed instantly and the entry could never become fresh again. +func (a *API) serveJSON(w http.ResponseWriter, r *http.Request, c *jsonCache, key string, + compute func(db *DB) ([]byte, error)) { + if body, fresh := c.load(key); body != nil { + if fresh { + writeCachedJSON(w, body, "hit") + return + } + go a.refreshJSON(c, key, compute) + writeCachedJSON(w, body, "stale") + return + } + w.Header().Set("X-Cache", "miss") + // The shared computation is DETACHED from every caller, and that is deliberate rather than + // careless. Bound to the leader's r.Context() it inherits the leader's deadline and the leader's + // abandonment: when the leader timed out, compute failed with a cancelled context and + // singleflight handed that same error to every waiter — so one reader closing a tab failed the + // tab for everyone else, and the work already done was thrown away instead of being cached. + // That is the same "one caller's abandonment costs everyone" shape this whole change set exists + // to remove, and it would have been reintroduced here by the obvious code. + // + // Detaching it means the result is always cached even if nobody is left to receive it, so the + // next reader gets a hit rather than starting again. Each caller still gets its own deadline + // from the handler timeout, which is what bounds THEIR wait; this bounds the WORK. + v, err, _ := a.jsonInflight.Do(key, func() (any, error) { + ctx, cancel := context.WithTimeout(context.Background(), dashComputeTimeout) + defer cancel() + body, err := compute(a.rec.DB().WithContext(ctx)) + if err == nil { + c.set(key, body) + } + return body, err + }) + if err != nil { + httpErr(w, http.StatusInternalServerError, err.Error()) + return + } + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write(v.([]byte)) +} + +// refreshJSON recomputes one cache entry off the request path. +// +// Its context is detached and separately bounded: the request that triggered it has already been +// answered, so r.Context() is cancelled and inheriting it would cancel this immediately. The bound +// is generous rather than dashHandlerTimeout because nobody is waiting — the only thing that must +// not happen is a refresh living forever and holding a connection. +func (a *API) refreshJSON(c *jsonCache, key string, compute func(db *DB) ([]byte, error)) { + ctx, cancel := context.WithTimeout(context.Background(), dashComputeTimeout) + defer cancel() + body, err := compute(a.rec.DB().WithContext(ctx)) + if err != nil { + // Keep the stale entry: it is still servable and still inside its cap. Dropping it would + // turn a transient failure into a cold miss for the next reader, which is strictly worse. + slog.Warn("context-guru: dashboard cache refresh failed; serving the previous body until it expires", + "err", err) + return + } + c.set(key, body) +} + // cacheKey scopes a cache entry to the actual caller, not just the URL: a manager and a // tenant hitting the same query string must never share a cached body. // @@ -307,15 +496,15 @@ func (a *API) routes() []route { http.Redirect(w, r, "/dashboard/", http.StatusMovedPermanently) }}, {"GET /dashboard/", scopePublic, http.StripPrefix("/dashboard/", uiHandler()).ServeHTTP}, - {"GET /api/stats", scopeTenant, http.TimeoutHandler(http.HandlerFunc(a.stats), dashHandlerTimeout, dashTimeoutMsg).ServeHTTP}, + {"GET /api/stats", scopeTenant, a.stats}, {"GET /api/series", scopeTenant, a.series}, {"GET /api/requests", scopeTenant, a.requests}, {"GET /api/requests/{id}", scopeTenant, a.request}, {"GET /api/sessions", scopeTenant, a.sessions}, {"GET /api/sessions/{session}/transcript", scopeTenant, a.sessionTranscript}, - {"GET /api/components", scopeTenant, http.TimeoutHandler(http.HandlerFunc(a.components), dashHandlerTimeout, dashTimeoutMsg).ServeHTTP}, + {"GET /api/components", scopeTenant, a.components}, {"GET /api/breakdown", scopeTenant, a.breakdown}, - {"GET /api/facets", scopeTenant, http.TimeoutHandler(http.HandlerFunc(a.facets), dashHandlerTimeout, dashTimeoutMsg).ServeHTTP}, + {"GET /api/facets", scopeTenant, a.facets}, {"GET /api/config", scopeManager, a.config}, {"GET /api/benchmarks", scopeManager, a.benchmarks}, {"GET /api/benchmarks/{id}/tasks", scopeManager, a.benchmarkTasks}, @@ -344,8 +533,63 @@ func (a *API) routes() []route { // (typically "/dashboard" for the UI and "/api" for the data). func (a *API) Mount(m *http.ServeMux) { for _, rt := range a.routes() { - m.HandleFunc(rt.pattern, rt.h) + h := rt.h + if d := routeBound(rt.pattern); d > 0 { + h = http.TimeoutHandler(h, d, dashTimeoutMsg).ServeHTTP + } + m.HandleFunc(rt.pattern, h) + } +} + +// routeBounds overrides the default handler timeout for particular routes. 0 means NO timeout. +// +// The default is applied to every route by Mount and this map is the only way out, which is the +// whole point: dashHandlerTimeout used to be attached to three routes by hand, so every route added +// after it silently had none. /api/series and /api/capture were two of those, and in the outage this +// fixes they were the endpoints that hung longest — 4,049 and 3,549 gateway timeouts in a single +// day, because nothing in the process ever gave up. A route is now bounded whether or not its author +// thought about it. +// +// Two reasons to appear here, and they are different: +// +// - 0, UNBOUNDED. Either the response is STREAMED — http.TimeoutHandler buffers the whole body +// before writing, so wrapping an SSE feed would withhold every event and then discard them all +// — or the read crosses the NETWORK to cold storage under its own explicit, longer timeout. The +// static UI is here for neither reason: it touches no database, and buffering an embedded asset +// only to time it is pure overhead. +// - LONGER, for the three cached aggregate reads. See dashHeavyTimeout. +var routeBounds = map[string]time.Duration{ + "GET /api/events": 0, // SSE: a buffered stream is not a stream + "GET /api/archive/{session}": 0, // rclone fetch, own 60s bound + "GET /api/sessions/{session}/transcript": 0, // reaches cold storage + "GET /dashboard/": 0, // embedded assets, no DB + "GET /api/stats": dashHeavyTimeout, + "GET /api/facets": dashHeavyTimeout, + "GET /api/components": dashHeavyTimeout, + // The Inventory tab's reads, all three over tool_declarations (2.18M rows). Measured on the + // production database through the real handlers, unfiltered all-time: every one exceeded the + // 10s default, so all three returned 503 on 100% of requests to that tab's default view. + // /api/tools and /api/toolfilter both appear in the outage's nginx log; /api/prompt escaped it + // only because nobody opened that view while it was being recorded. + "GET /api/tools": dashHeavyTimeout, + "GET /api/toolfilter": dashHeavyTimeout, + // /api/prompt gets the longer bound but NOT a response cache, and the asymmetry is deliberate. + // It serves prompt CONTENT — a user's own system prompt and CLAUDE.md text — behind a gate that + // depends on the caller's ADDRESS (a.trusted, a CIDR check in single-tenant mode), not only on + // its principal. cacheKey scopes by principal, so a body built for a trusted caller could be + // handed to an untrusted one on the same account. Caching it correctly means keying on + // trustedness too; that is a change to a content gate and does not belong in an outage fix, so + // it waits, and meanwhile it simply gets long enough to finish. + "GET /api/prompt": dashHeavyTimeout, +} + +// routeBound is the timeout Mount applies to one route: its override if it has one, otherwise the +// default. Written as a function so an absent key and an explicit 0 stay distinguishable. +func routeBound(pattern string) time.Duration { + if d, ok := routeBounds[pattern]; ok { + return d } + return dashHandlerTimeout } // requireManager gates a route serving server-wide or process-wide facts. @@ -440,7 +684,7 @@ func (a *API) sessionTranscript(w http.ResponseWriter, r *http.Request) { limit = min(n, transcriptPageMax) } } - tp, err := a.rec.DB().SessionEventsPage(f, session, visible, r.URL.Query().Get("after"), limit) + tp, err := a.db(r).SessionEventsPage(f, session, visible, r.URL.Query().Get("after"), limit) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -462,7 +706,7 @@ func (a *API) sessionTranscript(w http.ResponseWriter, r *http.Request) { evs, f.Tenant, f.TenantAll = keep, owner, false } var arch *ArchivedSession - if meta, mErr := a.rec.DB().ArchivedSessionByID(session); mErr == nil { + if meta, mErr := a.db(r).ArchivedSessionByID(session); mErr == nil { // Ownership again: the index is keyed by an id a caller could guess, and this // row is the thing that says "there is something to fetch". if a.auth == nil || f.TenantAll || meta.TenantID == f.Tenant { @@ -574,7 +818,7 @@ func (a *API) archive(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - rows, err := a.rec.DB().ArchivedSessions(f, atoiDefault(r.URL.Query().Get("limit"), 100)) + rows, err := a.db(r).ArchivedSessions(f, atoiDefault(r.URL.Query().Get("limit"), 100)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -605,7 +849,7 @@ func (a *API) archivedSession(w http.ResponseWriter, r *http.Request) { return } session := r.PathValue("session") - meta, err := a.rec.DB().ArchivedSessionByID(session) + meta, err := a.db(r).ArchivedSessionByID(session) if err != nil { httpErr(w, http.StatusNotFound, "no such archived session") return @@ -656,6 +900,21 @@ func (a *API) events(w http.ResponseWriter, r *http.Request) { a.rec.Hub().ServeScoped(w, r, f.Tenant, f.TenantAll) } +// db is the store handle every read handler must use, rather than a.rec.DB() directly. +// +// It binds the read to the REQUEST's context, so work the caller has abandoned stops instead of +// running to completion on a pooled connection nobody is waiting for. That mattered here: the +// dashboard's own refresh timer re-issued a failing load every 5s, and because reads were +// uncancellable each retry occupied a connection and its allocations until it finished on its +// own — a pileup that pinned the process at its memory cap and made every subsequent query +// slower, which produced more retries. WithContext already existed for the KV-cache routes +// (dash/store.go) and was simply never wired to the rest. +// +// It is a method taking r, not a field, because the context is per-request; and reads go through +// this ONE accessor so a new handler cannot quietly reintroduce the uncancellable shape. Writes +// are deliberately NOT routed here — a write must complete even if the caller has gone. +func (a *API) db(r *http.Request) *DB { return a.rec.DB().WithContext(r.Context()) } + // trusted reports whether a request may see per-request CONTENT and the effective // configuration. Loopback always may; otherwise the peer must be in a configured // trusted CIDR. Aggregates are deliberately NOT gated — a proxy bound to 0.0.0.0 @@ -753,104 +1012,92 @@ func (a *API) stats(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - key := cacheKey(p, r) - if body, ok := a.statsCache.get(key); ok { - w.Header().Set("Content-Type", "application/json") - w.Write(body) - return - } - // The four calls below are independent of each other — none reads another's result, only - // this handler's own fields afterward do — so they run concurrently rather than one after - // another. Sequentially, on a production-sized DB, Overview() alone measured ~5-10s (see its - // own errgroup for why) and DeclCreditFor another ~4-16s (see SelfRemovals' own comment for - // why it was rewritten), which summed past this handler's 10s caller-facing timeout on every - // call. Run concurrently, wall time drops to roughly the slowest of the four rather than - // their sum. - var ( - o *Overview - overviewErr error - cachesplitHist *CachesplitHistorical - tierCosts *TierCosts - declCredit *DeclCredit - ) - var g errgroup.Group - g.Go(func() error { - var err error - o, err = a.rec.DB().Overview(f) - overviewErr = err - return nil // Overview's own error is reported below, not folded into the group's error: - // a pricing failure in one of the other three must not mask it, and it must not mask them. - }) - // Best-effort, and omitted rather than zeroed when it cannot be computed: a figure the - // dashboard cannot value must read as absent, never as "saved nothing". - if a.pricer != nil { + a.serveJSON(w, r, &a.statsCache, cacheKey(p, r), func(db *DB) ([]byte, error) { + // The four calls below are independent of each other — none reads another's result, only + // this handler's own fields afterward do — so they run concurrently rather than one after + // another. Sequentially, on a production-sized DB, Overview() alone measured ~5-10s (see its + // own errgroup for why) and DeclCreditFor another ~4-16s (see SelfRemovals' own comment for + // why it was rewritten), which summed past this handler's 10s caller-facing timeout on every + // call. Run concurrently, wall time drops to roughly the slowest of the four rather than + // their sum. + var ( + o *Overview + overviewErr error + cachesplitHist *CachesplitHistorical + tierCosts *TierCosts + declCredit *DeclCredit + ) + var g errgroup.Group g.Go(func() error { - if h, err := a.rec.DB().CachesplitHistoricalUSD(f, a.pricer); err == nil { - cachesplitHist = &h - } - return nil + var err error + o, err = db.Overview(f) + overviewErr = err + return nil // Overview's own error is reported below, not folded into the group's error: + // a pricing failure in one of the other three must not mask it, and it must not mask them. }) - // The bill split by tier, and with it the addressable share and the safety panel's - // benefit half. Same rule: absent when it cannot be priced, never a zeroed bill. + // Best-effort, and omitted rather than zeroed when it cannot be computed: a figure the + // dashboard cannot value must read as absent, never as "saved nothing". + if a.pricer != nil { + g.Go(func() error { + if h, err := db.CachesplitHistoricalUSD(f, a.pricer); err == nil { + cachesplitHist = &h + } + return nil + }) + // The bill split by tier, and with it the addressable share and the safety panel's + // benefit half. Same rule: absent when it cannot be priced, never a zeroed bill. + g.Go(func() error { + if t, err := db.TierCosts(f, a.pricer); err == nil { + tierCosts = t + } + return nil + }) + } + // The declarations no longer sent, both halves. Needs no pricer for the token counts, so it + // runs outside the block above; best-effort and non-fatal, because it is an addition to the + // walk and a deployment where it fails should still get the walk. NEVER silent, though: an + // error swallowed here returns zeros, and a zero in a savings figure is a claim. g.Go(func() error { - if t, err := a.rec.DB().TierCosts(f, a.pricer); err == nil { - tierCosts = t + c, err := db.DeclCreditFor(f, a.priceFn(r), a.toolFilterStateForScope(f).Removed) + if err != nil { + slog.Warn("dash: declaration-removal credit unavailable", "err", err) + return nil } + declCredit = c return nil }) - } - // The declarations no longer sent, both halves. Needs no pricer for the token counts, so it - // runs outside the block above; best-effort and non-fatal, because it is an addition to the - // walk and a deployment where it fails should still get the walk. NEVER silent, though: an - // error swallowed here returns zeros, and a zero in a savings figure is a claim. - g.Go(func() error { - c, err := a.rec.DB().DeclCreditFor(f, a.priceFn(r), a.toolFilterStateForScope(f).Removed) - if err != nil { - slog.Warn("dash: declaration-removal credit unavailable", "err", err) - return nil + g.Wait() //nolint:errcheck // every goroutine above always returns nil; see each one's own error handling + if overviewErr != nil { + return nil, overviewErr + } + if cachesplitHist != nil { + o.CachesplitHistorical = cachesplitHist + // Folded into the running total here, not inside Overview() itself, because + // pricing it needs a.pricer — Overview() returns before this figure exists, the + // same reason DeclCreditFor's addition below happens out here too. Leaving it out + // was the actual inconsistency, not a deliberate scoping choice: the page's own + // "Prefix-cache savings" tile (dash/ui/app.js) already adds CachesplitSavedUSD and + // this historical figure together and calls the sum ours — the headline total + // should agree with the tile two inches to its right, not exclude half of it. + o.TotalSavedUSD += cachesplitHist.USD + } + if tierCosts != nil { + o.SetTiers(tierCosts) + } + if declCredit != nil { + o.SetDeclCredit(declCredit) } - declCredit = c - return nil + // Rebuilt here, not left as Overview()'s own snapshot: o.Waterfall was materialized + // before any of the priced additions above existed, so its "declarations no longer + // sent" step baked in a zero (SetDeclCredit had not run yet) and its own "total_saved" + // step baked in a total short by both the historical split figure and the decl-filter + // credit — silently disagreeing with the headline tile two inches above it, which reads + // o.TotalSavedUSD directly rather than through the waterfall. waterfall() only reads + // current field values, so calling it again here is exactly as correct as the first + // call and now sees everything this handler has since added. + o.Waterfall = o.waterfall() + return json.Marshal(o) }) - g.Wait() //nolint:errcheck // every goroutine above always returns nil; see each one's own error handling - if overviewErr != nil { - httpErr(w, http.StatusInternalServerError, overviewErr.Error()) - return - } - if cachesplitHist != nil { - o.CachesplitHistorical = cachesplitHist - // Folded into the running total here, not inside Overview() itself, because - // pricing it needs a.pricer — Overview() returns before this figure exists, the - // same reason DeclCreditFor's addition below happens out here too. Leaving it out - // was the actual inconsistency, not a deliberate scoping choice: the page's own - // "Prefix-cache savings" tile (dash/ui/app.js) already adds CachesplitSavedUSD and - // this historical figure together and calls the sum ours — the headline total - // should agree with the tile two inches to its right, not exclude half of it. - o.TotalSavedUSD += cachesplitHist.USD - } - if tierCosts != nil { - o.SetTiers(tierCosts) - } - if declCredit != nil { - o.SetDeclCredit(declCredit) - } - // Rebuilt here, not left as Overview()'s own snapshot: o.Waterfall was materialized - // before any of the priced additions above existed, so its "declarations no longer - // sent" step baked in a zero (SetDeclCredit had not run yet) and its own "total_saved" - // step baked in a total short by both the historical split figure and the decl-filter - // credit — silently disagreeing with the headline tile two inches above it, which reads - // o.TotalSavedUSD directly rather than through the waterfall. waterfall() only reads - // current field values, so calling it again here is exactly as correct as the first - // call and now sees everything this handler has since added. - o.Waterfall = o.waterfall() - body, err := json.Marshal(o) - if err != nil { - httpErr(w, http.StatusInternalServerError, err.Error()) - return - } - a.statsCache.set(key, body) - w.Header().Set("Content-Type", "application/json") - w.Write(body) } func (a *API) series(w http.ResponseWriter, r *http.Request) { @@ -860,7 +1107,7 @@ func (a *API) series(w http.ResponseWriter, r *http.Request) { return } bucket := atoi64(r.URL.Query().Get("bucket")) - b, err := a.rec.DB().Series(f, bucket) + b, err := a.db(r).Series(f, bucket) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -875,7 +1122,7 @@ func (a *API) requests(w http.ResponseWriter, r *http.Request) { return } q := r.URL.Query() - p, err := a.rec.DB().Requests(f, atoi64(q.Get("before")), atoiDefault(q.Get("limit"), 50)) + p, err := a.db(r).Requests(f, atoi64(q.Get("before")), atoiDefault(q.Get("limit"), 50)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -903,7 +1150,7 @@ func (a *API) request(w http.ResponseWriter, r *http.Request) { if a.auth != nil { trusted = true // hosted: the ownership 404 below is the gate, not the address } - e, err := a.rec.DB().Request(id, trusted) + e, err := a.db(r).Request(id, trusted) if err != nil { httpErr(w, http.StatusNotFound, "no such request") return @@ -925,7 +1172,7 @@ func (a *API) request(w http.ResponseWriter, r *http.Request) { // discover and call — is more moving parts for the same wait. archived := false if trusted && len(e.Content) == 0 && e.SessionID != "" { - if meta, err := a.rec.DB().ArchivedSessionByID(e.SessionID); err == nil && meta.ContentPath != "" { + if meta, err := a.db(r).ArchivedSessionByID(e.SessionID); err == nil && meta.ContentPath != "" { archived = true ctx, cancel := context.WithTimeout(r.Context(), 30*time.Second) rows, ferr := a.rec.FetchArchivedContent(ctx, e.SessionID, e.ID) @@ -961,7 +1208,7 @@ func (a *API) sessions(w http.ResponseWriter, r *http.Request) { return } q := r.URL.Query() - rows, total, err := a.rec.DB().Sessions(f, + rows, total, err := a.db(r).Sessions(f, atoiDefault(q.Get("limit"), 50), atoiDefault(q.Get("offset"), 0)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) @@ -976,43 +1223,30 @@ func (a *API) components(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - key := cacheKey(p, r) - if body, ok := a.componentsCache.get(key); ok { - w.Header().Set("Content-Type", "application/json") - w.Write(body) - return - } - rows, err := a.rec.DB().Components(f) - if err != nil { - httpErr(w, http.StatusInternalServerError, err.Error()) - return - } - // Value the rows whose saved_usd predates the column, into their own field. Without this - // the most-read tab in the dashboard reports $0.00 for every component over all history - // that predates the last restart — measured, 6 populated rows out of 100,579. - if a.pricer != nil { - // Both read-time valuations, in order: the estimate fills history that predates the - // saved_usd column, the decomposition splits every priced row into its first-removal - // and replay halves so the two opposite-signed verdicts can be shown together. - if err := a.rec.DB().DecomposeComponentSavedUSD(f, a.pricer, rows); err != nil { - httpErr(w, http.StatusInternalServerError, err.Error()) - return + a.serveJSON(w, r, &a.componentsCache, cacheKey(p, r), func(db *DB) ([]byte, error) { + rows, err := db.Components(f) + if err != nil { + return nil, err } - if err := a.rec.DB().EstimateComponentSavedUSD(f, a.pricer, rows); err != nil { - // Best effort, like every other read-time valuation: the stored figures are - // already in `rows` and a failed estimate must not cost the caller the tab. - slog.Warn("context-guru: component saved_usd estimate failed; pre-column rows read $0.00", - "err", err) + // Value the rows whose saved_usd predates the column, into their own field. Without this + // the most-read tab in the dashboard reports $0.00 for every component over all history + // that predates the last restart — measured, 6 populated rows out of 100,579. + if a.pricer != nil { + // Both read-time valuations, in order: the estimate fills history that predates the + // saved_usd column, the decomposition splits every priced row into its first-removal + // and replay halves so the two opposite-signed verdicts can be shown together. + if err := db.DecomposeComponentSavedUSD(f, a.pricer, rows); err != nil { + return nil, err + } + if err := db.EstimateComponentSavedUSD(f, a.pricer, rows); err != nil { + // Best effort, like every other read-time valuation: the stored figures are + // already in `rows` and a failed estimate must not cost the caller the tab. + slog.Warn("context-guru: component saved_usd estimate failed; pre-column rows read $0.00", + "err", err) + } } - } - body, err := json.Marshal(map[string]any{"components": rows}) - if err != nil { - httpErr(w, http.StatusInternalServerError, err.Error()) - return - } - a.componentsCache.set(key, body) - w.Header().Set("Content-Type", "application/json") - w.Write(body) + return json.Marshal(map[string]any{"components": rows}) + }) } // breakdown serves spent-vs-saved and usage aggregated by ONE dimension — per model, per @@ -1033,7 +1267,7 @@ func (a *API) breakdown(w http.ResponseWriter, r *http.Request) { if dim == "" { dim = "model" } - rows, err := a.rec.DB().Breakdown(f, dim) + rows, err := a.db(r).Breakdown(f, dim) if err != nil { // A bad dimension is the CALLER's error, not a server fault, and the answer names // the dimensions that do exist rather than making the UI guess. @@ -1058,25 +1292,13 @@ func (a *API) facets(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - key := cacheKey(p, r) - if body, ok := a.facetsCache.get(key); ok { - w.Header().Set("Content-Type", "application/json") - w.Write(body) - return - } - f, err := a.rec.DB().Facets(flt) - if err != nil { - httpErr(w, http.StatusInternalServerError, err.Error()) - return - } - body, err := json.Marshal(f) - if err != nil { - httpErr(w, http.StatusInternalServerError, err.Error()) - return - } - a.facetsCache.set(key, body) - w.Header().Set("Content-Type", "application/json") - w.Write(body) + a.serveJSON(w, r, &a.facetsCache, cacheKey(p, r), func(db *DB) ([]byte, error) { + f, err := db.Facets(flt) + if err != nil { + return nil, err + } + return json.Marshal(f) + }) } // The two /api/config descriptions. This route serves the PROCESS's own resolved @@ -1146,11 +1368,11 @@ func (a *API) benchmarks(w http.ResponseWriter, r *http.Request) { // correct scan of an empty directory are the same response — and the UI reported both // as "nothing happened" because it discarded the body entirely. dirs := a.rec.Opts().BenchDirs - runs, tasks := a.rec.DB().IngestBenchRoots(dirs) + runs, tasks := a.db(r).IngestBenchRoots(dirs) writeJSON(w, map[string]any{"ingested_runs": runs, "ingested_tasks": tasks, "dirs": dirs}) return } - runs, err := a.rec.DB().BenchRuns() + runs, err := a.db(r).BenchRuns() if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -1162,7 +1384,7 @@ func (a *API) benchmarkTasks(w http.ResponseWriter, r *http.Request) { if !a.requireManager(w, r, "benchmark runs") { return } - rows, err := a.rec.DB().BenchTasks(atoi64(r.PathValue("id")), r.URL.Query().Get("arm")) + rows, err := a.db(r).BenchTasks(atoi64(r.PathValue("id")), r.URL.Query().Get("arm")) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return diff --git a/dash/api_test.go b/dash/api_test.go index 6c3439ea..e7ef82b1 100644 --- a/dash/api_test.go +++ b/dash/api_test.go @@ -1116,3 +1116,27 @@ func TestUINeverShowsABareCost(t *testing.T) { } } } + +// The 5 s response cache is the reason /api/facets survived at ~1.5s per call: requested on +// every tab switch, one miss followed by eleven hits reads as a fast endpoint. X-Cache is what +// lets a measurement tell the two apart, so it is asserted rather than assumed — an A/B that +// silently compares a miss against a hit reports a 158x "optimisation" nobody made. +func TestCachedRoutesLabelHitsAndMisses(t *testing.T) { + a, rec := newTestAPI(t, Options{}) + seed(t, rec, mkEvent(time.Now().UnixMilli(), "sess-1", "aws/claude-sonnet-5", 1000, 800)) + for _, path := range []string{"/api/stats", "/api/facets", "/api/components"} { + w, _ := get(t, a, path, "") + if got := w.Header().Get("X-Cache"); got != "miss" { + t.Errorf("%s first call: X-Cache = %q, want miss", path, got) + } + w, _ = get(t, a, path, "") + if got := w.Header().Get("X-Cache"); got != "hit" { + t.Errorf("%s second call: X-Cache = %q, want hit", path, got) + } + } + // An uncached route must not claim either, or the header becomes noise. + w, _ := get(t, a, "/api/requests?limit=1", "") + if got := w.Header().Get("X-Cache"); got != "" { + t.Errorf("/api/requests: X-Cache = %q, want absent", got) + } +} diff --git a/dash/archive.go b/dash/archive.go index 3b6cdf3a..0e41fe53 100644 --- a/dash/archive.go +++ b/dash/archive.go @@ -113,7 +113,7 @@ func (d *DB) coldSessions(idleBefore int64, kind string, limit int) ([]coldCandi FROM requests r WHERE r.session_id <> '' ` + notYet + ` GROUP BY r.session_id HAVING MAX(r.ts) < ? ORDER BY MAX(r.ts) ASC LIMIT ?` - rows, err := d.sql.Query(q, idleBefore, limit) + rows, err := d.sql.QueryContext(d.readCtx(), q, idleBefore, limit) if err != nil { return nil, err } @@ -139,7 +139,7 @@ func (d *DB) oldestLocalSessions(limit int) ([]coldCandidate, error) { // scanCandidates runs a candidate query and scans its rows. func (d *DB) scanCandidates(q string, args ...any) ([]coldCandidate, error) { - rows, err := d.sql.Query(q, args...) + rows, err := d.sql.QueryContext(d.readCtx(), q, args...) if err != nil { return nil, err } @@ -403,7 +403,7 @@ func (d *DB) ArchivedSessions(f Filter, limit int) ([]ArchivedSession, error) { } q += ` ORDER BY last_ts DESC LIMIT ?` args = append(args, limit) - rows, err := d.sql.Query(q, args...) + rows, err := d.sql.QueryContext(d.readCtx(), q, args...) if err != nil { return nil, err } @@ -424,7 +424,7 @@ func (d *DB) ArchivedSessions(f Filter, limit int) ([]ArchivedSession, error) { // ArchivedSessionByID reads one index row. func (d *DB) ArchivedSessionByID(sessionID string) (ArchivedSession, error) { var a ArchivedSession - err := d.sql.QueryRow(`SELECT session_id,tenant_id,first_ts,last_ts,requests, + err := d.sql.QueryRowContext(d.readCtx(), `SELECT session_id,tenant_id,first_ts,last_ts,requests, content_path,content_bytes,full_path,full_bytes,archived_at,remote FROM archived_sessions WHERE session_id = ?`, sessionID).Scan( &a.SessionID, &a.TenantID, &a.FirstTS, &a.LastTS, &a.Requests, diff --git a/dash/bench.go b/dash/bench.go index 6ad9374a..e0c2623f 100644 --- a/dash/bench.go +++ b/dash/bench.go @@ -207,7 +207,7 @@ type BenchArm struct { // BenchRuns returns every ingested run with its per-arm aggregates. func (d *DB) BenchRuns() ([]*BenchRun, error) { - rows, err := d.sql.Query(`SELECT id, name, ts, dataset, model, summary FROM bench_runs ORDER BY ts DESC`) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT id, name, ts, dataset, model, summary FROM bench_runs ORDER BY ts DESC`) if err != nil { return nil, err } @@ -236,7 +236,7 @@ func (d *DB) BenchRuns() ([]*BenchRun, error) { } func (d *DB) benchArms(runID int64) ([]BenchArm, error) { - rows, err := d.sql.Query(`SELECT arm, COUNT(*), + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT arm, COUNT(*), SUM(CASE WHEN exception = 0 THEN 1 ELSE 0 END), SUM(CASE WHEN reward >= 1 THEN 1 ELSE 0 END), AVG(reward), AVG(steps), SUM(cost_usd), AVG(cost_usd), SUM(norm_cost_usd), @@ -295,7 +295,7 @@ func (d *DB) BenchTasks(runID int64, arm string) ([]*BenchTask, error) { args = append(args, arm) } q += " ORDER BY task, arm" - rows, err := d.sql.Query(q, args...) + rows, err := d.sql.QueryContext(d.readCtx(), q, args...) if err != nil { return nil, err } diff --git a/dash/cachehistory.go b/dash/cachehistory.go index 6605b0ac..1eb19b22 100644 --- a/dash/cachehistory.go +++ b/dash/cachehistory.go @@ -86,11 +86,22 @@ func (d *DB) CachesplitHistoricalUSD(f Filter, p modelinfo.Pricer) (CachesplitHi // ROW_NUMBER ranks EVERY row in the table by session, unfiltered, so rn=1 means exactly // what the old subquery's NOT EXISTS meant — "nothing earlier in this session, filtered or // not" — before the outer WHERE narrows to the rows this query actually values. - rows, err := d.sql.Query(`WITH s AS ( - SELECT r.*, ROW_NUMBER() OVER (PARTITION BY r.session_id ORDER BY r.ts, r.id) AS rn + // The ranking CTE emits (id, rn) and is joined back on the primary key, rather than pulling + // `r.*` through the PARTITION BY sort for the sake of one integer per row. Same rewrite as + // CompactionResets in overview.go, same reason, and the same caveat: the CTE stays UNFILTERED, + // which is the whole correctness argument above — rn=1 has to mean "nothing earlier in this + // session, filtered or not", so the filter may only ever be applied outside it. + // + // Measured: 199-208 ms to 38-44 ms on the 16,444-request corpus, and 1,103 ms to 270 ms + // read-only against the production database. Results identical, checked on the 6,697 rows + // this predicate actually returns there and on 16,167 rows with the split/cache filters + // dropped, plus each tenant scope separately -- the frozen corpus returns ZERO rows for the + // shipped predicate, so a check against it alone proves nothing. + rows, err := d.sql.QueryContext(d.readCtx(), `WITH rn AS ( + SELECT r.id AS rid, ROW_NUMBER() OVER (PARTITION BY r.session_id ORDER BY r.ts, r.id) AS n FROM requests r - ) SELECT r.model, r.cache_read, r.cache_write FROM s r - WHERE `+cond+` AND r.split_stable_tokens = 0 AND r.cache_read > 0 AND r.rn = 1`, args...) + ) SELECT r.model, r.cache_read, r.cache_write FROM requests r JOIN rn ON rn.rid = r.id AND rn.n = 1 + WHERE `+cond+` AND r.split_stable_tokens = 0 AND r.cache_read > 0`, args...) if err != nil { return out, err } @@ -162,11 +173,22 @@ func (d *DB) CachesplitHistoricalUSDByTenant(since int64, p modelinfo.Pricer) (m return out, err } cond, args := (Filter{Since: since, TenantAll: true}).where() - rows, err := d.sql.Query(`WITH s AS ( - SELECT r.*, ROW_NUMBER() OVER (PARTITION BY r.session_id ORDER BY r.ts, r.id) AS rn + // The ranking CTE emits (id, rn) and is joined back on the primary key, rather than pulling + // `r.*` through the PARTITION BY sort for the sake of one integer per row. Same rewrite as + // CompactionResets in overview.go, same reason, and the same caveat: the CTE stays UNFILTERED, + // which is the whole correctness argument above — rn=1 has to mean "nothing earlier in this + // session, filtered or not", so the filter may only ever be applied outside it. + // + // Measured: 199-208 ms to 38-44 ms on the 16,444-request corpus, and 1,103 ms to 270 ms + // read-only against the production database. Results identical, checked on the 6,697 rows + // this predicate actually returns there and on 16,167 rows with the split/cache filters + // dropped, plus each tenant scope separately -- the frozen corpus returns ZERO rows for the + // shipped predicate, so a check against it alone proves nothing. + rows, err := d.sql.QueryContext(d.readCtx(), `WITH rn AS ( + SELECT r.id AS rid, ROW_NUMBER() OVER (PARTITION BY r.session_id ORDER BY r.ts, r.id) AS n FROM requests r - ) SELECT r.tenant_id, r.model, r.cache_read, r.cache_write FROM s r - WHERE `+cond+` AND r.split_stable_tokens = 0 AND r.cache_read > 0 AND r.rn = 1`, args...) + ) SELECT r.tenant_id, r.model, r.cache_read, r.cache_write FROM requests r JOIN rn ON rn.rid = r.id AND rn.n = 1 + WHERE `+cond+` AND r.split_stable_tokens = 0 AND r.cache_read > 0`, args...) if err != nil { return out, err } @@ -234,7 +256,7 @@ func (d *DB) CachesplitHistoricalUSDByTenant(since int64, p modelinfo.Pricer) (m // instead of assumed, and it is what decides the refusal rather than merely reporting on it. func (d *DB) CachesplitSizeSpread() (map[string][2]int, error) { out := map[string][2]int{} - rows, err := d.sql.Query(`SELECT model, MIN(split_stable_tokens), MAX(split_stable_tokens) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT model, MIN(split_stable_tokens), MAX(split_stable_tokens) FROM requests WHERE split_stable_tokens > 0 GROUP BY model`) if err != nil { return nil, err diff --git a/dash/campaignsavings.go b/dash/campaignsavings.go index da18beea..c25577a3 100644 --- a/dash/campaignsavings.go +++ b/dash/campaignsavings.go @@ -117,7 +117,7 @@ func (d *DB) CampaignRealSavings(strategyIDs, tenantIDs []string, since int64) ( costArgs = append(costArgs, id) } costArgs = append(costArgs, since) - costRows, err := d.sql.Query(`SELECT tenant_id, + costRows, err := d.sql.QueryContext(d.readCtx(), `SELECT tenant_id, CAST(strftime('%H', ts/1000, 'unixepoch') AS INTEGER) h, COUNT(*), COALESCE(SUM(cost_usd),0) FROM requests WHERE keepalive = 1 AND keepalive_strategy_id IN (`+ @@ -175,7 +175,7 @@ func (d *DB) CampaignRealSavings(strategyIDs, tenantIDs []string, since int64) ( savingArgs = append(savingArgs, id) } savingArgs = append(savingArgs, since) - savingRows, err := d.sql.Query(`SELECT r.tenant_id, + savingRows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.tenant_id, CAST(strftime('%H', r.ts/1000, 'unixepoch') AS INTEGER) h, COUNT(*), COUNT(DISTINCT r.ts/86400000), `+savedExpr+` FROM requests r WHERE r.keepalive = 0 AND r.tenant_id IN (`+ diff --git a/dash/componentscache_test.go b/dash/componentscache_test.go index 7d93d912..a40a6be0 100644 --- a/dash/componentscache_test.go +++ b/dash/componentscache_test.go @@ -7,12 +7,18 @@ import ( "time" ) -// TestComponentsCached guards the fix: /api/components had no cache at all (unlike -// /api/stats and /api/facets), so every load re-ran all five of its queries cold — -// measured ~4.4s on a corpus matching production scale. A second call within -// dashCacheTTL must be served from cache, not re-run against the store: seed one -// component row, read it, seed a second, and confirm the immediate re-read still -// reports only the first (the cached body), while a read past the TTL sees both. +// TestComponentsCached guards the fix: /api/components had no cache at all (unlike /api/stats and +// /api/facets), so every load re-ran all five of its queries cold — measured ~4.4s on a corpus +// matching production scale, ~6s on the live one. +// +// It now guards the STALE-WHILE-REVALIDATE contract too, which is a deliberate change from "past +// the TTL, block and return fresh". A TTL of 5s in front of a 6s query cached nothing — every +// reader missed and paid full price, and nineteen of them at once turned a query that fits inside +// the handler timeout into 503s all day. So past the TTL a reader is now handed the previous body +// immediately (X-Cache: stale) while the replacement is computed behind the response, and only +// past dashCacheStale on top of that does anyone wait again. The staleness cap is the honest half +// and is asserted here: without it a quiet deployment would serve its last body forever while the +// page reported it as current. func TestComponentsCached(t *testing.T) { a, rec := newTestAPI(t, Options{}) e := mkEvent(time.Now().UnixMilli(), "sess-1", "aws/claude-sonnet-5", 1000, 800) @@ -39,19 +45,59 @@ func TestComponentsCached(t *testing.T) { t.Fatalf("second call within the TTL: got %d component rows, want 1 (cached) -- the cache did not hit", len(rows)) } - // Past the TTL, the same call must see the fresh data. Single-tenant scope() always - // returns Principal{Manager: true} (see API.scope), so cacheKey's own rule gives a - // deterministic key to backdate. + // Single-tenant scope() always returns Principal{Manager: true} (see API.scope), so cacheKey's + // own rule gives a deterministic key to backdate. key := cacheKey(Principal{Manager: true}, httptest.NewRequest(http.MethodGet, "/api/components", nil)) - a.componentsCache.mu.Lock() - entry := a.componentsCache.entries[key] - entry.at = time.Now().Add(-dashCacheTTL - time.Second) - a.componentsCache.entries[key] = entry - a.componentsCache.mu.Unlock() + backdate := func(d time.Duration) { + a.componentsCache.mu.Lock() + entry := a.componentsCache.entries[key] + entry.at = time.Now().Add(-d) + a.componentsCache.entries[key] = entry + a.componentsCache.mu.Unlock() + } - _, body = get(t, a, "/api/components", "127.0.0.1:1") + // Just past the TTL: the reader is handed the STALE body rather than made to wait, and the + // refresh happens behind the response. + backdate(dashCacheTTL + time.Second) + w, body = get(t, a, "/api/components", "127.0.0.1:1") + if got := w.Header().Get("X-Cache"); got != "stale" { + t.Errorf("just past the TTL: X-Cache = %q, want \"stale\" — the reader should not wait for a "+ + "recompute when a servable body exists", got) + } + rows, _ = body["components"].([]any) + if len(rows) != 1 { + t.Errorf("just past the TTL: got %d component rows, want 1 (the stale body served immediately)", len(rows)) + } + + // ...and that background refresh must actually land, or "stale" would be permanent. + deadline := time.Now().Add(5 * time.Second) + for { + _, body = get(t, a, "/api/components", "127.0.0.1:1") + rows, _ = body["components"].([]any) + if len(rows) == 2 { + break + } + if time.Now().After(deadline) { + t.Fatalf("the background refresh never replaced the stale body: still %d rows after 5s. "+ + "A refresh that cannot complete makes every reader permanently stale, which is worse "+ + "than the blocking recompute this replaced.", len(rows)) + } + time.Sleep(20 * time.Millisecond) + } + + // Past the staleness cap, a reader waits for fresh numbers instead. Seed a third component so + // "fresh" is distinguishable from whatever is cached. + e3 := mkEvent(time.Now().UnixMilli(), "sess-3", "aws/claude-sonnet-5", 1000, 800) + e3.Components = []CompRow{{Component: "dedup", Kind: "reformat", Acted: true}} + seed(t, rec, e3) + backdate(dashCacheTTL + dashCacheStale + time.Second) + w, body = get(t, a, "/api/components", "127.0.0.1:1") + if got := w.Header().Get("X-Cache"); got != "miss" { + t.Errorf("past dashCacheStale: X-Cache = %q, want \"miss\" — beyond the cap a body is too old "+ + "to serve, and the freshness line the page prints would be a lie", got) + } rows, _ = body["components"].([]any) - if len(rows) != 2 { - t.Fatalf("call past the TTL: got %d component rows, want 2 (fresh)", len(rows)) + if len(rows) != 3 { + t.Errorf("past dashCacheStale: got %d component rows, want 3 (recomputed)", len(rows)) } } diff --git a/dash/dedupetext.go b/dash/dedupetext.go index 38e4177c..a4a3e59a 100644 --- a/dash/dedupetext.go +++ b/dash/dedupetext.go @@ -138,7 +138,7 @@ const dedupeMigrationDoneKey = "dedupe_declaration_text_done" // that silently never runs. func (d *DB) dedupeMigrationDone() (bool, error) { var v string - err := d.sql.QueryRow(`SELECT value FROM meta WHERE key = ?`, dedupeMigrationDoneKey).Scan(&v) + err := d.sql.QueryRowContext(d.readCtx(), `SELECT value FROM meta WHERE key = ?`, dedupeMigrationDoneKey).Scan(&v) if err == sql.ErrNoRows { return false, nil } @@ -164,7 +164,7 @@ type declBlob struct { // pendingDedupe reads the next batch of rows whose text is still on the row itself. rowid is // the table's own key, so `rowid > ?` is a seek rather than a scan of what came before it. func (d *DB) pendingDedupe(after int64, limit int) ([]declBlob, error) { - rows, err := d.sql.Query(`SELECT rowid, text_gz FROM tool_declarations + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT rowid, text_gz FROM tool_declarations WHERE rowid > ? AND text_gz IS NOT NULL ORDER BY rowid LIMIT ?`, after, limit) if err != nil { return nil, err diff --git a/dash/janitor.go b/dash/janitor.go index 2f569442..40801732 100644 --- a/dash/janitor.go +++ b/dash/janitor.go @@ -50,6 +50,36 @@ func (r *Recorder) janitorPass() { slog.Info("dash: pruned old dashboard rows", "requests", n) } r.relieveDiskPressure() + // Keep the query planner's statistics current. Cheap, and the one thing here that makes + // existing indexes get USED rather than merely exist. + // + // BEFORE the checkpoint below, not after, and that ordering is load-bearing: PRAGMA optimize + // runs ANALYZE, which WRITES sqlite_stat1. Run after the checkpoint, those writes land in a + // freshly truncated WAL and stay there until the next pass — so every pass would leave the WAL + // growing again, which is the exact thing the checkpoint exists to prevent. + // TestJanitorPassCheckpointsWAL caught this, and it is the reason that test asserts on WAL size + // rather than on the checkpoint merely having been called. + // + // This database had never been ANALYZEd at all — sqlite_stat1 did not exist — so SQLite was + // planning every join in this package on hard-coded guesses. Measured on a copy of the + // production database, /api/components over a 24-hour window: 3.59s without statistics, + // 0.81s with them, a 4.4x difference from no code change and no new index. The guess it was + // getting wrong is join ORDER: with no row counts it scanned all 1.58M request_components + // rows and probed requests per row, instead of driving from the filtered requests window + // through idx_rc_request. Two of those queries are pinned explicitly with a CROSS JOIN + // barrier (see Components in dash/query.go); statistics fix the rest, including + // DecomposeComponentSavedUSD, EstimateComponentSavedUSD and Facets' component list. + // + // PRAGMA optimize rather than a bare ANALYZE, and here rather than at Open: it re-analyses + // only tables whose statistics are missing or stale, so the steady-state cost is near zero + // and only the first pass does real work. A bare ANALYZE on this database measures 72s — + // fine on a background timer, and exactly what must never sit in front of the listener, + // which Open does (cmd/context-guru-proxy opens the store long before it serves). + // + // Statistics going stale is the failure mode to keep in mind: they are a snapshot, and a + // database that doubles in size between passes plans against the old shape. That is what + // makes this belong on the recurring pass rather than being run once by hand. + r.db.optimize() // Checkpoint on every pass, not only as reclaim()'s side effect of an actual // deletion above: a deployment comfortably inside its retention budget never // deletes anything, so without this the WAL was left to grow until SQLite's own diff --git a/dash/keepalive.go b/dash/keepalive.go index cd01426f..c1658818 100644 --- a/dash/keepalive.go +++ b/dash/keepalive.go @@ -229,7 +229,7 @@ func (d *DB) KeepAliveLedger(f Filter) (*KeepAliveLedger, error) { // request that benefited, never on the ping. cond, args := f.where() var from sql.NullInt64 - if err := d.sql.QueryRow(`SELECT + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COALESCE(SUM(`+kaSaved("r.")+`),0), COALESCE(SUM(CASE WHEN `+kaSaved("r.")+` > 0 THEN 1 ELSE 0 END),0), COUNT(*) @@ -240,7 +240,7 @@ func (d *DB) KeepAliveLedger(f Filter) (*KeepAliveLedger, error) { // The COST half, with ping rows included. A second query and not a CASE: one predicate, // one meaning. kaCond, kaArgs := withKeepAlive(f).where() - if err := d.sql.QueryRow(`SELECT + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COALESCE(SUM(CASE WHEN r.keepalive = 1 THEN 1 ELSE 0 END),0), COALESCE(SUM(CASE WHEN r.keepalive = 1 THEN r.cost_usd ELSE 0 END),0), COALESCE(SUM(CASE WHEN r.keepalive = 1 AND r.cache_read = 0 THEN 1 ELSE 0 END),0), @@ -254,7 +254,7 @@ func (d *DB) KeepAliveLedger(f Filter) (*KeepAliveLedger, error) { o.NetUSD = o.SavedUSD - o.PingUSD o.RecordedFrom = from.Int64 if o.RecordedFrom > 0 { - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.ts >= ?`, + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.ts >= ?`, append(append([]any(nil), args...), o.RecordedFrom)...).Scan(&o.RecordedRows); err != nil { return nil, err } @@ -291,7 +291,7 @@ func (d *DB) KeepAliveLedger(f Filter) (*KeepAliveLedger, error) { } // What is still on the table: the addressable expiries in this window, and their bill. aCond, aArgs := addressable(f) - if err := d.sql.QueryRow(aCond+` + if err := d.sql.QueryRowContext(d.readCtx(), aCond+` SELECT COUNT(*), COALESCE(SUM(cost_usd),0) FROM addressable`, aArgs...).Scan( &o.Addressable, &o.AddressableUSD); err != nil { return nil, err @@ -317,7 +317,7 @@ func (d *DB) KeepAliveLedger(f Filter) (*KeepAliveLedger, error) { func (d *DB) KeepAliveNetUSDByTenant(since int64) (map[string]float64, error) { out := map[string]float64{} cond, args := (Filter{Since: since, TenantAll: true}).where() - rows, err := d.sql.Query(`SELECT r.tenant_id, COALESCE(SUM(`+kaSaved("r.")+`),0) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.tenant_id, COALESCE(SUM(`+kaSaved("r.")+`),0) FROM requests r WHERE `+cond+` GROUP BY r.tenant_id`, args...) if err != nil { return nil, err @@ -336,7 +336,7 @@ func (d *DB) KeepAliveNetUSDByTenant(since int64) (map[string]float64, error) { return nil, err } kaCond, kaArgs := withKeepAlive(Filter{Since: since, TenantAll: true}).where() - rows2, err := d.sql.Query(`SELECT r.tenant_id, COALESCE(SUM(r.cost_usd),0) + rows2, err := d.sql.QueryContext(d.readCtx(), `SELECT r.tenant_id, COALESCE(SUM(r.cost_usd),0) FROM requests r WHERE `+kaCond+` AND r.keepalive = 1 GROUP BY r.tenant_id`, kaArgs...) if err != nil { return nil, err @@ -372,7 +372,7 @@ func (d *DB) KeepAliveLatencyDiagnostic(f Filter) (kvcache.Latency, error) { var l kvcache.Latency cond, args := f.where() var hitSum, missSum sql.NullFloat64 - row := d.sql.QueryRow(`SELECT + row := d.sql.QueryRowContext(d.readCtx(), `SELECT SUM(CASE WHEN r.cache_read > r.cache_write AND r.cache_read > 0 THEN r.upstream_ms END), COALESCE(SUM(CASE WHEN r.cache_read > r.cache_write AND r.cache_read > 0 THEN 1 ELSE 0 END),0), SUM(CASE WHEN r.cache_write >= r.cache_read AND r.cache_write > 0 THEN r.upstream_ms END), @@ -396,7 +396,7 @@ func (d *DB) KeepAliveLatencyDiagnostic(f Filter) (kvcache.Latency, error) { // sumBySession groups one column by session under an extra predicate. func (d *DB) sumBySession(cond string, args []any, col, extra string) (map[string]float64, error) { - rows, err := d.sql.Query(`SELECT r.session_id, COALESCE(SUM(`+col+`),0) FROM requests r + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.session_id, COALESCE(SUM(`+col+`),0) FROM requests r WHERE `+cond+` AND `+extra+` AND r.session_id <> '' GROUP BY 1`, args...) if err != nil { return nil, err @@ -419,7 +419,7 @@ func (d *DB) sumBySession(cond string, args []any, col, extra string) (map[strin // report a rate per day of traffic that did not happen. func (d *DB) windowDays(cond string, args []any) float64 { var lo, hi sql.NullInt64 - if err := d.sql.QueryRow(`SELECT MIN(r.ts), MAX(r.ts) FROM requests r WHERE `+cond, + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT MIN(r.ts), MAX(r.ts) FROM requests r WHERE `+cond, args...).Scan(&lo, &hi); err != nil { return 0 } @@ -550,7 +550,7 @@ func (d *DB) KeepAliveBehaviour(f Filter, coverageSeconds float64) (*KeepAliveBe n int64 usd float64 }{} - rows, err := d.sql.Query(`SELECT date(r.ts/1000,'unixepoch'), COUNT(*), COALESCE(SUM(r.cost_usd),0) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT date(r.ts/1000,'unixepoch'), COUNT(*), COALESCE(SUM(r.cost_usd),0) FROM requests r WHERE `+cond+` GROUP BY 1`, args...) if err != nil { return nil, err @@ -572,7 +572,7 @@ func (d *DB) KeepAliveBehaviour(f Filter, coverageSeconds float64) (*KeepAliveBe if err := rows.Err(); err != nil { return nil, err } - rows, err = d.sql.Query(aCond+` + rows, err = d.sql.QueryContext(d.readCtx(), aCond+` SELECT date(ts/1000,'unixepoch'), MIN(ts), COUNT(*), COALESCE(SUM(cost_usd),0) FROM addressable GROUP BY 1 ORDER BY 1`, aArgs...) if err != nil { @@ -610,7 +610,7 @@ func (d *DB) KeepAliveBehaviour(f Filter, coverageSeconds float64) (*KeepAliveBe hourN := make([]int64, 24) hourUSD := make([]float64, 24) var gaps, prefixes []float64 - rows, err = d.sql.Query(aCond+` + rows, err = d.sql.QueryContext(d.readCtx(), aCond+` SELECT gap_s, COALESCE(prev_prefix,0), cost_usd, CAST(strftime('%H', ts/1000, 'unixepoch') AS INTEGER) FROM addressable`, aArgs...) @@ -682,14 +682,14 @@ func (d *DB) KeepAliveBehaviour(f Filter, coverageSeconds float64) (*KeepAliveBe // The phantoms, named rather than silently dropped: a reader comparing this panel with the // cache-miss breakdown on Usage will see two different `ttl_expiry` counts, and the // difference has to be explicable. - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond+` + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.cache_miss_reason = 'ttl_expiry' AND r.cache_write = 0`, args...).Scan( &out.Phantom); err != nil { return nil, err } // 3d: gaps BETWEEN expiries, per account. - rows, err = d.sql.Query(aCond+`, e AS ( + rows, err = d.sql.QueryContext(d.readCtx(), aCond+`, e AS ( SELECT tenant_id, (ts - LAG(ts) OVER (PARTITION BY tenant_id ORDER BY ts)) / 3600000.0 AS h FROM addressable) SELECT tenant_id, COUNT(h), AVG(h), MAX(h) FROM e WHERE h IS NOT NULL GROUP BY 1 @@ -718,7 +718,7 @@ func (d *DB) KeepAliveBehaviour(f Filter, coverageSeconds float64) (*KeepAliveBe for i := range out.Gaps { g := &out.Gaps[i] var hs []float64 - r2, err := d.sql.Query(aCond+`, e AS ( + r2, err := d.sql.QueryContext(d.readCtx(), aCond+`, e AS ( SELECT tenant_id, (ts - LAG(ts) OVER (PARTITION BY tenant_id ORDER BY ts)) / 3600000.0 AS h FROM addressable) SELECT h FROM e WHERE h IS NOT NULL AND tenant_id = ?`, @@ -755,18 +755,18 @@ func (d *DB) keepAliveCoverage(f Filter) (*KeepAliveCoverage, error) { cond, args := f.where() kaCond, kaArgs := withKeepAlive(f).where() var from sql.NullInt64 - if err := d.sql.QueryRow(`SELECT MIN(CASE WHEN r.keepalive = 1 OR r.keepalive_pings > 0 + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT MIN(CASE WHEN r.keepalive = 1 OR r.keepalive_pings > 0 OR r.keepalive_saved_usd > 0 THEN r.ts END) FROM requests r WHERE `+kaCond, kaArgs...).Scan(&from); err != nil { return nil, err } c.RecordedFrom = from.Int64 - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond, args...).Scan( + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond, args...).Scan( &c.Requests); err != nil { return nil, err } if c.RecordedFrom > 0 { - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.ts >= ?`, + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.ts >= ?`, append(append([]any(nil), args...), c.RecordedFrom)...).Scan(&c.RecordedRows); err != nil { return nil, err } @@ -816,7 +816,7 @@ func (d *DB) KeepAliveSessions(f Filter, limit int) ([]*KeepAliveSessionRow, err limit = 20 } aCond, aArgs := addressable(f) - rows, err := d.sql.Query(aCond+` + rows, err := d.sql.QueryContext(d.readCtx(), aCond+` SELECT session_id, MIN(tenant_id), COUNT(*), COALESCE(SUM(cost_usd),0) FROM addressable WHERE session_id <> '' GROUP BY session_id ORDER BY 4 DESC LIMIT ?`, @@ -846,14 +846,14 @@ func (d *DB) KeepAliveSessions(f Filter, limit int) ([]*KeepAliveSessionRow, err // count as a turn or re-date the session. cond, args := f.where() for _, s := range out { - if err := d.sql.QueryRow(`SELECT COUNT(*), MAX(r.ts) FROM requests r + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*), MAX(r.ts) FROM requests r WHERE `+cond+` AND r.session_id = ?`, append(append([]any(nil), args...), s.SessionID)...).Scan(&s.Turns, &s.Last); err != nil { return nil, err } var prefix sql.NullInt64 var model sql.NullString - if err := d.sql.QueryRow(`SELECT r.cache_read + r.cache_write, r.model FROM requests r + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT r.cache_read + r.cache_write, r.model FROM requests r WHERE `+cond+` AND r.session_id = ? ORDER BY r.ts DESC, r.id DESC LIMIT 1`, append(append([]any(nil), args...), s.SessionID)...).Scan(&prefix, &model); err != nil && err != sql.ErrNoRows { @@ -1005,7 +1005,7 @@ func (d *DB) KeepAliveLive(f Filter, now int64, idleSeconds float64, maxPings in // the three window MAXes answer "which tier is in force" without a query per row: the entry's // lifetime is the one it was WRITTEN at, and a read refreshes it at that same tier, so the // tell is whether this session's most recent write was a one-hour write. - rows, err := d.sql.Query(`WITH t AS ( + rows, err := d.sql.QueryContext(d.readCtx(), `WITH t AS ( SELECT r.session_id AS session_id, r.tenant_id AS tenant_id, r.ts AS ts, r.model AS model, r.cache_read + r.cache_write AS prefix, ROW_NUMBER() OVER w AS rn, @@ -1105,7 +1105,7 @@ func (d *DB) KeepAliveLive(f Filter, now int64, idleSeconds float64, maxPings in // countBySession counts rows per session under an extra predicate. func (d *DB) countBySession(cond string, args []any, extra string) (map[string]int64, error) { - rows, err := d.sql.Query(`SELECT r.session_id, COUNT(*) FROM requests r + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.session_id, COUNT(*) FROM requests r WHERE `+cond+` AND `+extra+` AND r.session_id <> '' GROUP BY 1`, args...) if err != nil { return nil, err @@ -1203,7 +1203,7 @@ func (d *DB) pingSpans(f Filter, minPrefix int64) ([]pingSpan, error) { cond, args := f.where() // LEAD, not LAG: a span belongs to the request that OPENS it, which is the request the gate // is evaluated on, and LEAD is NULL exactly on the session-final row. - rows, err := d.sql.Query(`WITH s AS ( + rows, err := d.sql.QueryContext(d.readCtx(), `WITH s AS ( SELECT r.session_id AS session_id, ROW_NUMBER() OVER (PARTITION BY r.tenant_id, r.session_id ORDER BY r.ts, r.id) - 1 AS turn, @@ -1294,7 +1294,7 @@ func (d *DB) KeepAliveCalc(f Filter, idleSeconds float64, prefix int64, model st aCond, aArgs := addressable(f) var gaps []float64 var usd []float64 - rows, err := d.sql.Query(aCond+` SELECT gap_s, cost_usd FROM addressable`, aArgs...) + rows, err := d.sql.QueryContext(d.readCtx(), aCond+` SELECT gap_s, cost_usd FROM addressable`, aArgs...) if err != nil { return nil, err } @@ -1365,7 +1365,7 @@ func (d *DB) KeepAliveCalc(f Filter, idleSeconds float64, prefix int64, model st // Returns 0 and "" when the account has no addressable expiry. func (d *DB) AccountMedianPrefix(f Filter) (int64, string, error) { aCond, aArgs := addressable(f) - rows, err := d.sql.Query(aCond+` SELECT COALESCE(prev_prefix,0), model FROM addressable`, aArgs...) + rows, err := d.sql.QueryContext(d.readCtx(), aCond+` SELECT COALESCE(prev_prefix,0), model FROM addressable`, aArgs...) if err != nil { return 0, "", err } @@ -1412,7 +1412,7 @@ func (d *DB) LastBilledPrefix(f Filter, session string) (int64, string, error) { cond, args := f.where() var prefix sql.NullInt64 var model sql.NullString - err := d.sql.QueryRow(`SELECT r.cache_read + r.cache_write, r.model FROM requests r + err := d.sql.QueryRowContext(d.readCtx(), `SELECT r.cache_read + r.cache_write, r.model FROM requests r WHERE `+cond+` AND r.session_id = ? ORDER BY r.ts DESC, r.id DESC LIMIT 1`, append(append([]any(nil), args...), session)...).Scan(&prefix, &model) if err == sql.ErrNoRows { @@ -1501,7 +1501,7 @@ func (d *DB) KeepAliveRecommend(f Filter) (*KeepAliveRecommendation, error) { // The account's own addressable expiries, grouped by session — the resampling unit. aCond, aArgs := addressable(f) - rows, err := d.sql.Query(aCond+` + rows, err := d.sql.QueryContext(d.readCtx(), aCond+` SELECT session_id, gap_s, cost_usd FROM addressable`, aArgs...) if err != nil { return nil, err @@ -1662,7 +1662,7 @@ func (d *DB) medianPingUSD(f Filter) (float64, error) { aCond, aArgs := addressable(f) // cost_usd on an addressable miss is dominated by the re-creation of prev_prefix at 1.25x // base input, so cost/prefix/1.25 recovers the base rate and 0.1x of it is the read. - rows, err := d.sql.Query(aCond+` + rows, err := d.sql.QueryContext(d.readCtx(), aCond+` SELECT cost_usd, COALESCE(prev_prefix,0) FROM addressable WHERE prev_prefix > 0`, aArgs...) if err != nil { return 0, err diff --git a/dash/keepaliveapi.go b/dash/keepaliveapi.go index b59728b1..a5e8599a 100644 --- a/dash/keepaliveapi.go +++ b/dash/keepaliveapi.go @@ -36,7 +36,7 @@ func (a *API) keepAlive(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - led, err := a.rec.DB().KeepAliveLedger(f) + led, err := a.db(r).KeepAliveLedger(f) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -55,7 +55,7 @@ func (a *API) keepAliveBehaviour(w http.ResponseWriter, r *http.Request) { // the page knows it. Defaulted in the DB layer, never guessed here. x, _ := strconv.ParseFloat(r.URL.Query().Get("x"), 64) k, _ := strconv.Atoi(r.URL.Query().Get("k")) - b, err := a.rec.DB().KeepAliveBehaviour(f, CoverageSeconds(x, k)) + b, err := a.db(r).KeepAliveBehaviour(f, CoverageSeconds(x, k)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -71,7 +71,7 @@ func (a *API) keepAliveSessions(w http.ResponseWriter, r *http.Request) { return } limit, _ := strconv.Atoi(r.URL.Query().Get("limit")) - rows, err := a.rec.DB().KeepAliveSessions(f, limit) + rows, err := a.db(r).KeepAliveSessions(f, limit) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -96,7 +96,7 @@ func (a *API) keepAliveCalc(w http.ResponseWriter, r *http.Request) { k, _ := strconv.Atoi(q.Get("k")) prefix, _ := strconv.ParseInt(q.Get("prefix"), 10, 64) model, source := q.Get("model"), "given" - db := a.rec.DB() + db := a.db(r) if session := q.Get("session"); session != "" { p, m, err := db.LastBilledPrefix(f, session) if err != nil { @@ -158,7 +158,7 @@ func (a *API) keepAliveLive(w http.ResponseWriter, r *http.Request) { q := r.URL.Query() x, _ := strconv.ParseFloat(q.Get("x"), 64) k, _ := strconv.Atoi(q.Get("k")) - out, err := a.rec.DB().KeepAliveLive(f, time.Now().UnixMilli(), x, k, a.priceFn(r)) + out, err := a.db(r).KeepAliveLive(f, time.Now().UnixMilli(), x, k, a.priceFn(r)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -173,7 +173,7 @@ func (a *API) keepAliveRecommend(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - rec, err := a.rec.DB().KeepAliveRecommend(f) + rec, err := a.db(r).KeepAliveRecommend(f) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return diff --git a/dash/keepalivestrategy.go b/dash/keepalivestrategy.go index 58b7ebc9..47a34abd 100644 --- a/dash/keepalivestrategy.go +++ b/dash/keepalivestrategy.go @@ -42,7 +42,7 @@ type StrategyLedgerView struct { // attributed to whichever strategy's ping(s) actually preceded it, once. func (d *DB) StrategyLedger(strategyID string) (*StrategyLedgerView, error) { out := &StrategyLedgerView{StrategyID: strategyID, Tenants: []StrategyLedgerRow{}} - rows, err := d.sql.Query(`SELECT tenant_id, COUNT(*), COALESCE(SUM(cost_usd),0) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT tenant_id, COUNT(*), COALESCE(SUM(cost_usd),0) FROM requests WHERE keepalive = 1 AND keepalive_strategy_id = ? GROUP BY tenant_id ORDER BY 3 DESC`, strategyID) if err != nil { @@ -65,7 +65,7 @@ func (d *DB) StrategyLedger(strategyID string) (*StrategyLedgerView, error) { for i := range out.Tenants { row := &out.Tenants[i] var saved sql.NullFloat64 - if err := d.sql.QueryRow(`SELECT SUM(`+kaSaved("r.")+`) FROM requests r + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT SUM(`+kaSaved("r.")+`) FROM requests r WHERE r.tenant_id = ? AND r.keepalive_saved_usd > 0 AND r.keepalive_strategy_id = ?`, row.TenantID, strategyID).Scan(&saved); err != nil { return nil, err @@ -99,7 +99,7 @@ func (a *API) keepAliveStrategyLedger(w http.ResponseWriter, r *http.Request) { httpErr(w, http.StatusBadRequest, "name the strategy") return } - led, err := a.rec.DB().StrategyLedger(id) + led, err := a.db(r).StrategyLedger(id) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return diff --git a/dash/keepalivestrategybackfill.go b/dash/keepalivestrategybackfill.go index a2bc5465..06597154 100644 --- a/dash/keepalivestrategybackfill.go +++ b/dash/keepalivestrategybackfill.go @@ -114,7 +114,7 @@ func (d *DB) backfillKeepAliveStrategyID(stop <-chan struct{}, batch int, pause // (keepalive_pings > 0) that have never been tagged with the strategy that sent the ping. // id is the table's own rowid, so `id > ?` is a seek rather than a rescan of what came before. func (d *DB) pendingKeepAliveStrategyBackfill(after int64, limit int) ([]int64, error) { - rows, err := d.sql.Query(`SELECT id FROM requests + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT id FROM requests WHERE id > ? AND keepalive = 0 AND keepalive_pings > 0 AND keepalive_strategy_id IS NULL ORDER BY id LIMIT ?`, after, limit) if err != nil { @@ -197,7 +197,7 @@ func (d *DB) backfillOneKeepAliveStrategyBatch(ids []int64) (int64, error) { // recoverable rows. func (d *DB) keepAliveStrategyBackfillDone() (bool, error) { var v string - err := d.sql.QueryRow(`SELECT value FROM meta WHERE key = ?`, keepAliveStrategyBackfillDoneKey).Scan(&v) + err := d.sql.QueryRowContext(d.readCtx(), `SELECT value FROM meta WHERE key = ?`, keepAliveStrategyBackfillDoneKey).Scan(&v) if err == sql.ErrNoRows { return false, nil } diff --git a/dash/kvcacheapi.go b/dash/kvcacheapi.go index da679e4b..08bbba0d 100644 --- a/dash/kvcacheapi.go +++ b/dash/kvcacheapi.go @@ -54,7 +54,7 @@ func (a *API) kvCache(w http.ResponseWriter, r *http.Request) { return } defer releaseKVCache() - out, err := a.rec.DB().WithContext(r.Context()). + out, err := a.db(r). KVCacheAnalyze(f, kvCacheOptionsFrom(r), a.pricer, kvCacheConfigFrom(r)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) @@ -70,7 +70,7 @@ func (a *API) kvCacheRows(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - out, err := a.rec.DB().WithContext(r.Context()).KVCacheRows(f, kvCacheOptionsFrom(r)) + out, err := a.db(r).KVCacheRows(f, kvCacheOptionsFrom(r)) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) return @@ -89,7 +89,7 @@ func (a *API) kvCacheSimulate(w http.ResponseWriter, r *http.Request) { return } defer releaseKVCache() - out, err := a.rec.DB().WithContext(r.Context()). + out, err := a.db(r). KVCacheSimulate(f, kvCacheOptionsFrom(r), a.pricer, kvCacheConfigFrom(r)) if err != nil { // An unknown arm or baseline is the caller's mistake; anything else came from the store. @@ -117,7 +117,7 @@ func (a *API) kvCacheSuggest(w http.ResponseWriter, r *http.Request) { return } defer releaseKVCache() - out, err := a.rec.DB().WithContext(r.Context()). + out, err := a.db(r). KVCacheSuggest(f, kvCacheOptionsFrom(r), a.pricer, kvCacheConfigFrom(r)) if err != nil { // An unknown baseline is the caller's mistake, same as on /api/kvcache/simulate. @@ -154,7 +154,7 @@ func (a *API) kvCacheSuggestHoldout(w http.ResponseWriter, r *http.Request) { q := r.URL.Query() train := Window{Since: atoi64(q.Get("train_since")), Until: atoi64(q.Get("train_until"))} test := Window{Since: atoi64(q.Get("test_since")), Until: atoi64(q.Get("test_until"))} - out, err := a.rec.DB().WithContext(r.Context()).KVCacheSuggestHoldout( + out, err := a.db(r).KVCacheSuggestHoldout( f, kvCacheOptionsFrom(r), a.pricer, kvCacheConfigFrom(r), train, test) if err != nil { // Every error validHoldoutWindows returns is the caller's own malformed window, and @@ -187,7 +187,7 @@ func (a *API) kvCachePricing(w http.ResponseWriter, r *http.Request) { // both captioned "this window's own median". o := kvCacheOptionsFrom(r) cfg := kvCacheConfigFrom(r) - db := a.rec.DB().WithContext(r.Context()) + db := a.db(r) models, err := db.KVCacheModels(f) if err != nil { httpErr(w, http.StatusInternalServerError, err.Error()) diff --git a/dash/metrics_export.go b/dash/metrics_export.go index 6af83286..bb95b9ee 100644 --- a/dash/metrics_export.go +++ b/dash/metrics_export.go @@ -104,7 +104,7 @@ type TenantMetricRow struct { // a tenant that has ONLY archived data still needs a row, or its history would vanish // from Grafana the moment its last live session was archived. func (d *DB) TenantMetrics(since int64) ([]TenantMetricRow, error) { - rows, err := d.sql.Query(` + rows, err := d.sql.QueryContext(d.readCtx(), ` SELECT t.tenant_id, COALESCE(t.requests,0), COALESCE(t.tokens_before,0), COALESCE(t.tokens_after,0), COALESCE(t.saved_unique,0), COALESCE(t.cache_read,0), COALESCE(t.cache_write,0), diff --git a/dash/optimize_test.go b/dash/optimize_test.go new file mode 100644 index 00000000..6c800ff6 --- /dev/null +++ b/dash/optimize_test.go @@ -0,0 +1,81 @@ +package dash + +// One check that the janitor actually refreshes planner statistics. +// +// Worth a test because the failure is silent and slow rather than visible: this database ran in +// production with no sqlite_stat1 at all, so SQLite planned every join in this package on +// hard-coded guesses and picked the wrong join order. Nothing breaks when that regresses — +// queries just get several times slower, which is how it went unnoticed in the first place. + +import ( + "os" + "strings" + "testing" + "time" +) + +func TestJanitorPassRefreshesPlannerStatistics(t *testing.T) { + a, rec := newTestAPI(t, Options{}) + // Enough rows that PRAGMA optimize judges the tables worth analysing; with a handful it may + // legitimately decide there is nothing to do. + evs := make([]*Event, 0, 400) + for i := 0; i < 400; i++ { + e := mkEvent(time.Now().UnixMilli()-int64(i)*1000, "sess-opt", "aws/claude-sonnet-5", 1000, 800) + e.Components = []CompRow{{Component: "toon", Kind: "reformat", Acted: true}} + evs = append(evs, e) + } + seed(t, rec, evs...) + _ = a + + var before int + // sqlite_stat1 does not exist until something analyses; a missing table is the "before" state. + _ = rec.DB().sql.QueryRow( + `SELECT COUNT(*) FROM sqlite_master WHERE type='table' AND name='sqlite_stat1'`).Scan(&before) + if before != 0 { + t.Fatalf("sqlite_stat1 already exists before any janitor pass (%d); this check needs rewriting", before) + } + + rec.janitorPass() + + var after int + if err := rec.DB().sql.QueryRow( + `SELECT COUNT(*) FROM sqlite_master WHERE type='table' AND name='sqlite_stat1'`).Scan(&after); err != nil { + t.Fatal(err) + } + if after == 0 { + t.Error("janitorPass did not create sqlite_stat1: planner statistics are never refreshed.\n" + + "Measured consequence on the production corpus: /api/components over 24h took 3.59s " + + "without statistics and 0.81s with them — same code, same indexes, 4.4x.") + } +} + +// The mask is asserted at SOURCE level because the functional test above cannot be trusted to +// catch its absence, and I know that because it did not. +// +// A bare `PRAGMA optimize` only considers tables the CURRENT CONNECTION has queried. The janitor +// takes a fresh pooled connection and queries nothing, so in production a bare form analyses +// nothing at all — measured on a copy of the production database: 0.00s, sqlite_stat1 still +// absent. The test above passed anyway, because seeding and janitorPass shared a pooled +// connection that HAD touched those tables. So the functional assertion can go green while the +// deployed behaviour is a no-op, which is precisely the shape that needs a source-level guard. +func TestOptimizeKeepsTheMaskThatMakesItWork(t *testing.T) { + src := readSource(t, "store.go") + if !strings.Contains(src, "PRAGMA optimize(0x10002)") { + t.Error("DB.optimize no longer runs `PRAGMA optimize(0x10002)`.\n" + + "0x10000 is what lets it consider tables this connection has not queried; without it the " + + "janitor's fresh pooled connection causes SQLite to analyse nothing and the call is a " + + "silent no-op. Measured: bare form 0.00s and no statistics; 0x10002 produces all 26 rows, " + + "also 0.00s, and takes the component aggregate from 2.0s to 0.209s.") + } +} + +// readSource reads a Go source file in this package from disk. Package tests run with the package +// directory as the working directory, so a bare filename resolves. +func readSource(t *testing.T, name string) string { + t.Helper() + b, err := os.ReadFile(name) + if err != nil { + t.Fatal(err) + } + return string(b) +} diff --git a/dash/overview.go b/dash/overview.go index a7d568dd..bb5226af 100644 --- a/dash/overview.go +++ b/dash/overview.go @@ -489,7 +489,7 @@ func (d *DB) Overview(f Filter) (*Overview, error) { CacheTTL: map[string]int64{}, } var cgAvg, upAvg, ttfbAvg, upBufAvg sql.NullFloat64 - err := d.sql.QueryRow(`SELECT COUNT(*), COUNT(DISTINCT r.session_id), + err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*), COUNT(DISTINCT r.session_id), COALESCE(SUM(r.tokens_before),0), COALESCE(SUM(r.tokens_after),0), COALESCE(SUM(r.saved_unique),0), COALESCE(SUM(r.attempted_tokens),0), COALESCE(SUM(r.frozen_tokens),0), -- The gross saving over ONLY the rows that recorded an attempted_tokens denominator, so @@ -646,16 +646,29 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // Everything from here to the percentiles below is a separate, independent read against // the same filter — none of these queries consumes another's result (the two exceptions, // the inflation correction and the estimator median, are noted where they are), so nothing - // stops them running concurrently instead of one after another. That is not an optimization - // for its own sake: measured against a production-sized copy of this table with zero write - // contention, this stretch alone summed to ~9s run sequentially — CompactionResets and the - // replay estimate each multiple seconds by themselves — which is why /api/stats was timing - // out its 10s caller-facing deadline on every single call, not just under load. Run - // concurrently against the same pooled *sql.DB (store.go's SetMaxOpenConns already sizes - // the pool for this), wall time drops to roughly the slowest single query rather than their - // sum. SQLite's WAL mode already gave each of these its own read snapshot when they ran - // sequentially — nothing here was ever one atomic view of the table — so concurrency changes - // only how long the caller waits, never what any individual query reads. + // stops them running concurrently instead of one after another. + // + // THE GROUP BUYS NO WALL TIME AT TODAY'S SIZES, and the claim that it does — that this + // "drops to roughly the slowest single query rather than their sum" — is retracted. Measured + // on a 16,444-request corpus: the sixteen queries in this function sum to 587 ms and the + // slowest is 186 ms, and Overview() measures 520-556 ms. That is the sum. The reason is the + // driver: `modernc.org/sqlite` reads do not run in parallel here. N copies of one ~280 ms + // query, 16 cores, SetMaxOpenConns(100) — n=2 is 1.05x, n=4 is 0.68x, n=8 is 0.51x, so + // concurrency is SLOWER than sequential once there is any of it. + // + // What is NOT established: the ~9s this comment used to attribute to sequential execution, + // and the /api/stats timeouts attributed to that. Both figures predate the LAG rewrite below + // and idx_tooldecl_session, and nobody has re-measured this stretch sequentially either side + // of those two changes — so which change earned that improvement is an open question, not + // something this comment gets to answer. Note also that 0.51x at n=8 is a measurement of + // TODAY's sizes; it does not establish that concurrency never helped at 9s scale, where the + // contention profile may genuinely have differed. So the group stays: a deletion needs its + // own before/after, which nobody has run. + // + // Still true, and unaffected by any of the above: SQLite's WAL mode already gave each of + // these its own read snapshot when they ran sequentially — nothing here was ever one atomic + // view of the table — so concurrency changes only how long the caller waits, never what any + // individual query reads. var ( replayProjectedRaw, inflation int64 ttl map[string]int64 @@ -675,7 +688,7 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // scopes this to the tenant/window idx_requests_tenant covers, so this is a filter over an // already-narrow row set, not a fresh scan. g.Go(func() error { - return d.sql.QueryRow(`SELECT COUNT(*) FROM requests r + return d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.preset = 'invalid'`, args...).Scan(&invalidConfigRequests) }) // The replay ceiling's raw form, corrected below by the inflation query once both are in — @@ -692,7 +705,7 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // function must still sort the WHOLE table before the outer filter can narrow anything. // Left as the correlated form on purpose. g.Go(func() error { - return d.sql.QueryRow(`SELECT COALESCE(SUM(r.saved_unique * ( + return d.sql.QueryRowContext(d.readCtx(), `SELECT COALESCE(SUM(r.saved_unique * ( SELECT COUNT(*) FROM requests p WHERE p.session_id = r.session_id AND (p.ts > r.ts OR (p.ts = r.ts AND p.id > r.id)))),0) FROM requests r WHERE `+cond+` AND r.saved_unique > 0`, args...).Scan(&replayProjectedRaw) @@ -708,7 +721,7 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // 10,000-row perf fixture, 5 trials: gated 52.7 ms against 53.0 ms ungated at 0 pings, and // 58.0 against 57.3 at 100 — one extra scan for no measurable saving, so it is gone. g.Go(func() error { - return d.sql.QueryRow(`SELECT COALESCE(SUM(( + return d.sql.QueryRowContext(d.readCtx(), `SELECT COALESCE(SUM(( SELECT COALESCE(SUM(r.saved_unique),0) FROM requests r WHERE r.session_id = p.session_id AND r.saved_unique > 0 AND (r.ts < p.ts OR (r.ts = p.ts AND r.id < p.id)) @@ -728,7 +741,7 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // The MODAL breakpoint placement, not the mean: 1.5 breakpoints in a system block is not // a thing any request did, and an average across locations describes no prompt at all. g.Go(func() error { - err := d.sql.QueryRow(`SELECT r.cache_bp_system, r.cache_bp_tools, r.cache_bp_messages, + err := d.sql.QueryRowContext(d.readCtx(), `SELECT r.cache_bp_system, r.cache_bp_tools, r.cache_bp_messages, r.cache_bp_blocks, COUNT(*) AS n FROM requests r WHERE `+cond+` GROUP BY 1,2,3,4 ORDER BY n DESC LIMIT 1`, args...).Scan(&bs, &bt, &bm, &bb, &modalRequests) @@ -753,14 +766,27 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // happens (tokens_before > 0 holds for every row measured), so this is not a behavior // change in practice, but it is not a byte-for-byte port of the old query's guarantee. g.Go(func() error { - q := `WITH s AS ( - SELECT r.*, LAG(CASE WHEN r.tokens_before > 0 THEN r.tokens_before END) + // Two columns through the window sort, not `r.*`. The CTE used to select every column + // of `requests` and carry all of them through the PARTITION BY sort, when the only thing + // the outer query wants from it is one LAG value per row. Emitting (id, prev) and joining + // back on the primary key sorts ~2 columns instead of ~56; the 16k primary-key probes + // that costs are cheaper than the payload they replace, which is the opposite of the + // tradeoff Facets' component list turns on (see query.go) — invocation count wins there, + // sort payload wins here, so neither is a rule. + // + // Measured: 242-316 ms to 59-63 ms on the 16,444-request corpus (5 runs), and 1,324 ms + // to 553 ms read-only against the production database. Result identical service-wide + // (37,954 rows there, 526 here) and under each tenant scope separately. Keeping the CTE + // self-contained but listing only the filterable columns was also tried and is the worse + // of the two at 135 ms. + q := `WITH prev AS ( + SELECT r.id AS rid, LAG(CASE WHEN r.tokens_before > 0 THEN r.tokens_before END) OVER (PARTITION BY r.session_id ORDER BY r.ts, r.id) AS prev_tokens_before FROM requests r - ) SELECT COUNT(*) FROM s r WHERE ` + cond + ` - AND r.tokens_before > 0 AND r.prev_tokens_before IS NOT NULL - AND r.tokens_before < r.prev_tokens_before` - return d.sql.QueryRow(q, args...).Scan(&o.CompactionResets) + ) SELECT COUNT(*) FROM requests r JOIN prev ON prev.rid = r.id WHERE ` + cond + ` + AND r.tokens_before > 0 AND prev.prev_tokens_before IS NOT NULL + AND r.tokens_before < prev.prev_tokens_before` + return d.sql.QueryRowContext(d.readCtx(), q, args...).Scan(&o.CompactionResets) }) // The estimator check, on the only population where the two counts are comparable: requests // where nothing was removed, so tokens_before and the provider's billed input describe the @@ -773,13 +799,13 @@ func (d *DB) Overview(f Filter) (*Overview, error) { g.Go(func() error { const ratioPop = ` AND r.tokens_before = r.tokens_after AND r.tokens_before > 0 AND r.token_accounting = 'complete' AND r.fresh_input + r.cache_read + r.cache_write > 0` - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond+ratioPop, + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+ratioPop, args...).Scan(&estimatorDivergenceRows); err != nil { return err } if estimatorDivergenceRows > 0 { var med sql.NullFloat64 - if err := d.sql.QueryRow(`SELECT + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT CAST(r.fresh_input + r.cache_read + r.cache_write AS REAL) / r.tokens_before AS ratio FROM requests r WHERE `+cond+ratioPop+` ORDER BY ratio ASC LIMIT 1 OFFSET ?`, @@ -795,7 +821,7 @@ func (d *DB) Overview(f Filter) (*Overview, error) { // them: one predicate, one meaning. g.Go(func() error { kaCond, kaArgs := withKeepAlive(f).where() - return d.sql.QueryRow(`SELECT + return d.sql.QueryRowContext(d.readCtx(), `SELECT COALESCE(SUM(CASE WHEN r.keepalive = 1 THEN 1 ELSE 0 END),0), COALESCE(SUM(CASE WHEN r.keepalive = 1 THEN r.cost_usd ELSE 0 END),0) FROM requests r WHERE `+kaCond, kaArgs...).Scan(&keepAlivePings, &keepAlivePingUSD) @@ -1103,7 +1129,7 @@ func (o *Overview) waterfall() []WaterfallStep { // countBy groups the filtered window by one column. func (d *DB) countBy(cond string, args []any, col string) (map[string]int64, error) { - rows, err := d.sql.Query(`SELECT r.`+col+`, COUNT(*) FROM requests r WHERE `+cond+` GROUP BY 1`, args...) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.`+col+`, COUNT(*) FROM requests r WHERE `+cond+` GROUP BY 1`, args...) if err != nil { return nil, err } @@ -1126,7 +1152,7 @@ func (d *DB) countBy(cond string, args []any, col string) (map[string]int64, err // window of a few hundred thousand floats in milliseconds off the ts index. func (d *DB) percentile(cond string, args []any, col string, p float64) (float64, error) { var n int64 - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.`+col+` > 0`, args...).Scan(&n); err != nil { + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+` AND r.`+col+` > 0`, args...).Scan(&n); err != nil { return 0, err } if n == 0 { @@ -1134,7 +1160,7 @@ func (d *DB) percentile(cond string, args []any, col string, p float64) (float64 } idx := int64(float64(n-1) * p) var v sql.NullFloat64 - err := d.sql.QueryRow(`SELECT r.`+col+` FROM requests r WHERE `+cond+` AND r.`+col+` > 0 + err := d.sql.QueryRowContext(d.readCtx(), `SELECT r.`+col+` FROM requests r WHERE `+cond+` AND r.`+col+` > 0 ORDER BY r.`+col+` ASC LIMIT 1 OFFSET ?`, append(append([]any(nil), args...), idx)...).Scan(&v) if err == sql.ErrNoRows { return 0, nil diff --git a/dash/promptapi.go b/dash/promptapi.go index f02b40cf..b6e16d2c 100644 --- a/dash/promptapi.go +++ b/dash/promptapi.go @@ -107,7 +107,7 @@ func (a *API) prompt(w http.ResponseWriter, r *http.Request) { if a.auth != nil { trusted = true } - view, err := a.rec.DB().PromptViewFor(f) + view, err := a.db(r).PromptViewFor(f) if err != nil { httpErr(w, http.StatusInternalServerError, "could not read the prompt text") return @@ -183,7 +183,7 @@ func (d *DB) PromptViewFor(f Filter) (*PromptView, error) { } tq += ` GROUP BY d.session_id, d.kind, d.name, d.server)` var rows, textRows *int - if err := d.sql.QueryRow(tq, ta...).Scan(&rows, &textRows); err != nil { + if err := d.sql.QueryRowContext(d.readCtx(), tq, ta...).Scan(&rows, &textRows); err != nil { return nil, err } if rows != nil { @@ -207,7 +207,7 @@ func (d *DB) PromptViewFor(f Filter) (*PromptView, error) { var tenant, session, digest string var ts int64 var txt int - switch err := d.sql.QueryRow(pq, pa...).Scan(&tenant, &session, &digest, &ts, &txt); { + switch err := d.sql.QueryRowContext(d.readCtx(), pq, pa...).Scan(&tenant, &session, &digest, &ts, &txt); { case err == sql.ErrNoRows: return v, nil // nothing captured in scope at all case err != nil: @@ -224,7 +224,7 @@ func (d *DB) PromptViewFor(f Filter) (*PromptView, error) { FROM tool_declarations d ` + declTextJoin + ` WHERE d.tenant_id = ? AND d.session_id = ? AND d.digest = ?` ra := []any{tenant, session, digest} - rs, err := d.sql.Query(rq, ra...) + rs, err := d.sql.QueryContext(d.readCtx(), rq, ra...) if err != nil { return nil, err } diff --git a/dash/purge.go b/dash/purge.go index b51c1b3a..a0b79096 100644 --- a/dash/purge.go +++ b/dash/purge.go @@ -162,7 +162,7 @@ func (r *Recorder) PurgeTenant(ctx context.Context, tenantID string) (PurgeResul // caller that cannot ask cannot assert it. func (d *DB) TenantHasRows(tenantID string) (bool, error) { var n int64 - err := d.sql.QueryRow(`SELECT + err := d.sql.QueryRowContext(d.readCtx(), `SELECT (SELECT COUNT(*) FROM requests WHERE tenant_id = ?) + (SELECT COUNT(*) FROM archived_sessions WHERE tenant_id = ?) + (SELECT COUNT(*) FROM tenant_spend WHERE tenant_id = ?)`, @@ -175,11 +175,11 @@ func (d *DB) TenantHasRows(tenantID string) (bool, error) { // it exists to catch: a delete that took the parents and left the children belonging to // nobody, which no tenant-scoped query can see. func (d *DB) OrphanRows() (components, content int64, err error) { - if err = d.sql.QueryRow(`SELECT COUNT(*) FROM request_components c + if err = d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM request_components c WHERE NOT EXISTS (SELECT 1 FROM requests r WHERE r.id = c.request_id)`).Scan(&components); err != nil { return 0, 0, err } - err = d.sql.QueryRow(`SELECT COUNT(*) FROM request_content c + err = d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM request_content c WHERE NOT EXISTS (SELECT 1 FROM requests r WHERE r.id = c.request_id)`).Scan(&content) return components, content, err } diff --git a/dash/query.go b/dash/query.go index b4527d39..bd4eb5f4 100644 --- a/dash/query.go +++ b/dash/query.go @@ -193,7 +193,7 @@ func (d *DB) Requests(f Filter, before int64, limit int) (*Page, error) { pageArgs = append(pageArgs, before) } q += " ORDER BY r.id DESC LIMIT ?" - rows, err := d.sql.Query(q, append(pageArgs, limit+1)...) + rows, err := d.sql.QueryContext(d.readCtx(), q, append(pageArgs, limit+1)...) if err != nil { return nil, err } @@ -215,7 +215,7 @@ func (d *DB) Requests(f Filter, before int64, limit int) (*Page, error) { page.Requests = page.Requests[:limit] page.NextCursor = page.Requests[limit-1].ID } - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond, filterArgs...).Scan(&page.Total); err != nil { + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond, filterArgs...).Scan(&page.Total); err != nil { return nil, err } return page, nil @@ -225,12 +225,12 @@ func (d *DB) Requests(f Filter, before int64, limit int) (*Page, error) { // captured, its before/after blobs. withContent=false omits the content entirely // (the caller decides, based on the access gate). func (d *DB) Request(id int64, withContent bool) (*Event, error) { - row := d.sql.QueryRow(`SELECT `+requestCols+` FROM requests r WHERE r.id = ?`, id) + row := d.sql.QueryRowContext(d.readCtx(), `SELECT `+requestCols+` FROM requests r WHERE r.id = ?`, id) e, err := scanRequest(row) if err != nil { return nil, err } - crows, err := d.sql.Query(`SELECT component, kind, acted, mutated, reverted, skipped, + crows, err := d.sql.QueryContext(d.readCtx(), `SELECT component, kind, acted, mutated, reverted, skipped, saved_gross, saved_unique, saved_usd, duration_ms, err, gates, events FROM request_components WHERE request_id = ? ORDER BY rowid`, id) if err != nil { @@ -275,7 +275,7 @@ func (d *DB) Request(id int64, withContent bool) (*Event, error) { // rows (cost, latency, tokens, gate reason, saving) are operational metrics rather than // transcript content, and they are what answers "was this call worth it?". The text // halves are loaded only WITH content access, below. - xrows, err := d.sql.Query(`SELECT component, model, strategy, aggressiveness, cold, escalated, + xrows, err := d.sql.QueryContext(d.readCtx(), `SELECT component, model, strategy, aggressiveness, cold, escalated, candidate_tokens, saved_tokens, prompt_tokens, completion_tokens, cache_read, cache_write, cost_usd, latency_ms, accepted, gate_reason, rejection, summary, before_gz, after_gz FROM extraction_calls WHERE request_id = ? ORDER BY seq`, id) @@ -307,7 +307,7 @@ func (d *DB) Request(id int64, withContent bool) (*Event, error) { if !withContent { return e, nil } - trows, err := d.sql.Query(`SELECT path, before_tokens, after_tokens, before_gz, after_gz, components + trows, err := d.sql.QueryContext(d.readCtx(), `SELECT path, before_tokens, after_tokens, before_gz, after_gz, components FROM request_content WHERE request_id = ? ORDER BY seq`, id) if err != nil { return nil, err @@ -403,7 +403,7 @@ func (d *DB) SessionEventsPage(f Filter, sessionID string, withContent bool, aft q += ` LIMIT ?` pageArgs = append(pageArgs, limit+1) } - rows, err := d.sql.Query(q, pageArgs...) + rows, err := d.sql.QueryContext(d.readCtx(), q, pageArgs...) if err != nil { return nil, err } @@ -439,13 +439,13 @@ func (d *DB) SessionEventsPage(f Filter, sessionID string, withContent bool, aft page.Requests = append(page.Requests, e) } - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests r WHERE `+cond+ + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests r WHERE `+cond+ ` AND r.session_id = ?`, sessArgs...).Scan(&page.Total); err != nil { return nil, err } // Session-wide, not page-wide, and cheap: idx_content_request makes it an index // probe and EXISTS stops at the first hit. - if err := d.sql.QueryRow(`SELECT EXISTS(SELECT 1 FROM requests r + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT EXISTS(SELECT 1 FROM requests r JOIN request_content c ON c.request_id = r.id WHERE `+cond+` AND r.session_id = ?)`, sessArgs...).Scan(&page.HasContent); err != nil { return nil, err @@ -539,7 +539,7 @@ func (d *DB) Sessions(f Filter, limit, offset int) ([]*SessionRow, int64, error) COALESCE(SUM(` + kaSaved("r.") + `),0) FROM requests r WHERE ` + cond + ` GROUP BY r.session_id ORDER BY MAX(r.ts) DESC LIMIT ? OFFSET ?` - rows, err := d.sql.Query(q, append(args, limit, offset)...) + rows, err := d.sql.QueryContext(d.readCtx(), q, append(args, limit, offset)...) if err != nil { return nil, 0, err } @@ -586,7 +586,7 @@ func (d *DB) Sessions(f Filter, limit, offset int) ([]*SessionRow, int64, error) } } var total int64 - err = d.sql.QueryRow(`SELECT COUNT(DISTINCT r.session_id) FROM requests r WHERE `+cond, args...).Scan(&total) + err = d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(DISTINCT r.session_id) FROM requests r WHERE `+cond, args...).Scan(&total) return out, total, err } @@ -598,7 +598,7 @@ type pingCount struct { // pingsBySession groups the ping rows by session. The caller passes a filter that INCLUDES them. func (d *DB) pingsBySession(cond string, args []any) (map[string]pingCount, error) { - rows, err := d.sql.Query(`SELECT r.session_id, COUNT(*), COALESCE(SUM(r.cost_usd),0) + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.session_id, COUNT(*), COALESCE(SUM(r.cost_usd),0) FROM requests r WHERE `+cond+` AND r.keepalive = 1 GROUP BY 1`, args...) if err != nil { return nil, err @@ -754,7 +754,7 @@ func (d *DB) Components(f Filter) ([]*ComponentRow, error) { SUM(CASE WHEN c.err <> '' THEN 1 ELSE 0 END) FROM request_components c JOIN requests r ON r.id = c.request_id WHERE ` + cond + ` GROUP BY c.component ORDER BY SUM(c.saved_unique) DESC, c.component` - rows, err := d.sql.Query(q, args...) + rows, err := d.sql.QueryContext(d.readCtx(), q, args...) if err != nil { return nil, err } @@ -794,7 +794,7 @@ func (d *DB) Components(f Filter) ([]*ComponentRow, error) { AVG(x.latency_ms), SUM(x.saved_tokens) FROM extraction_calls x JOIN requests r ON r.id = x.request_id WHERE ` + cond + ` GROUP BY x.component` - xrows, err := d.sql.Query(xq, args...) + xrows, err := d.sql.QueryContext(d.readCtx(), xq, args...) if err != nil { return nil, err } @@ -845,7 +845,7 @@ func (d *DB) Components(f Filter) ([]*ComponentRow, error) { SUM(r.cg_llm_cost_usd * CASE WHEN tot.tcost > 0 THEN per.ccost / tot.tcost ELSE 0 END) FROM per JOIN tot ON tot.rid = per.rid JOIN requests r ON r.id = per.rid WHERE ` + cond + ` GROUP BY 1` - irows, err := d.sql.Query(iq, args...) + irows, err := d.sql.QueryContext(d.readCtx(), iq, args...) if err != nil { return nil, err } @@ -881,10 +881,25 @@ func (d *DB) Components(f Filter) ([]*ComponentRow, error) { // Gate totals, summed in SQL with json_each rather than by decoding a map per row in // Go: a filtered window is hundreds of thousands of component rows and the gate map is // the widest text on each of them. + // + // CROSS JOIN is an OPTIMISER BARRIER here, not a different join — in SQLite it forbids + // reordering, and that is the entire point. Written as a plain JOIN, the planner drove this + // from request_components (SCAN ... USING INDEX idx_rc_comp: all 1,576,383 rows) and probed + // requests by rowid to apply the time filter afterwards, so a 24-hour window paid for the + // whole table. Pinning requests first makes it SEARCH idx_requests_ts and touch only the + // 303,770 component rows actually in the window. Measured on the production database, warm, + // with identical result rows: 2.862s -> 0.527s for gates, same shape for events, and + // Components() overall 13.2s -> 6.0s. + // + // The plain-JOIN form was ALSO tried with requests written first (FROM requests r JOIN + // request_components c ...) and measured 2.807s — no change, because the planner reorders it + // straight back. Only the barrier holds. Query 1 above needs none: with no json_each + // cross-join to cost around, the planner already picks requests first. gq := `SELECT c.component, j.key, SUM(CAST(j.value AS INTEGER)) - FROM request_components c JOIN requests r ON r.id = c.request_id, json_each(c.gates) j + FROM requests r CROSS JOIN request_components c ON c.request_id = r.id + CROSS JOIN json_each(c.gates) j WHERE ` + cond + ` AND json_valid(c.gates) GROUP BY 1, 2` - grows, err := d.sql.Query(gq, args...) + grows, err := d.sql.QueryContext(d.readCtx(), gq, args...) if err != nil { return nil, err } @@ -915,9 +930,10 @@ func (d *DB) Components(f Filter) ([]*ComponentRow, error) { // duplication is four lines and the alternative is a discriminator column threaded through the // scan. eq := `SELECT c.component, j.key, SUM(CAST(j.value AS INTEGER)) - FROM request_components c JOIN requests r ON r.id = c.request_id, json_each(c.events) j + FROM requests r CROSS JOIN request_components c ON c.request_id = r.id + CROSS JOIN json_each(c.events) j WHERE ` + cond + ` AND json_valid(c.events) GROUP BY 1, 2` - erows, err := d.sql.Query(eq, args...) + erows, err := d.sql.QueryContext(d.readCtx(), eq, args...) if err != nil { return nil, err } @@ -1002,7 +1018,7 @@ func (d *DB) Series(f Filter, bucketMs int64) ([]*Bucket, error) { SUM(r.expands), SUM(r.expand_tokens), SUM(CASE WHEN r.cache_miss_reason NOT IN ('hit','') THEN 1 ELSE 0 END) FROM requests r WHERE %s GROUP BY b ORDER BY b`, bucketMs, bucketMs, cond) - rows, err := d.sql.Query(q, args...) + rows, err := d.sql.QueryContext(d.readCtx(), q, args...) if err != nil { return nil, err } @@ -1150,7 +1166,7 @@ func (d *DB) Breakdown(f Filter, dim string) ([]*GroupRow, error) { COALESCE(SUM(CASE WHEN r.token_accounting <> 'complete' THEN 1 ELSE 0 END),0) FROM requests r WHERE ` + cond + ` GROUP BY k ORDER BY SUM(r.cost_usd) DESC, COUNT(*) DESC, k LIMIT 200` - rows, err := d.sql.Query(q, args...) + rows, err := d.sql.QueryContext(d.readCtx(), q, args...) if err != nil { return nil, err } @@ -1232,7 +1248,7 @@ func (d *DB) Facets(f Filter) (map[string][]string, error) { out := map[string][]string{} for name, col := range facetQueries { cond, args := selfBlanked(f, name).where() - rows, err := d.sql.Query( + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT DISTINCT r.`+col+` FROM requests r WHERE `+cond+` AND r.`+col+` <> '' ORDER BY 1 LIMIT 200`, args...) if err != nil { return nil, err @@ -1257,9 +1273,30 @@ func (d *DB) Facets(f Filter) (map[string][]string, error) { // missing here, which made one tenant's dropdown an enumeration of every component // every OTHER tenant runs. ccond, cargs := selfBlanked(f, "component").where() - rows, err := d.sql.Query(`SELECT DISTINCT c.component - FROM request_components c JOIN requests r ON r.id = c.request_id - WHERE `+ccond+` ORDER BY 1 LIMIT 200`, cargs...) + // Probed once per DISTINCT COMPONENT, not once per component row. + // + // The straightforward join — request_components JOIN requests, DISTINCT the component — + // makes SQLite scan idx_rc_comp and probe the requests primary key for EVERY component row + // to apply a filter that lives on requests. There are 14 distinct components and 155,757 + // component rows on the 16,428-request corpus (1,210,932 on the production one), so that is + // ~11,000 probes per answer it could possibly return. Measured, 5 runs, that corpus: + // 278 ms for the join against 17 ms for the form below, which is 16x, and it is the same + // invocation-count shape as CompactionResets (see overview.go) rather than an I/O problem — + // the plan was already index-driven. + // + // The rewrite asks the question the dropdown actually asks: for each component NAME, does + // any in-scope request carry it? That is 14 EXISTS probes, each stopping at its first match. + // Worst case — a component present in the table but in no in-scope request — degenerates to + // scanning that one component's rows, which is bounded by what the join did unconditionally. + // + // The scoping is unchanged: the join and its predicate are intact inside the EXISTS, which + // is what keeps one tenant's dropdown from enumerating every component every OTHER tenant + // runs (the bug the comment below records). + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT names.component + FROM (SELECT DISTINCT component FROM request_components) names + WHERE EXISTS (SELECT 1 FROM request_components c JOIN requests r ON r.id = c.request_id + WHERE c.component = names.component AND `+ccond+`) + ORDER BY 1 LIMIT 200`, cargs...) if err != nil { return nil, err } diff --git a/dash/readvalue.go b/dash/readvalue.go index 8016172e..8b8dc4d8 100644 --- a/dash/readvalue.go +++ b/dash/readvalue.go @@ -82,7 +82,7 @@ func (d *DB) TierCosts(f Filter, p modelinfo.Pricer) (*TierCosts, error) { // Incomplete accounting is excluded, not priced as zero: Event.Price refuses to price // such a request at all, and an estimate that quietly included them would report a // smaller bill than the one that was billed. - rows, err := d.sql.Query(`SELECT r.model, COUNT(*), + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.model, COUNT(*), COALESCE(SUM(r.fresh_input),0), COALESCE(SUM(r.cache_read),0), COALESCE(SUM(r.cache_write),0), COALESCE(SUM(r.output_tokens),0), COALESCE(SUM(MIN(r.frozen_tokens, r.cache_read)),0), COALESCE(SUM(r.cost_usd),0) @@ -173,7 +173,7 @@ func (d *DB) DecomposeComponentSavedUSD(f Filter, p modelinfo.Pricer, out []*Com const uniq = `min(max(c.saved_unique,0), max(c.saved_gross,0))` // Grouped by whether the row carried a STORED saved_usd, because that is what decides // whether comparing the two is a check or a tautology — see the cross-check note below. - rows, err := d.sql.Query(`SELECT c.component, r.model, + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT c.component, r.model, CASE WHEN r.cache_read > 0 THEN 'read' WHEN r.cache_write > 0 AND r.cache_write >= r.fresh_input THEN 'write' ELSE 'fresh' END, @@ -300,7 +300,7 @@ func (d *DB) EstimateComponentSavedUSD(f Filter, p modelinfo.Pricer, out []*Comp // window-wide average that would flatter warm traffic. const gross = `max(c.saved_gross,0)` const uniq = `min(max(c.saved_unique,0), max(c.saved_gross,0))` - rows, err := d.sql.Query(`SELECT c.component, r.model, + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT c.component, r.model, CASE WHEN r.cache_read > 0 THEN 'read' WHEN r.cache_write > 0 AND r.cache_write >= r.fresh_input THEN 'write' ELSE 'fresh' END, @@ -343,7 +343,7 @@ func (d *DB) EstimateComponentSavedUSD(f Filter, p modelinfo.Pricer, out []*Comp } // Rows that removed tokens but whose request was never priced at all. Counted, not // valued: "we cannot say" and "it was worth nothing" are different answers. - urows, err := d.sql.Query(`SELECT c.component, COUNT(*) + urows, err := d.sql.QueryContext(d.readCtx(), `SELECT c.component, COUNT(*) FROM request_components c JOIN requests r ON r.id = c.request_id WHERE `+cond+` AND c.saved_usd = 0 AND c.saved_gross > 0 AND r.token_accounting <> 'complete' GROUP BY 1`, args...) diff --git a/dash/schema.go b/dash/schema.go index 7a456b1b..ec8d1165 100644 --- a/dash/schema.go +++ b/dash/schema.go @@ -471,6 +471,31 @@ CREATE INDEX IF NOT EXISTS idx_tooldecl_name ON tool_declarations(name); -- the production corpus for a query with no other reason to be slow. CREATE INDEX IF NOT EXISTS idx_tooldecl_session ON tool_declarations(session_id); +-- SelfRemovals' declaration pass (dash/toolapi.go) reads (tenant_id, session_id, kind, name, +-- server, tokens) for every declaration row and reduces them, in Go, to one fact per +-- (tenant, session, kind, name, server). The grain of this table is one row per DIGEST, so +-- that reduction is 33.5:1 on the production corpus — 1,811,405 rows collapsing to 54,030. +-- +-- This index makes the reduction SQL's job instead of Go's. Its column order is exactly the +-- GROUP BY, so SQLite streams the groups out of the index in order: no temp b-tree, and no +-- table fetch, because the index carries the only six columns the query wants. That matters +-- because this table is the widest in the schema — 695 MB of pages on production against +-- 205 MB for this index, most of the difference being digest, text_hash and the free space +-- left behind when text_gz moved to declaration_text. +-- +-- Measured on a synthetic corpus built to production's cardinalities (1,843,616 rows, +-- 54,224 distinct groups, 280 MB primary-key index against production's 286 MB), median of +-- 3 runs: the shipped full scan 4,498 ms; a GROUP BY WITHOUT this index 10,749 ms, worse, +-- because it sorts into a temp b-tree; the GROUP BY WITH it 1,229 ms. So the index and the +-- GROUP BY only pay TOGETHER — either alone is neutral or a regression. Adding the index +-- without changing the query leaves the plan on the table scan (measured 3,636 ms), which is +-- the same trap idx_requests_session_tb fell into below. +-- CROSS-FILE INVARIANT: this index is load-bearing for the GROUP BY in SelfRemovals +-- (dash/toolapi.go). Dropping it does not merely slow that query down, it makes it 2.4x SLOWER +-- than the plain scan it replaced. The two ship together or not at all. +CREATE INDEX IF NOT EXISTS idx_tooldecl_inventory + ON tool_declarations(tenant_id, session_id, kind, name, server, tokens); + -- What a session actually INVOKED: one row per distinct tool name (and, for the Skill -- tool, per skill — input.skill is the only place a skill invocation is identifiable, -- since the Skill tool's schema carries no enum). Counted from the LAST tool-using turn diff --git a/dash/spend.go b/dash/spend.go index f6621fcb..f54694ed 100644 --- a/dash/spend.go +++ b/dash/spend.go @@ -42,7 +42,7 @@ import ( // be. func (d *DB) MonthToDateUSD(tenantID string) (float64, error) { var usd float64 - err := d.sql.QueryRow(`SELECT usd FROM tenant_spend WHERE tenant_id = ? AND month = ?`, + err := d.sql.QueryRowContext(d.readCtx(), `SELECT usd FROM tenant_spend WHERE tenant_id = ? AND month = ?`, tenantID, monthKey(time.Now().UnixMilli())).Scan(&usd) if errors.Is(err, sql.ErrNoRows) { return 0, nil diff --git a/dash/store.go b/dash/store.go index f9e53a70..3358238a 100644 --- a/dash/store.go +++ b/dash/store.go @@ -553,7 +553,7 @@ func (d *DB) Prune(now time.Time, maxAge time.Duration, maxBytes int64) (int64, return deleted, err } var total int64 - if err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests`).Scan(&total); err != nil { + if err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests`).Scan(&total); err != nil { return deleted, err } if total == 0 { @@ -595,10 +595,10 @@ func (d *DB) Prune(now time.Time, maxAge time.Duration, maxBytes int64) (int64, // have nothing to look at). func (d *DB) sizeBytes() (int64, error) { var pages, pageSize int64 - if err := d.sql.QueryRow(`PRAGMA page_count`).Scan(&pages); err != nil { + if err := d.sql.QueryRowContext(d.readCtx(), `PRAGMA page_count`).Scan(&pages); err != nil { return 0, err } - if err := d.sql.QueryRow(`PRAGMA page_size`).Scan(&pageSize); err != nil { + if err := d.sql.QueryRowContext(d.readCtx(), `PRAGMA page_size`).Scan(&pageSize); err != nil { return 0, err } total := pages * pageSize @@ -625,7 +625,7 @@ func (d *DB) reclaim() error { // then reads its own progress backwards and deletes again. d.checkpoint() var mode int - if err := d.sql.QueryRow(`PRAGMA auto_vacuum`).Scan(&mode); err == nil && mode == 2 { + if err := d.sql.QueryRowContext(d.readCtx(), `PRAGMA auto_vacuum`).Scan(&mode); err == nil && mode == 2 { if _, err := d.sql.Exec(`PRAGMA incremental_vacuum(2000)`); err != nil { return err } @@ -646,6 +646,35 @@ func (d *DB) checkpoint() { _, _ = d.sql.Exec(`PRAGMA wal_checkpoint(TRUNCATE)`) } +// optimize refreshes the query planner's statistics for tables whose statistics are missing or +// stale. Called from the janitor's recurring pass; see janitorPass for the measurement and for +// why it is not done at Open. +// +// The 0x10002 MASK IS LOAD-BEARING and a bare `PRAGMA optimize` here is a silent no-op. 0x00002 is +// "run ANALYZE where it would help"; 0x10000 is what lifts the restriction that a table must have +// been queried BY THIS CONNECTION to be considered. The janitor takes a fresh connection from the +// pool and runs no queries of its own, so under the default mask SQLite correctly concludes this +// connection has used nothing and analyses nothing. Measured on a copy of the production database, +// on a cold connection: bare `PRAGMA optimize` completes in 0.00s and leaves sqlite_stat1 absent; +// `PRAGMA optimize(0x10002)` produces all 26 statistic rows, also in 0.00s. +// +// It is fast because it SAMPLES rather than doing a full scan — which is the whole reason it can +// live on a recurring pass, where a bare ANALYZE (72s on this database) could not. The sampled +// statistics are good enough for the decision that actually matters here, join order: with them the +// component aggregate plans as SEARCH requests USING idx_requests_ts -> SEARCH request_components +// USING idx_rc_request and runs in 0.209s, against 2.0s and a full 1.58M-row scan without them. +// +// Errors are logged rather than returned: out-of-date statistics make queries slower, never wrong, +// so a failure here must not stop the rest of a janitor pass. +func (d *DB) optimize() { + if d.path == "" || d.path == ":memory:" { + return + } + if _, err := d.sql.Exec(`PRAGMA optimize(0x10002)`); err != nil { + slog.Warn("dash: PRAGMA optimize failed; query plans will use whatever statistics exist", "err", err) + } +} + // DropOldestSessions deletes the n least-recently-active SESSIONS and returns how // many request rows went with them. Component and content rows follow via // ON DELETE CASCADE. @@ -678,7 +707,7 @@ func (d *DB) DropOldestSessions(n int) (int64, error) { // traffic evict everyone else's history, which is the shared-service failure where the // person causing the problem is the last to notice it. func (d *DB) TenantRowCounts() (map[string]int64, error) { - rows, err := d.sql.Query(`SELECT tenant_id, COUNT(*) c FROM requests + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT tenant_id, COUNT(*) c FROM requests WHERE tenant_id <> '' GROUP BY tenant_id ORDER BY c DESC`) if err != nil { return nil, err @@ -699,7 +728,7 @@ func (d *DB) TenantRowCounts() (map[string]int64, error) { // tenantRowCount counts one tenant's request rows. func (d *DB) tenantRowCount(tenant string) (int64, error) { var n int64 - err := d.sql.QueryRow(`SELECT COUNT(*) FROM requests WHERE tenant_id = ?`, tenant).Scan(&n) + err := d.sql.QueryRowContext(d.readCtx(), `SELECT COUNT(*) FROM requests WHERE tenant_id = ?`, tenant).Scan(&n) return n, err } diff --git a/dash/toolapi.go b/dash/toolapi.go index 18c53cd6..8e0d37a5 100644 --- a/dash/toolapi.go +++ b/dash/toolapi.go @@ -21,6 +21,7 @@ package dash import ( "database/sql" + "encoding/json" "log/slog" "net/http" "sort" @@ -373,7 +374,7 @@ func (d *DB) ToolReportFor(f Filter, price func(string) (modelinfo.Price, bool)) where, args := f.where() // Sessions in scope, their re-read multiplier and the tiers they paid. tools>0 // because a request that declared nothing has no inventory to be missing. - rows, err := d.sql.Query(`SELECT r.session_id, r.model, + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.session_id, r.model, SUM(CASE WHEN r.cache_read > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN r.cache_read = 0 AND r.cache_write > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN r.cache_read = 0 AND r.cache_write = 0 THEN 1 ELSE 0 END) @@ -456,7 +457,7 @@ func (d *DB) scopedDecls(f Filter, where string, args []any) ([]declRow, error) a = append(a, f.Tenant) } q += ` GROUP BY 1, 2, 3, 4` - rows, err := d.sql.Query(q, a...) + rows, err := d.sql.QueryContext(d.readCtx(), q, a...) if err != nil { return nil, err } @@ -485,7 +486,7 @@ func (d *DB) scopedUses(f Filter, where string, args []any) ([]useRow, error) { a = append(a, f.Tenant) } q += ` GROUP BY 1, 2, 3` - rows, err := d.sql.Query(q, a...) + rows, err := d.sql.QueryContext(d.readCtx(), q, a...) if err != nil { return nil, err } @@ -902,33 +903,34 @@ func (a *API) MountTools(m *http.ServeMux) { // to one session (through the standard filter, so an id belonging to someone else // simply selects nothing rather than 403-ing and confirming that it exists). func (a *API) tools(w http.ResponseWriter, r *http.Request) { - f, _, ok := a.scope(r) + f, p, ok := a.scope(r) if !ok { unauthorized(w) return } price := a.priceFn(r) - rep, err := a.rec.DB().ToolReportFor(f, price) - if err != nil { - httpErr(w, http.StatusInternalServerError, "could not read the tool inventory") - return - } - // Credit for what the USER removed themselves. Best-effort and non-fatal: it is an - // addition to the report, so a deployment where it fails still gets the inventory rather - // than an error page. Needs a pricer to put a dollar on, and the token counts stand - // without one. - if price != nil { - // The account's own server-side removal list, so a reduction that the tool filter is - // ALREADY credited for can be marked as overlapping instead of counted twice. - sr, err := a.rec.DB().SelfRemovals(f, price, a.toolFilterStateForScope(f).Removed) + a.serveJSON(w, r, &a.toolsCache, cacheKey(p, r), func(db *DB) ([]byte, error) { + rep, err := db.ToolReportFor(f, price) if err != nil { - // Non-fatal, but never silent: swallowing this returned an empty list that was - // indistinguishable from "the account removed nothing", which is a claim. - slog.Warn("dash: self-removal credit unavailable", "err", err) + return nil, err } - rep.SelfRemoved = sr - } - writeJSON(w, rep) + // Credit for what the USER removed themselves. Best-effort and non-fatal: it is an + // addition to the report, so a deployment where it fails still gets the inventory rather + // than an error page. Needs a pricer to put a dollar on, and the token counts stand + // without one. + if price != nil { + // The account's own server-side removal list, so a reduction that the tool filter is + // ALREADY credited for can be marked as overlapping instead of counted twice. + sr, err := db.SelfRemovals(f, price, a.toolFilterStateForScope(f).Removed) + if err != nil { + // Non-fatal, but never silent: swallowing this returned an empty list that was + // indistinguishable from "the account removed nothing", which is a claim. + slog.Warn("dash: self-removal credit unavailable", "err", err) + } + rep.SelfRemoved = sr + } + return json.Marshal(rep) + }) } // priceFn resolves a model's rates for the duration of one request, or nil when the @@ -949,7 +951,7 @@ func (a *API) priceFn(r *http.Request) func(string) (modelinfo.Price, bool) { // countInventoryRows is a test and diagnostic helper: how many inventory rows exist. func (d *DB) countInventoryRows() (decls, uses int64, err error) { - err = d.sql.QueryRow(`SELECT + err = d.sql.QueryRowContext(d.readCtx(), `SELECT (SELECT COUNT(*) FROM tool_declarations), (SELECT COUNT(*) FROM tool_uses)`).Scan(&decls, &uses) if err == sql.ErrNoRows { @@ -997,7 +999,7 @@ func (d *DB) SelfRemovals(f Filter, price func(string) (modelinfo.Price, bool), model string hasMCP, hasSkills bool } - srows, err := d.sql.Query(`SELECT r.tenant_id, r.session_id, MIN(r.ts), + srows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.tenant_id, r.session_id, MIN(r.ts), SUM(CASE WHEN r.cache_read > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN r.cache_read = 0 AND r.cache_write > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN r.cache_read = 0 AND r.cache_write = 0 THEN 1 ELSE 0 END), @@ -1042,13 +1044,32 @@ func (d *DB) SelfRemovals(f Filter, price func(string) (modelinfo.Price, bool), // join condition, and the candidate + cohort aggregation happen in the same pass. Filtered by // tenant_id in SQL when the caller is scoped to one account — the common case — so a // per-account view still only ever touches that account's own rows, exactly as before. - dq := `SELECT tenant_id, session_id, kind, name, server, tokens FROM tool_declarations` + // Reduced in SQL, not in Go. The loop below keeps MAX(tokens) per candidate and a SET of + // session ids, so feeding it one row per digest and letting it collapse them was 33.5 rows + // of work per fact it kept: 1,811,405 declaration rows for 54,030 distinct + // (tenant, session, kind, name, server) on the production corpus. GROUP BY in the same + // column order as idx_tooldecl_inventory (see schema.go) makes this an ordered scan of a + // covering index — no temp b-tree, no table fetch — and hands Go the 54k facts instead of + // the 1.8M rows. Measured on a corpus built to production's cardinalities: 4,498 ms to + // 1,229 ms, and 10,749 ms if the GROUP BY runs WITHOUT the index, so the two ship together. + // + // CROSS-FILE INVARIANT: this GROUP BY and idx_tooldecl_inventory in schema.go are only + // correct together and either half alone is a regression -- the index without the GROUP BY + // leaves the plan on the table scan (3,636 ms, buys nothing), the GROUP BY without the index + // sorts into a temp b-tree (10,749 ms, 2.4x SLOWER than the scan it replaced). Removing + // either half looks independently safe and is not. + // + // `started` is deliberately NOT in this SELECT: it comes from the requests-side sessByKey + // lookup below, not from this table. Adding MAX(started) here without also adding it to the + // GROUP BY would silently change the grouping -- the same trap in the other direction. + dq := `SELECT tenant_id, session_id, kind, name, server, MAX(tokens) FROM tool_declarations` var dargs []any if !f.TenantAll { dq += ` WHERE tenant_id = ?` dargs = append(dargs, f.Tenant) } - drows, err := d.sql.Query(dq, dargs...) + dq += ` GROUP BY tenant_id, session_id, kind, name, server` + drows, err := d.sql.QueryContext(d.readCtx(), dq, dargs...) if err != nil { return nil, err } diff --git a/dash/toolsuggest.go b/dash/toolsuggest.go index 374e58cf..0760e716 100644 --- a/dash/toolsuggest.go +++ b/dash/toolsuggest.go @@ -48,6 +48,7 @@ package dash // Basis string says so in words. import ( + "encoding/json" "errors" "fmt" "net/http" @@ -163,7 +164,7 @@ type ToolFilterState struct { // to none. func (d *DB) DeclFilterSavings(f Filter, price func(string) (modelinfo.Price, bool)) (*DeclFilterSaving, error) { where, args := f.where() - rows, err := d.sql.Query(`SELECT r.session_id, r.model, r.filtered_decl_tokens, + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.session_id, r.model, r.filtered_decl_tokens, r.cache_read, r.cache_write, r.ts FROM requests r WHERE `+where+` AND r.filtered_decl_tokens > 0`, args...) if err != nil { @@ -233,7 +234,7 @@ func accumulateDeclFilterRow(out *DeclFilterSaving, sessions map[string]bool, // (dash/cachehistory.go) for why a query per tenant re-pays the same table scan N times over. func (d *DB) DeclFilterSavingsByTenant(since int64, price func(string) (modelinfo.Price, bool)) (map[string]*DeclFilterSaving, error) { cond, args := (Filter{Since: since, TenantAll: true}).where() - rows, err := d.sql.Query(`SELECT r.tenant_id, r.session_id, r.model, r.filtered_decl_tokens, + rows, err := d.sql.QueryContext(d.readCtx(), `SELECT r.tenant_id, r.session_id, r.model, r.filtered_decl_tokens, r.cache_read, r.cache_write, r.ts FROM requests r WHERE `+cond+` AND r.filtered_decl_tokens > 0`, args...) if err != nil { @@ -286,7 +287,7 @@ func (d *DB) declWindows(f Filter) (map[statKey]declWindow, error) { a = append(a, f.Tenant) } q += ` GROUP BY 1, 2` - rows, err := d.sql.Query(q, a...) + rows, err := d.sql.QueryContext(d.readCtx(), q, a...) if err != nil { return nil, err } @@ -544,7 +545,7 @@ func (a *API) ToolFilterDocument(r *http.Request) (*ToolFilterDoc, error) { if !ok { return nil, errNotPermitted } - return a.rec.DB().ToolFilterDocFor(f, a.priceFn(r), a.toolFilterStateForScope(f)) + return a.db(r).ToolFilterDocFor(f, a.priceFn(r), a.toolFilterStateForScope(f)) } // errNotPermitted is returned to a caller that has no scope, so the control plane can tell @@ -553,15 +554,18 @@ var errNotPermitted = errors.New("not permitted") // toolFilter serves the removal control document for the caller's scope. func (a *API) toolFilterDoc(w http.ResponseWriter, r *http.Request) { - f, _, ok := a.scope(r) + f, p, ok := a.scope(r) if !ok { unauthorized(w) return } - doc, err := a.rec.DB().ToolFilterDocFor(f, a.priceFn(r), a.toolFilterStateForScope(f)) - if err != nil { - httpErr(w, http.StatusInternalServerError, "could not read the removal report") - return - } - writeJSON(w, doc) + price := a.priceFn(r) + state := a.toolFilterStateForScope(f) + a.serveJSON(w, r, &a.toolFilterCache, cacheKey(p, r), func(db *DB) ([]byte, error) { + doc, err := db.ToolFilterDocFor(f, price, state) + if err != nil { + return nil, err + } + return json.Marshal(doc) + }) } diff --git a/dash/ui/app.js b/dash/ui/app.js index d05c95ef..2fc2e2b3 100644 --- a/dash/ui/app.js +++ b/dash/ui/app.js @@ -194,6 +194,21 @@ const state = { // that no longer repaints itself every ten seconds: the reader can always see how old // what they are looking at is, and whether refreshing would change it. See initRefresh. loadedAt: 0, + // lastTryAt is when a load last FINISHED, succeeded or not, and loadingOverview is whether one is + // in flight. They exist because loadedAt alone cannot pace the timer: it only advances on + // success, so once a load started failing the timer's own backoff guards — which both measure + // `now - loadedAt` — were permanently satisfied and it re-fired on every 5s tick instead of every + // 5 minutes. Worse, the repaint error path calls markDirty(), which set dirty and so ALSO removed + // the staleness cap that was the second brake. A dashboard left open therefore hammered two + // expensive endpoints 12x a minute for as long as they kept failing, which is how a slow query + // became a service-wide outage. + // + // They are separate from loadedAt rather than a redefinition of it because loadedAt has a second + // job: paintFreshness() reports it to the reader as "Updated 3m ago", and that line must keep + // meaning "when the numbers on screen were fetched". Pacing and freshness are two different + // questions and one timestamp cannot answer both honestly. + lastTryAt: 0, + loadingOverview: false, dirty: false, // The time range, Grafana's model: `from` and `to` are each EITHER a relative token // ('now-6h', 'now') or an absolute epoch-ms number. 0 means unbounded, which is what @@ -2018,6 +2033,7 @@ async function loadOverview(opts = {}) { // moves. `silent` is implicit rather than a caller's flag: having data already IS the // condition, so no call site has to remember. const first = !state.overview; + state.loadingOverview = true; if (first) loadingState($('#tiles'), 4); const scroll = window.scrollY; try { @@ -2074,6 +2090,13 @@ async function loadOverview(opts = {}) { // the old code replaced the tiles with an error state, so one blip wiped the numbers. if (!first) { markDirty(); return; } errorState($('#tiles'), 'Could not load statistics', err); + } finally { + // In `finally`, so a failure and an abort pace the timer exactly like a success does. Every + // early `return` above — including the abort check at the top of the catch — passes through + // here, which is the point: there is no exit from this function that leaves the timer believing + // no attempt was made. + state.loadingOverview = false; + state.lastTryAt = Date.now(); } } @@ -5784,7 +5807,17 @@ function initRefresh() { // `dirty` is the same argument applied to a window that CAN: no captured request means // no changed rollup, and the SSE stream already tells us. if (busyReading()) return; // try again on the next tick; the button is always available - const age = Date.now() - state.loadedAt; + // Never stack. A load slower than this tick would otherwise have another started on top of it + // every 5s, and since a failing load is also a SLOW one, the failure case stacked hardest: an + // abandoned request still costs the server a connection and a full query, so a pileup on the + // client is a pileup on the server. + if (state.loadingOverview) return; + // Paced on the last ATTEMPT, not the last success. Using loadedAt here is what let a failing + // dashboard poll every 5s forever: it only advances when a load works, so `age` grew without + // bound and both of these guards stopped guarding. lastTryAt advances in loadOverview's + // `finally`, so a run of failures backs off to the reader's chosen interval exactly like a run + // of successes. + const age = Date.now() - Math.max(state.loadedAt, state.lastTryAt); if (age < every) return; // The staleness cap, and it is the honest half of this design. // diff --git a/dash/uirefreshpacing_test.go b/dash/uirefreshpacing_test.go new file mode 100644 index 00000000..c6ffbb26 --- /dev/null +++ b/dash/uirefreshpacing_test.go @@ -0,0 +1,89 @@ +package dash + +// Static checks over the Overview refresh timer's pacing. +// +// These are source-level assertions for the same reason the keep-alive and inventory ones are: +// the bug they guard is invisible on screen. A dashboard whose retry pacing has broken looks +// exactly like a dashboard that is working — the reader sees an error or a stale number either +// way — and the damage lands on the SERVER, as a request rate nobody watching the page can see. +// +// The outage that earned them: the timer ticks every 5s and gated on `now - state.loadedAt`, +// which advances only when a load SUCCEEDS. So the first failing load left `age` growing without +// bound, both backoff guards permanently satisfied, and every open tab re-firing two expensive +// queries every 5 seconds instead of every 5 minutes — for hours. Because reads were also +// uncancellable server-side, each of those abandoned requests kept a pooled connection and ran +// its query to completion, which took the process to its memory cap and made every subsequent +// query slower, producing more failures. One line of client pacing sat at the head of that loop. + +import ( + "regexp" + "strings" + "testing" +) + +// The timer must pace on the last ATTEMPT and must not stack overlapping loads. +func TestOverviewRefreshPacesOnAttemptsNotSuccesses(t *testing.T) { + src := readUI(t, "ui/app.js") + + // The tick body, from the interval callback to its 5000ms period. Scoping the assertions to + // it matters: `loadedAt` legitimately appears elsewhere (paintFreshness reports it to the + // reader), so a whole-file search would pass on the wrong occurrence. + tick := regexp.MustCompile(`(?s)setInterval\(\(\) => \{\s*const every = refreshMs\(\);.*?\}, 5000\);`). + FindString(src) + if tick == "" { + t.Fatal("could not find the Overview refresh tick (setInterval ... refreshMs ... 5000);\n" + + "if the timer was restructured, this check needs rewriting against whatever replaced it") + } + + if !strings.Contains(tick, "state.loadingOverview") { + t.Error("the refresh tick does not check state.loadingOverview.\n" + + "Without it a load slower than the 5s tick has another started on top of it every tick. " + + "A failing load is also a slow one, so the failure case stacks hardest, and an " + + "abandoned request still costs the server a connection and a whole query.") + } + if !strings.Contains(tick, "state.lastTryAt") { + t.Error("the refresh tick does not consult state.lastTryAt.\n" + + "Pacing on state.loadedAt alone is the outage: it advances only on success, so a " + + "failing dashboard polls every 5s forever instead of backing off to the reader's interval.") + } + // The guard has to be the MAXIMUM of the two. Pacing on lastTryAt alone would be correct for + // backoff but would stop honouring a successful load's freshness; taking loadedAt alone is + // the original bug. + if !regexp.MustCompile(`Math\.max\(state\.loadedAt, state\.lastTryAt\)`).MatchString(tick) { + t.Error("the tick's age is not Math.max(state.loadedAt, state.lastTryAt).\n" + + "Both matter: loadedAt is freshness of what is on screen, lastTryAt is when we last " + + "tried. Dropping either one reintroduces a poll rate no reader asked for.") + } +} + +// lastTryAt must be advanced on EVERY exit from loadOverview, which in practice means `finally`. +// +// Asserted separately from the tick because this is the half that is easy to get subtly wrong: +// setting it at the end of the try block, or in the catch, leaves the abort path (`if +// (aborted(err)) return;`) and any future early return recording no attempt — and one uncounted +// exit is enough to restore the 5s hammer. +func TestLoadOverviewRecordsEveryAttempt(t *testing.T) { + src := readUI(t, "ui/app.js") + body := regexp.MustCompile(`(?s)async function loadOverview\(opts = \{\}\) \{.*?\n\}\n`).FindString(src) + if body == "" { + t.Fatal("could not find loadOverview(); this check needs rewriting against whatever replaced it") + } + fin := strings.LastIndex(body, "} finally {") + if fin < 0 { + t.Fatal("loadOverview has no `finally` block.\n" + + "state.lastTryAt and state.loadingOverview must be settled on every exit, including the " + + "abort early-return inside the catch. Only `finally` covers all of them.") + } + tail := body[fin:] + for _, want := range []string{"state.loadingOverview = false", "state.lastTryAt = Date.now()"} { + if !strings.Contains(tail, want) { + t.Errorf("loadOverview's `finally` does not contain %q.\n"+ + "Recording the attempt anywhere else leaves an exit path that tells the timer no "+ + "attempt was made, and the 5s retry storm comes back.", want) + } + } + if !strings.Contains(body, "state.loadingOverview = true") { + t.Error("loadOverview never sets state.loadingOverview = true, so the tick's " + + "anti-stacking guard can never fire.") + } +} diff --git a/dash/zz_perf_test.go b/dash/zz_perf_test.go index 5dcb249a..498b83b1 100644 --- a/dash/zz_perf_test.go +++ b/dash/zz_perf_test.go @@ -2,10 +2,47 @@ package dash import ( "fmt" + "strings" "testing" "time" ) +// Three measured counter-examples to "a correlated subquery is the slow shape", collected +// here because this package keeps rediscovering the same lesson from the wrong end. The cost of +// a correlated subquery is its INVOCATION COUNT, which is set by how selective the OUTER +// predicate is and by where that predicate sits — not by the subquery being correlated. +// +// 1. CompactionResets' outer filter (tokens_before > 0) matched ~100% of rows, so the subquery +// ran 65k+ times and a covering index changed the plan without moving the measured time at +// all. A LAG window function took ~25s to ~3.3s. Correlated form lost. +// 2. ReplayProjectedTokens looks identical in shape, and the same rewrite makes it WORSE: +// byte-identical result, consistently 50-70% slower on live data (0.9s correlated against +// 1.5s windowed, 5 runs), because its outer filter (saved_unique > 0) matches only 8.5% of +// rows — so the subquery runs for that 8.5% while a window function must still sort the +// whole table first. Correlated form won. See the comment at that query. +// 3. Predicate ORDER inside one AND is worth more than either: in kaSaved (dash/keepalive.go) +// the cheap `keepalive_saved_usd > 0` guard placed before the reachability EXISTS makes a +// full-table SUM 314 ms; placed after it, the identical answer takes 61.9 SECONDS. 197x, +// from moving one term. That expression is now inlined at ten read sites — do not let a +// tidy-up normalise the order. +// +// A fourth, added on the same sweep: splitMoved's two correlated LIMIT-1 subqueries rewritten as +// a LAG over only the non-zero rows is byte-identical and WITHIN NOISE on time (80.3 vs 94.1 ms, +// then 77.6 vs 71.9 ms, two 5-run passes). Rejected. Three of the four say do not rewrite it. +// +// And one that cuts the other way, so the lesson is not "never touch a window function": +// CompactionResets' CTE selected `r.*` and carried ~56 columns through the PARTITION BY sort to +// produce one LAG value per row. Narrowing it to (id, prev) and joining back on the primary key +// is 242-316 ms to 59-63 ms here and 1,324 ms to 553 ms on production. That trade ADDS ~16k +// primary-key probes and still wins, which is the exact opposite of Facets' component list +// (query.go), where removing ~1.2M probes is the whole win. So: +// +// Measure the selectivity of the outer predicate before reaching for a window function, and put +// the cheap term first. Then ask which of the two costs you are actually paying -- invocation +// count or sort payload -- because in this package both have won, and the shape of the query +// does not tell you which. An index that leaves the plan alone buys nothing, and a plan change +// that leaves the dominant cost alone buys nothing either. + // The gate aggregation expands request_components through json_each, so it could have // turned a dashboard load into a table scan. // @@ -73,3 +110,54 @@ func TestOverviewStaysFastOnALargeWindow(t *testing.T) { t.Errorf("too slow overall: overview %v, components %v", overview, comps) } } + +// Both of the query-cost fixes in this package are PLAN changes whose whole value is a lower +// invocation count, and both are the kind of thing a later tidy-up reverts by accident while +// keeping the results identical. A timing assertion cannot catch that at test-fixture size, so +// this asserts the plan instead — which is also the check the CompactionResets round taught +// this package to run: an index that leaves the plan alone buys nothing (dash/CLAUDE.local.md, +// and idx_requests_session_tb in schema.go, which measurably did nothing). +func TestQueryPlansStayOnTheCheapShape(t *testing.T) { + db := openTestDB(t) + plan := func(q string, args ...any) string { + rows, err := db.sql.Query("EXPLAIN QUERY PLAN "+q, args...) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + var out string + for rows.Next() { + var a, b, c int + var detail string + if err := rows.Scan(&a, &b, &c, &detail); err != nil { + t.Fatal(err) + } + out += detail + "\n" + } + return out + } + // Facets' component list must not probe the requests primary key once per component row. + // Measured on the production database read-only, 1,210,932 component rows for 12 distinct + // components: 1,533 ms for the per-row form against 73 ms for this one. + cond, args := selfBlanked(Filter{TenantAll: true}, "component").where() + got := plan(`SELECT names.component + FROM (SELECT DISTINCT component FROM request_components) names + WHERE EXISTS (SELECT 1 FROM request_components c JOIN requests r ON r.id = c.request_id + WHERE c.component = names.component AND `+cond+`) + ORDER BY 1 LIMIT 200`, args...) + if !strings.Contains(got, "CORRELATED SCALAR SUBQUERY") { + t.Errorf("Facets' component list is no longer probed per distinct component:\n%s", got) + } + // SelfRemovals' declaration pass must group off idx_tooldecl_inventory. Without that index + // the same GROUP BY sorts into a temp b-tree and is 2.4x SLOWER than the scan it replaced + // (10,192 ms against 4,189 ms on a corpus built to production's cardinalities), so the + // index and the GROUP BY are only correct together. + got = plan(`SELECT tenant_id, session_id, kind, name, server, MAX(tokens) FROM tool_declarations + GROUP BY tenant_id, session_id, kind, name, server`) + if !strings.Contains(got, "COVERING INDEX idx_tooldecl_inventory") { + t.Errorf("SelfRemovals' declaration pass is not covered by idx_tooldecl_inventory:\n%s", got) + } + if strings.Contains(got, "TEMP B-TREE") { + t.Errorf("SelfRemovals' declaration pass sorts into a temp b-tree:\n%s", got) + } +} diff --git a/deploy/service/context-guru.service b/deploy/service/context-guru.service index beaea0d8..edb10430 100644 --- a/deploy/service/context-guru.service +++ b/deploy/service/context-guru.service @@ -146,5 +146,26 @@ LimitNOFILE=65536 MemoryMax=8G TasksMax=4096 +# GOMEMLIMIT must be set whenever MemoryMax is, and this deployment is the proof. +# +# Go's garbage collector sizes the heap against its OWN target and knows nothing about a cgroup +# limit. So a process under MemoryMax grows until the KERNEL starts refusing it memory, and then +# behaves at its worst: the GC keeps chasing a heap goal the cgroup will not allow, the kernel +# reclaims continuously to keep it under the cap, and the two fight. Measured on this box, live: +# 6.8 GB of Go heap against the 8 G cap, 3.66 cores burned continuously with the CPU spread evenly +# across twelve threads (the GC's own signature, not an application loop), for 28 hours. Every +# dashboard query ran inside that, which is why they crossed their 10s timeout. +# +# 7 GiB leaves the ~1 GB of headroom the cap needs for everything that is not Go heap — thread +# stacks, the rclone child, page cache the process has dirtied — while giving the GC a ceiling it +# can actually aim at, so it collects harder instead of being throttled by the kernel. +# +# Honest about what this is: a SEATBELT, not the cure. It converts "kernel reclaim thrash, and an +# OOM kill if the burst is sharp enough" into "known, bounded GC pressure". If the real working set +# genuinely exceeds the limit, it relocates the thrash rather than removing it. What removes it is +# not needing the memory — bounding read concurrency and cancelling reads whose caller has gone +# (dash/store.go, dash/api.go), which is where the 6.8 GB actually came from. +Environment=GOMEMLIMIT=7GiB + [Install] WantedBy=multi-user.target diff --git a/proxy/promexport.go b/proxy/promexport.go index 192d8f8b..7998c612 100644 --- a/proxy/promexport.go +++ b/proxy/promexport.go @@ -39,9 +39,22 @@ import ( // they are cached for a scrape interval — Grafana will scrape every 15s and a query // per scrape per tenant would make observability the load. -// promCacheTTL bounds how stale per-tenant series may be. Just under a typical 15s -// scrape so consecutive scrapes do not serve one cached copy twice. -const promCacheTTL = 10 * time.Second +// promCacheTTL is how old a rendered exposition may get before a scrape triggers a refresh. +// +// It was 10s, chosen as "just under a typical 15s scrape so consecutive scrapes do not serve one +// cached copy twice". That reasoning inverts: a TTL SHORTER than the scrape interval guarantees +// the cached body is always already expired when a scrape arrives, so the cache never serves a +// single scrape and every scrape pays a full render. Once a render exceeded the 10s scrape_timeout +// that became a permanent outage — every scrape rendering from scratch, being cut off at 10s by +// the TimeoutHandler in Mux, and returning 503 — which is exactly how this deployment's Grafana +// went blank while the exposition itself was perfectly healthy. +// +// So the TTL is now comfortably LONGER than a scrape interval, and staleness is handled by serving +// the last good body while a refresh happens behind it (see metricsHandler). Prometheus timestamps +// a sample when it scrapes, so a body one refresh old costs a little resolution; a body that never +// arrives costs the whole dashboard. cg_metrics_age_seconds publishes the difference so it can be +// seen and alerted on rather than guessed at. +const promCacheTTL = 60 * time.Second // Refusals: every way a request can be turned away before it reaches an upstream. // @@ -196,6 +209,11 @@ type promCache struct { mu sync.Mutex at time.Time body string + // took is how long the last render actually needed. Exported beside the body's age because the + // two together are the whole diagnosis when this endpoint misbehaves: a rising age with a small + // duration means the refresher is not running, and an age pinned near the duration means + // rendering has grown past the interval and the numbers are as fresh as they can be. + took time.Duration } // metricsHandler serves the Prometheus endpoint. @@ -210,39 +228,95 @@ func (h *Handler) metricsHandler(w http.ResponseWriter, r *http.Request) { "/metrics is a service-wide view; scrape it from loopback or set METRICS_TOKEN"}) return } - h.promCache.mu.Lock() - if time.Since(h.promCache.at) < promCacheTTL && h.promCache.body != "" { - body := h.promCache.body - h.promCache.mu.Unlock() - writeMetrics(w, body) + body, age, took := h.promSnapshot() + if body != "" && age < promCacheTTL { + writeMetrics(w, body, age, took) return } - h.promCache.mu.Unlock() - // SINGLE-FLIGHT, not a bare re-render: rendering used to happen OUTSIDE any lock, on the - // stated assumption that a cache-miss race costs "at most one redundant render." That - // held only while a render finishes faster than requests arrive. Once real write - // contention (this driver blocks a read across the writer's whole open transaction — - // see CLAUDE.local.md) pushes a render's own time past that interval, EVERY request - // during the slow render sees the same stale cache and starts ANOTHER render — and more - // concurrent renders competing for the same bounded connection pool makes each one - // slower still, a spiral that measured live as /metrics reliably timing out. Collapsing - // every concurrent cache-miss into the one render already in flight stops that spiral at - // any render duration: however long it takes, it happens once, and every waiter shares it. - v, _, _ := h.metricsInflight.Do("metrics", func() (any, error) { - return h.renderMetrics(), nil - }) - body := v.(string) + // STALE-WHILE-REVALIDATE. A scrape is never made to wait for a render it did not cause. + // + // This is the fix for the outage, and the reasoning is worth keeping because the obvious + // alternative is what was here: render on the miss and make the scraper wait. That is fine + // while a render is fast and becomes an unrecoverable outage the moment it is not — the render + // exceeds scrape_timeout, the TimeoutHandler in Mux discards it and answers 503, and because + // nothing was cached the next scrape repeats the whole thing. The target goes down and STAYS + // down, and every dashboard built on these series reads "No data", which looks like the + // service is dead rather than like one endpoint being slow. + // + // Serving the previous body immediately breaks that: a scraper always gets a valid exposition, + // the refresh happens behind it, and the worst case degrades to resolution rather than to + // absence. The singleflight below means an arbitrarily slow render still happens once at a + // time no matter how many scrapes arrive during it. + if body != "" { + go h.refreshMetrics() + writeMetrics(w, body, age, took) + return + } + // Nothing cached at all — the first scrape after a restart. There is no stale body to fall back + // on, so this one renders inline and does have to wait. It is bounded by the TimeoutHandler + // like before, and it is the only scrape that ever pays. + h.refreshMetrics() + body, age, took = h.promSnapshot() + if body == "" { + // The render was cut off before it stored anything. Say so as a 503 rather than serve an + // empty exposition, which Prometheus would accept as a successful scrape of a service with + // no metrics — indistinguishable, on a dashboard, from every counter being zero. + http.Error(w, "metrics render did not complete; retry", http.StatusServiceUnavailable) + return + } + writeMetrics(w, body, age, took) +} + +// promSnapshot reads the cached exposition, its age and the duration of the render that produced +// it, under one lock acquisition so the three cannot disagree. +func (h *Handler) promSnapshot() (body string, age, took time.Duration) { h.promCache.mu.Lock() - h.promCache.at, h.promCache.body = time.Now(), body - h.promCache.mu.Unlock() - writeMetrics(w, body) + defer h.promCache.mu.Unlock() + if h.promCache.body == "" { + return "", 0, 0 + } + return h.promCache.body, time.Since(h.promCache.at), h.promCache.took +} + +// refreshMetrics renders the exposition and stores it, collapsing concurrent callers onto one +// render. +// +// Collapsing matters more than it looks: without it, a render slower than the scrape interval +// means every scrape starts another one, and concurrent renders compete for the same bounded +// connection pool, so each is slower than the last — a spiral that measured live as /metrics +// reliably timing out. With it, however long a render takes, it happens once and every waiter +// shares the result. +func (h *Handler) refreshMetrics() { + _, _, _ = h.metricsInflight.Do("metrics", func() (any, error) { + started := time.Now() + body := h.renderMetrics() + h.promCache.mu.Lock() + h.promCache.at, h.promCache.body, h.promCache.took = time.Now(), body, time.Since(started) + h.promCache.mu.Unlock() + return nil, nil + }) } -func writeMetrics(w http.ResponseWriter, body string) { - // version=0.0.4 is the classic text exposition format; naming it explicitly stops - // a scraper guessing. +func writeMetrics(w http.ResponseWriter, body string, age, took time.Duration) { + // version=0.0.4 is the classic text exposition format; naming it explicitly stops a scraper + // guessing. w.Header().Set("Content-Type", "text/plain; version=0.0.4; charset=utf-8") _, _ = w.Write([]byte(body)) + // Appended per response rather than built into the body, because they describe THIS response: + // the body is shared by every scrape served from one render, and its age differs for each. + // + // These two exist so that serving a stale body stays honest. Every other series here can be a + // minute old now, and without a published age there is no way to tell a dashboard showing + // slightly-old numbers from one showing numbers that stopped updating entirely — which is the + // failure this endpoint just had, in the form that took hours to notice. + var b strings.Builder + promHeaderProc(&b, "cg_metrics_age_seconds", + "Age of the exposition being served. Rises above the refresh interval only if refreshes have stopped; alert on it.", "gauge") + promLine(&b, "cg_metrics_age_seconds", "", age.Seconds()) + promHeaderProc(&b, "cg_metrics_render_seconds", + "How long the render that produced this body took. Approaching the scrape interval means the per-tenant queries need attention.", "gauge") + promLine(&b, "cg_metrics_render_seconds", "", took.Seconds()) + _, _ = w.Write([]byte(b.String())) } // metricsAllowed gates the endpoint. A bearer token is accepted so Prometheus can