fix(dash): stop the dashboard retry storm that took the service down - #183
Merged
Conversation
added 2 commits
September 2, 2026 22:05
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 <Osher.Elhadad@ibm.com>
…der's timeout failing everyone else's
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 <Osher.Elhadad@ibm.com>
…es get used
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 <Osher.Edhadad@ibm.com>
OsherElhadad
force-pushed
the
fix/dash-outage-0902-v2
branch
from
September 2, 2026 22:55
ad95e02 to
86022f1
Compare
… the checkpoint not after 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 <Osher.Elhadad@ibm.com>
OsherElhadad
pushed a commit
that referenced
this pull request
Sep 3, 2026
…ponse, not renderMetrics() TestDashboardsOnlyQueryMetricsWeExport failed on this branch (both build-test and purego, same single test) reporting cg_metrics_age_seconds and cg_metrics_render_seconds as unexported. They are exported — #183 ships them — but not by renderMetrics(), which is what the test inspected. Those two are appended PER RESPONSE in writeMetrics rather than built into the cached body, and that is deliberate: the body is shared by every scrape served from one render, so its age differs for each of them. Baking an age into the cached body would make it report the same figure to every scrape, which is the exact lie those two series exist to expose. So the test was asserting against the wrong artifact. Its own doc comment says the property under test is "every cg_* name any dashboard queries must appear in the rendered exposition" — and what a scraper actually receives is the response. It now issues a real request through metricsHandler from loopback (metricsAllowed gates on that absent a METRICS_TOKEN) and asserts on that body, which covers both body-level and response-level series. Strictly stronger, not looser: verified by pointing a panel at a nonexistent cg_totally_bogus_metric_xyz, which the test still catches and names. Signed-off-by: Osher Elhadad <Osher.Elhadad@ibm.com>
OsherElhadad
added a commit
that referenced
this pull request
Sep 3, 2026
…watching, and alert on the observability path (#184) * feat(grafana): fill the two empty rows, graph the metrics nobody was watching, and alert on the observability path The main dashboard advertised two sections it never filled — "Is storage and cold storage healthy?" and "Is anything failing?" were rows with no panels under them, so the two questions an operator asks during an incident had a heading and nothing else. The alerting directory shipped with no rules at all, so nothing paged. context-guru: 27 -> 45 panels. The two empty rows now hold what they promise: local database against cold storage, filesystem in use, cold storage reachability, sessions archived, dropped capture events; and compaction-model failures, cache-write churn, tokens wasted recovering offloaded content, buffered streams, tenants disabled, expand bounces over time, buffered against streamed responses, requests refused by reason, refusals per tenant, expand recovery failures by cause. Four value panels join the savings row — net saved this month, extraction net value, cache-frozen headroom, and the prefix-cache and total-avoided figures that previously sat orphaned below the last row. service SLO: 16 -> 19 panels, all three in "Correctness of the observability path itself", which is exactly where this week's outage would have shown up and did not. cg_metrics_age_seconds is the series that matters: /metrics had a cache TTL shorter than the scrape interval, so it could not answer a single scrape and the target sat down for hours while every cg_* panel read "No data" — a state indistinguishable, from the dashboard, from the service being dead. An exposition age that stops advancing says which one it is in one number. alerting: three rules, each for a failure that was previously silent — the service being down, more than 10% of requests refused, and the metrics exposition ageing past its refresh interval. Every panel's PromQL was run against this deployment's Prometheus before being committed: 83 of 86 Prometheus queries return series on live data, and the three that do not are the two new cg_metrics_* series plus their timeseries, which only exist once the proxy carrying them is deployed. The 17 Loki queries were checked against Loki, which is healthy and ingesting. All three alert expressions return series. Both dashboard uids are unchanged, so provisioning and every existing link still resolve. Colours are untouched: blue #3987e5 actual, orange #d95926 comparison, aqua #199e70 savings, validated CVD-safe on Grafana dark at all-pairs deltaE 9.4. No fourth colour was needed. Note on drift: the deployed copy of context-guru.json came from d9e2f24, which is not on main — 41 panels that only ever existed on the box. This change is a strict superset of it, verified panel by panel, so landing it brings that work into the repo rather than reverting it. context-guru-logs.json and context-guru-host.json are deliberately untouched. Signed-off-by: Osher Elhadad <Osher.Elhadad@ibm.com> * test(proxy): assert the dashboard-metric guard against the SERVED response, not renderMetrics() TestDashboardsOnlyQueryMetricsWeExport failed on this branch (both build-test and purego, same single test) reporting cg_metrics_age_seconds and cg_metrics_render_seconds as unexported. They are exported — #183 ships them — but not by renderMetrics(), which is what the test inspected. Those two are appended PER RESPONSE in writeMetrics rather than built into the cached body, and that is deliberate: the body is shared by every scrape served from one render, so its age differs for each of them. Baking an age into the cached body would make it report the same figure to every scrape, which is the exact lie those two series exist to expose. So the test was asserting against the wrong artifact. Its own doc comment says the property under test is "every cg_* name any dashboard queries must appear in the rendered exposition" — and what a scraper actually receives is the response. It now issues a real request through metricsHandler from loopback (metricsAllowed gates on that absent a METRICS_TOKEN) and asserts on that body, which covers both body-level and response-level series. Strictly stronger, not looser: verified by pointing a panel at a nonexistent cg_totally_bogus_metric_xyz, which the test still catches and names. Signed-off-by: Osher Elhadad <Osher.Elhadad@ibm.com> --------- Signed-off-by: Osher Elhadad <Osher.Elhadad@ibm.com> Co-authored-by: Osher Elhadad <Osher.Elhadad@ibm.com>
This was referenced Sep 3, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The dashboard returned 503 to real users for over a day while the proxy itself was
perfectly healthy, and Grafana showed no data at all. One day's nginx log for the
service: 15,700 503s and 7,737 gateway timeouts against 36,702 OKs, across 19
client addresses. The process sat at 6.8 GB of Go heap against its 8 G cgroup cap
burning 3.66 cores continuously.
It was one feedback loop, and there were six independent places it could have been
broken. Every one of them is a variant of the same mistake: a cache or a bound set
against the wrong number.
The loop
The client turned a 5-minute poller into a 5-second hammer on first failure.
dash/ui/app.jspaced its refresh onstate.loadedAt, which is assigned onlyafter a load succeeds. The first failure froze it, so both backoff guards —
each measuring
now - loadedAt— were permanently satisfied and the 5s tickre-fired every 5s forever. 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
finallyso an abort counts too, plus anin-flight guard so ticks cannot stack.
Abandoned reads ran to completion holding a pooled connection.
WithContext/readCtxalready existed indash/store.gofor exactly thisproblem — its doc comment even measures it — and was wired only to the KV-cache
routes. The other handler call sites and 106 of 111
d.sql.Query/QueryRowcalls ignored it. Reads now run under the request context through one accessor,
a.db(r). Writes are untouched: a write must complete.Only 3 of ~30 routes had the handler timeout, attached by hand, so every
route added afterwards silently had none — including
/api/seriesand/api/capture, the two that hung longest (4,049 and 3,549 gateway timeouts ina day).
Mountnow applies a bound by default androuteBoundsnames theexceptions.
Two caches had a TTL shorter than the work they cached, so they cached
almost nothing:
/metrics:promCacheTTL10s against a 15sscrape_intervalmeant the bodywas always already expired when a scrape arrived, so the cache could never
serve a single scrape — that part is structural and load-independent. Every
scrape therefore rendered from scratch, and once the render exceeded the 10s
scrape_timeoutit returned 503 and the target stayed down for hours. Thatis why Grafana was blank.
Correction to an earlier version of this description, which said the 503 was
"independent of load". Only the cache-miss is. The render itself measures
8.3s cold / 3.2s warm on an idle box through the real driver, so it was not
always over 10s on its own — the permanent 503 needed the TTL bug and the
memory-pressure slowdown from items 1-3 together. Fixing either would have
helped; both are fixed here.
/api/{stats,facets,components}:dashCacheTTL5s against a ~6sComponents(). With no collapsing either, 19 readers meant 19 concurrentmulti-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.
dashCacheStalecaps how old a served body mayget, because the page stamps freshness when the browser fetched and cannot see
server-side staleness.
/api/componentsfailed 100% of the time on its default view. Theunfiltered all-time aggregate measures 10.2–10.4s against a 10s bound — it lost
by a fraction of a second, every time. That 10s existed because a comment said
it "matches Prometheus's own scrape_timeout", which is the wrong reason for
these three routes: nothing scrapes them. Prometheus reads
/metrics. Bound isnow 45s, well inside nginx's 600s
proxy_read_timeout.serveJSON's shared computation inherited the leader's request context, soa 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 completed work was discarded rather than cached.
Measured before the fix: 19 concurrent
/api/componentsall failed in 2ms. Itis now detached and separately bounded.
Plus
GOMEMLIMIT=7GiBin the unit. Go's GC cannot seeMemoryMax, so the processgrew until the kernel started refusing it memory and the two fought — measured
live, the CPU was spread evenly across twelve threads, which is the GC's signature
rather than an application loop. This is a seatbelt, not the cure; the cure is
items 1–6 not needing the memory.
Measured
On a copy of the production database (2.23 GB), warm, medians:
OverviewDeclCreditFor(SelfRemovals)ComponentsFacetsSeriesThrough the real mounted handlers, all-time default view:
/api/stats/api/facets/api/components40 concurrent
/api/components: 40× non-200 in 2ms → 40× 200 in 1ms.Live, deployed on the hosted box
each ~25s restart window.
/metrics: 503 after 10s → 200 in under 1ms; Prometheus targetdown→upwith 1.7ms scrapes; Grafana's cg_* series are flowing again, 13.6s behind live.
Not mine, and not fixed here
idx_tooldecl_inventorywith its matchingSelfRemovalsGROUP BY, and not carryingr.*through three window sorts, come fromperf/dash-query-cost-0901(79a132c,7471b09, f97bda5) — measured against production and never merged. Its invariant is
kept intact: the index and the GROUP BY ship together, because that branch measured
the rewrite without the index at 10,749ms against the plain scan's 4,498ms. The
index lives in
additiveDDL, which runs on every open, so it reaches an existingdatabase;
schemaVersionis untouched, so no database is renamed aside. On thisdeployment the one-time build took 12s.
The cold all-time
Components()is still ~10s. It is now paid once per refreshinterval by one reader instead of by every reader on every load, and it is honest
about itself through
X-Cacheandcg_metrics_render_seconds. Making the aggregateitself cheap needs a rollup table maintained on write — a real change with real
failure modes, which should not be smuggled in behind an outage fix.
MaxOpenConnsis deliberately not changed. Reads here are CPU-bound and do notparallelise (measured: at K=16 concurrent
Overviewcalls each takes 41s), so a poolof 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 PR removes. It
should be re-measured against the fixed demand, not guessed at now.
Tests
go test ./...andgo test -race ./...green;go vetandgofmtclean.dash/uirefreshpacing_test.gois new and guards the pacing invariant at sourcelevel (verified to fail on the pre-fix code, not just pass on the new). The
/api/componentscache test was rewritten to assert the newstale-while-revalidate contract including the staleness cap, rather than being
loosened to pass.