From db1c1d1e1a23c9dd04cd65cf09dc7d2443b63f1b Mon Sep 17 00:00:00 2001 From: Osher Elhadad Date: Wed, 2 Sep 2026 22:04:02 +0000 Subject: [PATCH 1/4] fix(dash): stop the dashboard retry storm that took the service down MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The dashboard 503'd for users for over a day (15,700 503s and 7,737 gateway timeouts against 36,702 OKs in one day, 19 client addresses) while the proxy itself was healthy, and Grafana showed no data at all. One feedback loop, and five places it could have been broken: 1. The refresh timer paced on state.loadedAt, which advances only when a load SUCCEEDS (dash/ui/app.js). The first failure left it frozen, so both backoff guards — each measuring now - loadedAt — were permanently satisfied and the 5s tick re-fired every 5s instead of every 5 minutes. The repaint error path also calls markDirty(), which removed the staleness cap that was the second brake. Now paced on the last ATTEMPT, recorded in a `finally` so an abort counts too, plus an in-flight guard so ticks cannot stack. 2. Reads were uncancellable, so every abandoned retry ran to completion holding a pooled connection. WithContext/readCtx already existed for exactly this and was wired only to the KV-cache routes; the other handler call sites and 106 of 111 d.sql.Query/QueryRow calls ignored it. Reads now run under the request context via one accessor, a.db(r). Writes are untouched: a write must complete. 3. Only 3 of ~30 routes had the handler timeout, attached by hand, so every route added afterwards had none — including /api/series and /api/capture, the two that hung longest. Mount now applies it by default; unboundedRoutes names the four genuine exceptions (SSE, cold storage, static assets). 4. Two caches had a TTL SHORTER THAN THE WORK THEY CACHED, so they cached almost nothing and every caller paid full price: - /metrics: promCacheTTL 10s against a 15s scrape_interval meant the body was always already expired when a scrape arrived. Every scrape rendered from scratch, exceeded the 10s scrape_timeout and returned 503 — permanently and independent of load. That alone is why Grafana was blank. - /api/{stats,facets,components}: dashCacheTTL 5s against a ~6s Components() and ~5s stats set. With no collapsing either, nineteen readers meant nineteen concurrent multi-second scans on one pool. Both now hold a body longer than it costs to build, serve the previous body while a replacement is computed behind the response, and collapse concurrent misses onto one computation. dashCacheStale caps how old a served body may get, because the page stamps freshness when the BROWSER fetched and cannot see server-side staleness. cg_metrics_age_seconds and cg_metrics_render_seconds publish the same thing for /metrics. 5. GOMEMLIMIT=7GiB in the unit: Go's GC cannot see MemoryMax, so the process sat at 6.8GB of heap against the 8G cap burning 3.66 cores continuously, spread evenly across twelve threads (the GC's signature, measured live). A seatbelt, not the cure — the cure is 1-4 not needing the memory. Two query changes come with it. The first is NOT mine: idx_tooldecl_inventory with its matching SelfRemovals GROUP BY, and not carrying r.* through three window sorts, are from perf/dash-query-cost-0901 (79a132c, 7471b09, f97bda5), which measured them against production and was never merged. Its own invariant is kept intact: the index and the GROUP BY ship together or not at all, because that branch measured the rewrite WITHOUT the index at 10,749ms against the plain scan's 4,498ms. idx_tooldecl_inventory sits in additiveDDL, which runs on every open, so it reaches an existing database; schemaVersion is untouched, so no database is renamed aside. The second is measured here: the two json_each aggregates in Components() drove from request_components (all 1,576,383 rows) and applied the time filter afterwards. CROSS JOIN as an optimiser barrier pins requests first so only the 303,770 rows in the window are touched. Writing requests first as a plain JOIN does nothing — the planner reorders it back. Measured on a copy of the production database (2.23GB), warm, medians: Overview 4.0s -> 1.7s DeclCreditFor (SelfRemovals) 7.2s -> 1.5s Components 13.2s -> 3.5s Facets 4.4s -> 2.8s Series 0.2s -> 0.06s A COLD first read after a restart still costs ~13-16s, so one reader can still time out once per restart per view before anything is cached. That is now the worst case rather than the steady state, and it is not fixed here: warming the cache at startup would need a principal and a filter to warm it FOR, and guessing either is how you build a cache nobody reads. MaxOpenConns is deliberately NOT changed. Reads here are CPU-bound and do not parallelise (measured: at K=16 concurrent Overview calls each takes 41s), so a pool of 100 cannot add throughput — but 20/10 was tried before and queued live traffic past the timeout, and that was under the pathological demand this commit removes. It should be re-measured against the fixed demand, not guessed at now. Signed-off-by: Osher Elhadad --- dash/api.go | 502 ++++++++++++++++++---------- dash/api_test.go | 24 ++ dash/archive.go | 8 +- dash/bench.go | 6 +- dash/cachehistory.go | 40 ++- dash/campaignsavings.go | 4 +- dash/componentscache_test.go | 80 ++++- dash/dedupetext.go | 4 +- dash/keepalive.go | 58 ++-- dash/keepaliveapi.go | 12 +- dash/keepalivestrategy.go | 6 +- dash/keepalivestrategybackfill.go | 4 +- dash/kvcacheapi.go | 12 +- dash/metrics_export.go | 2 +- dash/overview.go | 80 +++-- dash/promptapi.go | 8 +- dash/purge.go | 6 +- dash/query.go | 87 +++-- dash/readvalue.go | 8 +- dash/schema.go | 25 ++ dash/spend.go | 2 +- dash/store.go | 12 +- dash/toolapi.go | 37 +- dash/toolsuggest.go | 10 +- dash/ui/app.js | 35 +- dash/uirefreshpacing_test.go | 89 +++++ dash/zz_perf_test.go | 88 +++++ deploy/service/context-guru.service | 21 ++ proxy/promexport.go | 132 ++++++-- 29 files changed, 1027 insertions(+), 375 deletions(-) create mode 100644 dash/uirefreshpacing_test.go diff --git a/dash/api.go b/dash/api.go index 0a3e2b07..91414f03 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,25 +51,54 @@ 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 + // 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 const dashTimeoutMsg = "dashboard query timed out; try again in a moment" @@ -96,6 +127,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 +162,96 @@ 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") + v, err, _ := a.jsonInflight.Do(key, func() (any, error) { + body, err := compute(a.db(r)) + 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(), 2*time.Minute) + 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 +448,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,10 +485,39 @@ 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 !unboundedRoutes[rt.pattern] { + h = http.TimeoutHandler(h, dashHandlerTimeout, dashTimeoutMsg).ServeHTTP + } + m.HandleFunc(rt.pattern, h) } } +// unboundedRoutes are the routes Mount does NOT put a handler timeout on. +// +// The bound is applied by DEFAULT and named here as an opt-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, +// each burning 60s of nginx patience, because nothing in the process ever gave up. A route is now +// bounded whether or not its author thought about it, and exempting one takes a deliberate line. +// +// Only two shapes qualify, and "this one is slow" is not among them: +// +// - A STREAMED response. http.TimeoutHandler buffers the whole body before writing, so +// wrapping an SSE feed would withhold every event and then discard them all. +// - A read that legitimately outlasts the bound because it crosses the NETWORK to cold +// storage, under its own explicit and longer timeout. +// +// The static UI is listed for neither reason: it touches no database, and buffering an embedded +// asset only to time it is pure overhead. +var unboundedRoutes = map[string]bool{ + "GET /api/events": true, // SSE: a buffered stream is not a stream + "GET /api/archive/{session}": true, // rclone fetch, own 60s bound + "GET /api/sessions/{session}/transcript": true, // reaches cold storage + "GET /dashboard/": true, // embedded assets, no DB +} + // requireManager gates a route serving server-wide or process-wide facts. // // In SINGLE-TENANT mode (auth == nil) it is a no-op: there is no second party to @@ -440,7 +610,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 +632,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 +744,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 +775,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 +826,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 +938,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 } - declCredit = c - return nil + 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() + 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 +1033,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 +1048,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 +1076,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 +1098,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 +1134,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 +1149,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 +1193,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 +1218,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 +1294,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 +1310,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/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/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..10eebbbf 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 } @@ -678,7 +678,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 +699,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..d6e0bdbe 100644 --- a/dash/toolapi.go +++ b/dash/toolapi.go @@ -373,7 +373,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 +456,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 +485,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 } @@ -908,7 +908,7 @@ func (a *API) tools(w http.ResponseWriter, r *http.Request) { return } price := a.priceFn(r) - rep, err := a.rec.DB().ToolReportFor(f, price) + rep, err := a.db(r).ToolReportFor(f, price) if err != nil { httpErr(w, http.StatusInternalServerError, "could not read the tool inventory") return @@ -920,7 +920,7 @@ func (a *API) tools(w http.ResponseWriter, r *http.Request) { 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) + sr, err := a.db(r).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. @@ -949,7 +949,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 +997,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 +1042,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..b0c6f8c6 100644 --- a/dash/toolsuggest.go +++ b/dash/toolsuggest.go @@ -163,7 +163,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 +233,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 +286,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 +544,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 @@ -558,7 +558,7 @@ func (a *API) toolFilterDoc(w http.ResponseWriter, r *http.Request) { unauthorized(w) return } - doc, err := a.rec.DB().ToolFilterDocFor(f, a.priceFn(r), a.toolFilterStateForScope(f)) + doc, err := a.db(r).ToolFilterDocFor(f, a.priceFn(r), a.toolFilterStateForScope(f)) if err != nil { httpErr(w, http.StatusInternalServerError, "could not read the removal report") return 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 From b029179456b1b523b0a35a8b29aadf1d739c67d4 Mon Sep 17 00:00:00 2001 From: Osher Elhadad Date: Wed, 2 Sep 2026 22:20:51 +0000 Subject: [PATCH 2/4] fix(dash): make the unfiltered aggregate views load, and stop one reader's timeout failing everyone else's MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two defects found by driving the real mounted handlers against a copy of the production database, after the first round of fixes. Both were invisible to per-query benchmarking, which is how they survived it: every measurement so far used a 24-hour window, and the dashboard's DEFAULT view has no window at all. 1. /api/components returned 503 on 100% of requests to its default view. The unfiltered, all-time Components() aggregate measures 10.2-10.4s on this database against a 10s handler timeout — it lost by a fraction of a second, every time, for every user. The same view is ~2.9s over 24 hours and ~7.5s over 7 days, which is why a windowed benchmark said it was fine. The 10s came from a comment reading "matches Prometheus's own scrape_timeout, so a slow tab and a slow scrape fail the same way" — the wrong reason for these three routes, because nothing scrapes them. Prometheus reads /metrics. The bound now reflects what the caller can tolerate: a person who clicked a tab covering all history, at 45s, well inside nginx's 600s proxy_read_timeout. routeBounds replaces unboundedRoutes and carries both kinds of exception in one map, 0 meaning unbounded, so there is still exactly one place to look. 2. serveJSON's shared computation inherited the LEADER's request context, so a leader that timed out cancelled the work and singleflight handed that same cancelled-context error to every waiter: one reader closing a tab failed the tab for all of them, and the work already done was discarded rather than cached. Measured before the fix: 19 concurrent /api/components all failed in 2ms on the leader's error. That is the same "one caller's abandonment costs everyone" shape the rest of this change set removes, reintroduced by the obvious code. The computation is now detached and separately bounded (dashComputeTimeout), so it always lands in the cache even if nobody is left to receive it, and each caller's own deadline bounds only their own wait. Measured through the real handlers on the production copy, all-time default view: before after (cold) after (warm) /api/stats 200 5.8s 200 5.7s 200 0ms (hit) /api/facets 500 4ms 200 1.8s 200 0ms (hit) /api/components 503 10.0s 200 10.1s 200 0ms (hit) 40 concurrent /api/components: 40x non-200 in 2ms -> 40x 200 in 1ms The cold all-time Components() is still ~10s and is not made faster here. It is now paid once per refresh interval by one reader instead of by every reader on every load, and it is honest about itself through X-Cache and cg_metrics_render_seconds. Making the aggregate itself cheap needs a rollup table maintained on write, which is a real change with real failure modes and should not be smuggled in behind an outage fix. Signed-off-by: Osher Elhadad --- dash/api.go | 101 +++++++++++++++++++++++++++++++++++++++------------- 1 file changed, 77 insertions(+), 24 deletions(-) diff --git a/dash/api.go b/dash/api.go index 91414f03..5878e7ff 100644 --- a/dash/api.go +++ b/dash/api.go @@ -101,6 +101,35 @@ const dashCacheStale = 30 * time.Second // 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 @@ -217,8 +246,21 @@ func (a *API) serveJSON(w http.ResponseWriter, r *http.Request, c *jsonCache, ke 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) { - body, err := compute(a.db(r)) + ctx, cancel := context.WithTimeout(context.Background(), dashComputeTimeout) + defer cancel() + body, err := compute(a.rec.DB().WithContext(ctx)) if err == nil { c.set(key, body) } @@ -239,7 +281,7 @@ func (a *API) serveJSON(w http.ResponseWriter, r *http.Request, c *jsonCache, ke // 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(), 2*time.Minute) + ctx, cancel := context.WithTimeout(context.Background(), dashComputeTimeout) defer cancel() body, err := compute(a.rec.DB().WithContext(ctx)) if err != nil { @@ -486,36 +528,47 @@ func (a *API) routes() []route { func (a *API) Mount(m *http.ServeMux) { for _, rt := range a.routes() { h := rt.h - if !unboundedRoutes[rt.pattern] { - h = http.TimeoutHandler(h, dashHandlerTimeout, dashTimeoutMsg).ServeHTTP + if d := routeBound(rt.pattern); d > 0 { + h = http.TimeoutHandler(h, d, dashTimeoutMsg).ServeHTTP } m.HandleFunc(rt.pattern, h) } } -// unboundedRoutes are the routes Mount does NOT put a handler timeout on. +// routeBounds overrides the default handler timeout for particular routes. 0 means NO timeout. // -// The bound is applied by DEFAULT and named here as an opt-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, -// each burning 60s of nginx patience, because nothing in the process ever gave up. A route is now -// bounded whether or not its author thought about it, and exempting one takes a deliberate line. +// 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. // -// Only two shapes qualify, and "this one is slow" is not among them: +// Two reasons to appear here, and they are different: // -// - A STREAMED response. http.TimeoutHandler buffers the whole body before writing, so -// wrapping an SSE feed would withhold every event and then discard them all. -// - A read that legitimately outlasts the bound because it crosses the NETWORK to cold -// storage, under its own explicit and longer timeout. -// -// The static UI is listed for neither reason: it touches no database, and buffering an embedded -// asset only to time it is pure overhead. -var unboundedRoutes = map[string]bool{ - "GET /api/events": true, // SSE: a buffered stream is not a stream - "GET /api/archive/{session}": true, // rclone fetch, own 60s bound - "GET /api/sessions/{session}/transcript": true, // reaches cold storage - "GET /dashboard/": true, // embedded assets, no DB +// - 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, +} + +// 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. From 86022f13600e85c3f088c497fa896775e13a09f9 Mon Sep 17 00:00:00 2001 From: Osher Elhadad Date: Wed, 2 Sep 2026 22:42:14 +0000 Subject: [PATCH 3/4] perf(dash): keep the query planner's statistics current, so the indexes get used MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This database had never been ANALYZEd. `sqlite_stat1` did not exist at all, so SQLite planned every join in this package on hard-coded guesses — and the guess it got wrong was join ORDER: with no row counts it scanned all 1,580,133 request_components rows and probed requests once per row, instead of driving from the filtered requests window through idx_rc_request, which already existed and went unused. Measured on a copy of the production database, /api/components over a 24-hour window, same code and same indexes either way: without statistics 3.59s with statistics 0.81s 4.4x Two of those queries are already pinned with an explicit CROSS JOIN barrier (Components, dash/query.go). Statistics fix the ones that are not: DecomposeComponentSavedUSD, EstimateComponentSavedUSD and Facets' component list. `PRAGMA optimize(0x10002)` on the janitor's recurring pass, and every part of that is deliberate: - The MASK is load-bearing. A bare `PRAGMA optimize` only considers tables the CURRENT CONNECTION has queried; the janitor takes a fresh pooled connection and queries nothing, so the bare form analyses nothing at all. Measured on a cold connection: bare form 0.00s with sqlite_stat1 still absent, versus 0x10002 producing all 26 statistic rows. 0x10000 is what lifts that restriction. I shipped the bare form first and caught this only by testing the deployed shape rather than trusting a passing unit test — see the test file. - It SAMPLES rather than fully scanning, which is why it can live on a 5-minute ticker at all. A bare ANALYZE measures 72s on this database. The sampled statistics are sufficient for the decision that matters: the component aggregate replans to SEARCH requests USING idx_requests_ts -> SEARCH request_components USING idx_rc_request and runs in 0.209s against 2.0s. - Not at Open, because Open sits in front of the listener (cmd/context-guru-proxy opens the store long before it serves). Putting a 72s ANALYZE there would have recreated the startup outage the one-time index build already taught us about. Statistics going stale is the failure mode to keep in mind, and the reason this is recurring rather than a one-off DBA action: they are a snapshot, and a database that doubles between passes plans against the old shape. Honest about the limit: this does NOT help the unfiltered all-time view, measured 11.56s before and 10.49s after — within noise. The win comes from the planner choosing to drive from a filtered requests window, and an all-time query has no window to drive from. So this speeds up every view that has a time range and leaves the default view exactly where dashHeavyTimeout and the response cache found it. Signed-off-by: Osher Elhadad --- dash/janitor.go | 23 ++++++++++++ dash/optimize_test.go | 81 +++++++++++++++++++++++++++++++++++++++++++ dash/store.go | 29 ++++++++++++++++ 3 files changed, 133 insertions(+) create mode 100644 dash/optimize_test.go diff --git a/dash/janitor.go b/dash/janitor.go index 2f569442..bd367c64 100644 --- a/dash/janitor.go +++ b/dash/janitor.go @@ -62,6 +62,29 @@ func (r *Recorder) janitorPass() { // pruneInterval, keeps the backlog small enough that neither this call nor // SQLite's own auto-checkpoint in between is ever slow. r.db.checkpoint() + // Keep the query planner's statistics current. Cheap, and the one thing here that makes + // existing indexes get USED rather than merely exist. + // + // 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() } // diskWatermarks resolves the configured watermarks, applying defaults and 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/store.go b/dash/store.go index 10eebbbf..3358238a 100644 --- a/dash/store.go +++ b/dash/store.go @@ -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. From 54585ca277f99dff2fd644ae973857bd870d5056 Mon Sep 17 00:00:00 2001 From: Osher Elhadad Date: Wed, 2 Sep 2026 23:09:18 +0000 Subject: [PATCH 4/4] fix(dash): make the Inventory tab load at all, and run ANALYZE before the checkpoint not after MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two defects, both found by measuring the deployed shape rather than trusting a green test. 1. /api/tools, /api/toolfilter and /api/prompt returned 503 on 100% of requests to their default all-time view, for the same reason /api/components did: they read over tool_declarations (2,178,884 rows, 768MB — the widest table in the schema) and had NO response cache at all, against the 10s default bound. Two of them appear in the outage's nginx log; /api/prompt escaped it only because nobody opened that view while it was being recorded. They now get dashHeavyTimeout, and /api/tools and /api/toolfilter get the same cache-and-collapse treatment as the other aggregates. /api/prompt gets the longer bound but deliberately NOT a cache: 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 cached body built for a trusted caller could be served to an untrusted one on the same account. Keying on trustedness is a change to a content gate and does not belong in an outage fix. 2. PRAGMA optimize ran AFTER the WAL checkpoint. It runs ANALYZE, which WRITES sqlite_stat1 — so those writes landed in a freshly truncated WAL and stayed there until the next pass, leaving the WAL growing again on every pass, which is the exact thing the checkpoint exists to prevent. Moved before it. TestJanitorPassCheckpointsWAL caught this under -race, and I had already written that failure off once as a load-sensitive flake because it passed in isolation and on main. It was not a flake. It is the reason that test asserts on WAL SIZE rather than on checkpoint() merely having been called. Measured through the real handlers on a copy of the production database, the unfiltered all-time view, before -> after: /api/tools 503 @10s -> 200, 12.6s warm, then 1ms cached /api/toolfilter 503 @10s -> 200, ~21s /api/prompt 503 @10s -> 200, ~22s So the tab loads where it previously could not, and repeat views of /api/tools are instant. It is still SLOW, and this commit does not claim otherwise. Per-call cost, all-time, cold/warm: ToolReportFor 58.8s / 12.6s <- dominates /api/tools ToolFilterDocFor 21.0s / 21.2s <- does not warm up PromptViewFor 23.7s / 22.4s <- does not warm up SelfRemovals 12.9s / 1.8s <- already fixed by idx_tooldecl_inventory Making those three genuinely fast needs query work over tool_declarations that is not an outage fix: they are money-adjacent figures, and one of them (SelfRemovals' unscoped scan) has a known session-scoping rewrite measured at 0.97s that changes which population is credited. That is a deliberate change with its own review, not something to smuggle in behind a 503. Signed-off-by: Osher Elhadad --- dash/api.go | 21 +++++++++++++++++++++ dash/janitor.go | 31 +++++++++++++++++++------------ dash/toolapi.go | 42 ++++++++++++++++++++++-------------------- dash/toolsuggest.go | 18 +++++++++++------- 4 files changed, 73 insertions(+), 39 deletions(-) diff --git a/dash/api.go b/dash/api.go index 5878e7ff..3cc972af 100644 --- a/dash/api.go +++ b/dash/api.go @@ -51,6 +51,12 @@ 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. @@ -560,6 +566,21 @@ var routeBounds = map[string]time.Duration{ "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 diff --git a/dash/janitor.go b/dash/janitor.go index bd367c64..40801732 100644 --- a/dash/janitor.go +++ b/dash/janitor.go @@ -50,21 +50,16 @@ func (r *Recorder) janitorPass() { slog.Info("dash: pruned old dashboard rows", "requests", n) } r.relieveDiskPressure() - // 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 - // default wal_autocheckpoint (1000 pages) forced an inline checkpoint on an - // ordinary writer commit — paying off the WHOLE accumulated backlog inside that - // one commit. Measured against a WAL bloated to the production scale (~40k - // pages): that single commit took 5.5s, and a concurrent reader sharing this - // *sql.DB (e.g. /metrics) blocked for the same 5.2s — this driver does not give - // non-blocking WAL reads across a commit. Checkpointing here, every - // pruneInterval, keeps the backlog small enough that neither this call nor - // SQLite's own auto-checkpoint in between is ever slow. - r.db.checkpoint() // 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, @@ -85,6 +80,18 @@ func (r *Recorder) janitorPass() { // 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 + // default wal_autocheckpoint (1000 pages) forced an inline checkpoint on an + // ordinary writer commit — paying off the WHOLE accumulated backlog inside that + // one commit. Measured against a WAL bloated to the production scale (~40k + // pages): that single commit took 5.5s, and a concurrent reader sharing this + // *sql.DB (e.g. /metrics) blocked for the same 5.2s — this driver does not give + // non-blocking WAL reads across a commit. Checkpointing here, every + // pruneInterval, keeps the backlog small enough that neither this call nor + // SQLite's own auto-checkpoint in between is ever slow. + r.db.checkpoint() } // diskWatermarks resolves the configured watermarks, applying defaults and diff --git a/dash/toolapi.go b/dash/toolapi.go index d6e0bdbe..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" @@ -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.db(r).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.db(r).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 diff --git a/dash/toolsuggest.go b/dash/toolsuggest.go index b0c6f8c6..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" @@ -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.db(r).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) + }) }