Request-path latency grows with DB size: SQL on the 4-connection pool, partly under store.mu.RLock #2146

Summary

API latency on larger instances is dominated by waiting, not by SQLite query execution. Two mechanisms combine:

1. Several request handlers run SQL against the server's read pool, which is capped at 4 connections (cmd/server/db.go:153).
2. Some of those handlers issue that SQL while holding PacketStore.mu.RLock(). mu is a sync.RWMutex (store.go:187). Once the ingest poller calls Lock(), every new RLock() queues behind it. So a single RLock holder waiting on a pool connection stalls ingest and then every store-reading endpoint, including /api/healthz.

The result: endpoints that do almost no work show maxima of 8 to 80 seconds, and they get worse as the database grows. This issue tracks the fixes per endpoint so the instance stays responsive as databases keep growing.

Related: #1442. Its conclusion (no Postgres) still holds: the isolated query timings below are fast, and a different engine does not remove lock or pool waits. Its premise that "SQLite isn't queried for normal API reads" no longer holds for the endpoints listed here.

All file references are against master at 9dbc2875.

Measurements

/api/perf from two instances, 2026-10-09.

p95 covers only the last 100 requests per endpoint; avg and max cover the whole uptime.

The same queries in isolation (instance A, read-only, Python sqlite3 on the host)

The gap between these two columns is waiting time, plus Go-side work after the query. I have not split those two apart.

Caveat: these timings come from the host's Python sqlite3, not the mattn/go-sqlite3 build inside the container. The plan can differ between SQLite versions. The page cache was warm from run 2 on.

Mechanism, with references

• Pool: SetMaxOpenConns(4) (db.go:153). There is no global in-flight limit on SQL-backed handlers. Reach has its own semaphore of 2 (node_reach.go:816). The others have none.
• SQL under store.mu.RLock:
  • QueryPackets holds RLock (store.go:1916) while calling txToMapWithRP per result row (store.go:1957, 1967). That function runs fetchResolvedPathForTxBest (store.go:4037) and, with expand=observations, fetchResolvedPathForObs per observation (store.go:4046). The LRU stores only non-nil results, so rows without a resolved path query again on every request.
  • getCachedNodesAndPM (store.go:6983) runs a full nodes query on its 30 s miss. Several callers invoke it under RLock: node_hop_analytics.go:321-322, /api/resolve-hops, /api/nodes/:pubkey/paths. Nothing collapses concurrent misses, so every caller on a miss runs the query itself.
  • GetNodeHealth (store.go:9660) runs canRelaySets plus up to 20 txToMapWithRP calls under RLock.
  • computeNodeHomeRegions calls GetObservers under RLock on a hash-sizes cache miss.
• Store-only endpoints that sit in the convoy: /api/healthz takes RLock and loops over every packet to sum observations (healthz.go:29). /api/packets/timestamps and /api/health also take RLock.
• Pool users on every request, no cache: /api/config/regions runs SELECT DISTINCT iata FROM observers each time (routes.go:585). /api/observers skips its cache whenever there is a query string. buildNodeInfoMap runs SELECT id, name FROM observers on every neighbors request (neighbor_api.go:472).
• HTTP timeouts: WriteTimeout is 60 s (main.go:519). The 75 to 145 s maxima above exceed it, so those clients most likely received a dropped connection, not a response. I have not checked whether /api/perf records time past the timeout.

Per-endpoint work

Each item is meant as its own PR that references this issue.

• Stop issuing SQL while holding store.mu. Done in fix(server): no SQL while holding PacketStore.mu #2147. Copy what is needed under RLock, release it, then query. This applies to QueryPackets/txToMapWithRP, GetNodeHealth, the getCachedNodesAndPM callers, and computeNodeHomeRegions. This item has the widest effect: it removes the convoy that stalls /api/healthz, /api/stats and ingest.
• getCachedNodesAndPM: singleflight on the 30 s miss. Partly done in fix(server): no SQL while holding PacketStore.mu #2147: past the TTL, one background refresh per key. A cold or invalidated cache is still rebuilt by every concurrent caller.
• /api/nodes/:pubkey/reach: Query plan fixed in fix(server): drive the reach scan from the observations time window #2155 (3.2 s to 1.9 s on the 18M-observation database). The window scan with LIKE remains; an indexed hop table would remove it.
  • The plan is SCAN t (all transmissions), followed by an index probe on observations (node_reach.go:767-770). The path_json LIKE '%"XX"%' filter cannot use an index.
  • Options: drive the query from observations.timestamp, keep a hop-to-observation index table written by the ingestor, or serve reach from the in-memory store.
  • Also: Go-side time after the 3.3 s scan has not been measured yet.
• /api/nodes/:pubkey/paths: 1 to 3 queries per candidate transmission (resolved_index.go:160, INSTR(LOWER(resolved_path), ?)), run one after another. The LRU does not cache negative results. Status: perf(server): /paths reads canonical paths in batches and skips redundant collision checks #2157 (merged). The per-candidate collision query is skipped where the canonical path decides, and canonical paths are read in batches: 3.4-5.2 s to 1.7-3.1 s per call on staging.
• /api/channels and /api/channels/:hash/messages: both go to SQLite first and fall back to the store only when s.db is nil (routes.go:2773, 2805). GetChannels has no time bound. Store-first, or a time window. Status: measured, no change for now. The message page query takes 74-81 ms warm on the 18M-observation database; one cold 17.6 s run did not reproduce. Using transmissions.last_seen instead of the per-row MAX(timestamp) gives the same page warm, and last_seen differs from MAX(observations.timestamp) on 1,850 of 34,959 rows of the busiest channel.
• /api/perf: four SELECT COUNT(*) on every call (db.go:580). Cache the counts, or take them from the store. Status: perf(server): battery history via the primary key, cached /api/perf row counts #2156 (merged), counts cached for 60 s (COUNT(*) on observations: 116 ms).
• /api/stats: GetSignatureDropCount is a whole-table COUNT(*) FROM dropped_packets (db.go:3184). Status: measured, no change: COUNT(*) FROM dropped_packets takes 0.0 ms there.
• /api/nodes/:pubkey/neighbors: neighborMu is held for the whole graph rebuild (neighbor_api.go:85), plus a per-request observers query (neighbor_api.go:472).
• /api/config/regions: cache the distinct IATA list. Status: measured, no change: SELECT DISTINCT iata FROM observers takes 0.2 ms.
• /api/observers: cache keyed by the query string, not bypassed by it. Status: measured, no change: the packet-count query takes 1.3 ms.
• /api/nodes/:pubkey/battery: LOWER(observer_id) = ? (node_battery.go:56) prevents use of an index on observer_id. Status: perf(server): battery history via the primary key, cached /api/perf row counts #2156 (merged): observer_id IN (lower, upper) uses the primary key, 29 ms (174 ms cold) to 5.5 ms.
• /api/scope-stats: isolated cost is 0.05 to 0.54 s on instance A. Recheck after the items above. Its slowness on instance B may be waiting only. Status: measured, no change: the 24 h summary takes 7 ms warm.
• Ingestor startup ANALYZE: the daily planner-statistics refresh also ran 2 minutes after every start, holding the write connection for 4-9 minutes on a cold cache. Status: perf(ingestor): refresh planner statistics 24h after the last refresh, not after every start #2158 (merged): refresh 24 h after the previous one, recorded next to the database.
• Read pool size: measured, no change: a staging A/B with 8 instead of 4 connections lowered /paths throughput (133-146 to 81-103 calls per 120 s).

Not done

• No profiling of the running server (pprof, mutex or block profile). The convoy explanation comes from code reading plus the pattern in the maxima. It has not been observed directly.
• Go-side processing time per endpoint, separate from SQL wait, is not measured.
• Instance B was observed only through its public /api/perf and /api/health, with no access to its config or logs. Its packetStore.maxMB is 250, which keeps only about 23k packets in memory. Whether that pushes more requests onto the SQL fallback paths is not verified.
• Analytics store functions (topology, rf, hash-collisions) were read for SQL calls, not timed.

Question

Should the first PR be the "no SQL under store.mu" change (widest effect, touches shared code in store.go), or reach (largest total time on both instances, self-contained)?