perf: /api/stats recompute holds the GVL ~2.3s, freezing all Puma threads (cold TTFB root cause) #220

New Issue

2026-10-04T23:04:36+02:00

adam commented

2026-10-04 23:04:36 +02:00

Summary

GET /api/stats recomputes a CPU-bound aggregation (~2.3 s on a ~1.8 M-row instance) every 15 s when its API cache expires. Because the web app is a single-process Puma (16:128 threads, one MRI GVL), that recompute holds the GVL and freezes all 128 threads for its full duration — so the landing page (and every other request) that happens to arrive during the recompute stalls ~1.8–2.3 s. This is the root cause of the "cold" first-request TTFB observed on dweb.potatomesh.net.

The landing page itself has no cold path — GET / is a pure-ERB render that runs in ~1 ms and touches zero DB. It is purely a victim of the /api/stats GVL stall.

Evidence (isolated server-side profiling)

Paired capture during a stall:

89.42.42.116  "GET /api/stats"        200  2.2658   ← the cost
127.0.0.1     "GET /?probe=rp-3956"   200  0.0011   ← victim: 1.1 ms in-app, 2.25 s to client

Controlled proof: a cold /api/stats fired with 10 concurrent GET / → all 11 finish together at ~2.37 s; warm control → 2–8 ms.
API cache TTL is 15 s: call #1 = 2.66 s, calls #2–4 = 0.0007 s. Every 15 s the next hit pays the full recompute (5 slow hits in a 150 s run, ~20 s apart).
Not infra: at the slow moment the process is State: S, load ~1.0, ~41 GB free, no swap, no major faults — pure GVL contention, one CPU-bound C scan monopolizing the interpreter.

Root cause

query_active_node_stats → windowed_protocol_counts (web/lib/potato_mesh/application/queries/node_queries.rb:447) builds:

WITH visible AS (SELECT rx_time AS t, protocol AS p FROM <table> WHERE <opt-out …>)
SELECT (SELECT COUNT(*) FROM visible WHERE t >= ?) AS total_hour,
       … 12 such subqueries (4 windows × {total, meshcore, meshtastic}) …

The time filter sits on the aliased t in the outer subqueries, so SQLite materializes the entire table into visible, then scans it 12×. The idx_*_rx_time / last_heard indexes cannot be used against an alias inside a materialized CTE. EXPLAIN QUERY PLAN: MATERIALIZE visible once, then 12× SCAN visible. The telemetry umbrella alone (positions+telemetry+neighbors+traces UNION, ~2.5 M rows scanned 12×) = ~1.72 s; nodes ~1.43 s.

Proposed fix (Fix 1 — query pushdown)

Push the widest-window cutoff — "month" = now − four_weeks_seconds (node_queries.rb:353) — into each projection's WHERE on the raw column so the index is used and visible is pre-filtered to the last 28 days before aliasing:

node_activity_counts (:374): … WHERE last_heard >= ? AND <opt-out …>
message_activity_counts (:396): … WHERE rx_time >= ? AND <opt-out …>
telemetry_activity_counts (:414, per UNION branch :424): add rx_time >= ? to each branch's WHERE.

Provably lossless: four_weeks_seconds (month) is the widest of {hour, day, week, month}, and SPEC S4 guarantees no count reaches past the 28-day floor — so any row pruned by col >= now − four_weeks_seconds contributes 0 to all four windows. Only ~2 % of rows are inside 28 days (e.g. 39 k of 1.8 M positions), so the scan shrinks ~50×.

Measured: telemetry 1.72 s → 0.14 s; whole /api/stats recompute ~2.3 s → < 0.3 s, byte-identical results. (Single-pass SUM(CASE …) alone does not help — measured 1.77 s — the index pushdown is the essential part.)

Exactness caveat: thread the same now-derived month cutoff (cutoffs["month"]) into the projection — do not recompute Time.now in the CTE — so the pre-filter and the month count share one now.

Acceptance / guardrails

Must stay byte-identical and green (they seed rows on both sides of the 28-day boundary):

bundle exec rspec spec/queries_spec.rb -e "active_node_stats" (S-A2)
bundle exec rspec spec/queries_spec.rb -e "telemetry umbrella" (S-A3)
/api/stats shape check (S-A1) and private-mode zeroing (S-A4)

Add: a spec asserting the plan uses the index (e.g. EXPLAIN QUERY PLAN contains USING INDEX idx_*_rx_time/last_heard) so the pushdown can't silently regress; 100 % coverage per repo rule.

Related (tracked separately, not this issue)

Defense-in-depth: serve /api/stats stale-while-revalidate + configurable TTL so no user request ever recomputes synchronously (composes with this fix; full freeze-elimination requires this fix because a background recompute still holds the GVL until it is fast).
Structural: run Puma in cluster mode (N workers = N GVLs) so one CPU-bound request cannot freeze all threads.
Asset delivery: serve /assets/ from nginx with immutable caching (also removes ~50 GVL-competing asset requests/page from Puma).

References

web/lib/potato_mesh/application/queries/node_queries.rb — query_active_node_stats (:343), windowed_protocol_counts (:447), node_activity_counts (:372), message_activity_counts (:392), telemetry_activity_counts (:414)
SPEC S1–S7; ACCEPTANCE S-A1–S-A6

## Summary `GET /api/stats` recomputes a CPU-bound aggregation (~2.3 s on a ~1.8 M-row instance) every 15 s when its API cache expires. Because the web app is a **single-process Puma** (16:128 threads, one MRI GVL), that recompute **holds the GVL and freezes all 128 threads** for its full duration — so the landing page (and every other request) that happens to arrive during the recompute stalls ~1.8–2.3 s. This is the root cause of the "cold" first-request TTFB observed on `dweb.potatomesh.net`. The landing page itself has **no** cold path — `GET /` is a pure-ERB render that runs in ~1 ms and touches zero DB. It is purely a victim of the `/api/stats` GVL stall. ## Evidence (isolated server-side profiling) - Paired capture during a stall: ``` 89.42.42.116 "GET /api/stats" 200 2.2658 ← the cost 127.0.0.1 "GET /?probe=rp-3956" 200 0.0011 ← victim: 1.1 ms in-app, 2.25 s to client ``` - Controlled proof: a cold `/api/stats` fired with 10 concurrent `GET /` → **all 11 finish together at ~2.37 s**; warm control → 2–8 ms. - API cache TTL is 15 s: call #1 = 2.66 s, calls #2–4 = 0.0007 s. Every 15 s the next hit pays the full recompute (5 slow hits in a 150 s run, ~20 s apart). - Not infra: at the slow moment the process is `State: S`, load ~1.0, ~41 GB free, no swap, no major faults — **pure GVL contention**, one CPU-bound C scan monopolizing the interpreter. ## Root cause `query_active_node_stats` → `windowed_protocol_counts` (`web/lib/potato_mesh/application/queries/node_queries.rb:447`) builds: ```sql WITH visible AS (SELECT rx_time AS t, protocol AS p FROM <table> WHERE <opt-out …>) SELECT (SELECT COUNT(*) FROM visible WHERE t >= ?) AS total_hour, … 12 such subqueries (4 windows × {total, meshcore, meshtastic}) … ``` The time filter sits on the **aliased `t`** in the outer subqueries, so SQLite **materializes the entire table into `visible`, then scans it 12×**. The `idx_*_rx_time` / `last_heard` indexes cannot be used against an alias inside a materialized CTE. `EXPLAIN QUERY PLAN`: `MATERIALIZE visible` once, then `12× SCAN visible`. The telemetry umbrella alone (positions+telemetry+neighbors+traces UNION, ~2.5 M rows scanned 12×) = ~1.72 s; nodes ~1.43 s. ## Proposed fix (Fix 1 — query pushdown) Push the **widest-window** cutoff — `"month" = now − four_weeks_seconds` (`node_queries.rb:353`) — **into each projection's `WHERE` on the raw column** so the index is used and `visible` is pre-filtered to the last 28 days *before* aliasing: - `node_activity_counts` (`:374`): `… WHERE last_heard >= ? AND <opt-out …>` - `message_activity_counts` (`:396`): `… WHERE rx_time >= ? AND <opt-out …>` - `telemetry_activity_counts` (`:414`, per UNION branch `:424`): add `rx_time >= ?` to each branch's `WHERE`. **Provably lossless:** `four_weeks_seconds` (month) is the widest of {hour, day, week, month}, and SPEC **S4** guarantees no count reaches past the 28-day floor — so any row pruned by `col >= now − four_weeks_seconds` contributes **0** to all four windows. Only ~2 % of rows are inside 28 days (e.g. 39 k of 1.8 M positions), so the scan shrinks ~50×. Measured: telemetry 1.72 s → 0.14 s; whole `/api/stats` recompute ~2.3 s → **< 0.3 s**, byte-identical results. (Single-pass `SUM(CASE …)` alone does **not** help — measured 1.77 s — the index pushdown is the essential part.) **Exactness caveat:** thread the *same* `now`-derived month cutoff (`cutoffs["month"]`) into the projection — do not recompute `Time.now` in the CTE — so the pre-filter and the `month` count share one `now`. ## Acceptance / guardrails Must stay **byte-identical** and green (they seed rows on both sides of the 28-day boundary): - `bundle exec rspec spec/queries_spec.rb -e "active_node_stats"` (S-A2) - `bundle exec rspec spec/queries_spec.rb -e "telemetry umbrella"` (S-A3) - `/api/stats` shape check (S-A1) and private-mode zeroing (S-A4) Add: a spec asserting the plan uses the index (e.g. `EXPLAIN QUERY PLAN` contains `USING INDEX idx_*_rx_time`/`last_heard`) so the pushdown can't silently regress; 100 % coverage per repo rule. ## Related (tracked separately, not this issue) - **Defense-in-depth:** serve `/api/stats` stale-while-revalidate + configurable TTL so no user request ever recomputes synchronously (composes with this fix; full freeze-elimination requires this fix because a background recompute still holds the GVL until it is fast). - **Structural:** run Puma in **cluster mode** (N workers = N GVLs) so one CPU-bound request cannot freeze all threads. - **Asset delivery:** serve `/assets/` from nginx with immutable caching (also removes ~50 GVL-competing asset requests/page from Puma). ## References - `web/lib/potato_mesh/application/queries/node_queries.rb` — `query_active_node_stats` (`:343`), `windowed_protocol_counts` (`:447`), `node_activity_counts` (`:372`), `message_activity_counts` (`:392`), `telemetry_activity_counts` (`:414`) - SPEC `S1`–`S7`; ACCEPTANCE `S-A1`–`S-A6`

adam closed this issue

2026-10-04 23:04:36 +02:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: adam/potato-mesh#220