Files
meshcore-analyzer/cmd/server/cache_refresh.go
T
efitenandClaude Opus 5.5 f50312767f fix(server): no SQL while holding PacketStore.mu (#2147)
Refs #2146 (first item: "Stop issuing SQL while holding `store.mu`").

## Situation

Several store functions ran SQLite queries while holding
`PacketStore.mu`. The server's read pool has 4 connections
(`db.go:153`), so a store-lock holder could wait for a pool connection.
`mu` is a `sync.RWMutex`: once the ingest poller asks for the write
lock, every new reader queues behind it, including `/api/healthz`. A
test that scans the package (below) finds 16 such call sites on `master`
at 9dbc2875.

## My changes in this PR

One commit per part:

1. **Caches serve stale while one refresh runs** (`4d9a818e`).
`getCachedNodesAndPM`, `resolveRegionObservers` and `resolveAreaNodes`
ran their SQL inline on a 30 s TTL miss, also from ingest under the
write lock. Past the TTL they now return the cached value and start one
background refresh per key (`cache_refresh.go`).
- A cache that was never built, or was invalidated with
`InvalidateNodeCache`, still loads inline. A generation counter stops a
refresh that started before an invalidation from marking the cache
fresh.
- The region cache no longer holds `regionObsMu` across its query. Its
refresh re-queries only the regions looked up since the previous
refresh. That keeps it bounded, because the region comes from the query
string.
2. **resolved_path after the lock** (`750dd951`). `QueryPackets`,
`QueryMultiNodePackets`, `GetTransmissionByID`, `GetPacketByHash`,
`GetPacketByID`, `GetObservationsForHash` and `GetNodeHealth` record the
lookups under the lock (`rpJob`, with a snapshot of observation IDs and
path JSON) and run them after releasing it. The number of queries per
row is unchanged.
3. **Single queries before the lock** (`bf85e63e`): the `node=` filter
(`resolveQueryNode`), multi-node pubkey resolution, the can_relay sets
in node health, the observers read for hash-size home regions
(`observerIATAs`), and the stats read in topology.
4. **Bulk health** (`93b7e8ec`): the nodes-table read runs before the
lock. The region filter, which needs the in-memory indexes, is applied
to those rows under the lock.
5. **`/paths` observations race** (`c30e9b43`, `fbf0d7ef`).
`handleNodePaths` read each candidate's canonical resolved_path after
releasing the lock, and that lookup walked `tx.Observations`, which
ingest appends to under the write lock. `-race` reports it in the new
test. The handler now copies the survivors' observation IDs and path
JSON in a short read lock, and parses after releasing it.
`fetchResolvedPathForTxBest` had no caller left and is replaced by
`bestResolvedPath`.
6. **Topology node count** (`4094d215`). Topology used `db.GetStats()`
for one field, the 7-day active node count. `GetStats` also runs
`COUNT(*)` over transmissions and observations. That count is now
`CountActiveNodes`, one query on `nodes`, and `GetStats` uses it too.

## Tests

- `TestNoSQLUnderStoreLock` parses the package and fails on any call
inside a `store.mu` section that reaches SQL, directly or through other
package functions. It allows the three caches above as callees (they
only query when cold) and the startup loaders as holders.
`TestNoSQLUnderStoreLockDetects` runs the scan on a small synthetic
source, so a scan that stops matching cannot pass silently. On master:
16 call sites. On this branch: 0.
- `TestSlowResolvedPathSQLDoesNotStallReaders` reproduces the convoy. A
test hook makes the resolved_path query take 300 ms; `/api/packets` sits
in it, the ingest writer queues, then a reader takes `RLock`. With the
lookup back under the lock (as on master) the reader waited 590 ms. On
this branch it did not wait measurably.
- `TestResolvedPathSQLRunsWithoutStoreLock` checks all seven functions
from part 2. `cache_swr_test.go` covers stale serving, one refresh per
key, inline rebuild after invalidation, and a cold region not blocking a
cached one. `TestNodePathsDoesNotReadObservationsUnlocked` fails under
`-race` with the old read. `TestCountActiveNodes` pins the 7-day count
against `GetStats`.

## Verification

- `cmd/server`: `go test ./...` green, and `go test -race` on the full
package green with 0 races, both on the final commit.
- E2E against a local server on the CI fixture: `test-e2e-playwright.js`
148/151 (3 skipped by the suite itself), plus
`test-issue-1486-collapse-reopens-detail-e2e.js`,
`test-issue-1692-packets-init-parallel-e2e.js` and
`test-channel-issue-1087-e2e.js`, all passing. The other E2E suites were
not run locally.
- Browser: packets, node detail, analytics hash sizes and topology
render. In the API responses, resolved_path is present on 44 of 50
packets, on packet detail, and on health `recentPackets`. No console
errors.

### Staging measurement

A staging instance with 129k transmissions in memory. Load ran on the
same host: 4 threads looping `/paths`,
`/api/packets?limit=200&expand=observations`, node health,
`hash-sizes?region=`, `topology?region=` and `/api/packets?node=`, while
one thread sampled `/api/healthz` every 200 ms. Each build had one
cycle: 360 s during the ingestor's startup `ANALYZE` (heavy disk reads
for 7 to 9 minutes after every restart), then 2 runs of 120 s after it
finished. Values in ms.

| | without this PR | with this PR |
|---|---|---|
| **During ANALYZE** | | |
| `healthz` p95 / p99 / max | 156 / 1105 / 5681 | 42 / 905 / 4280 |
| `topology?region` p99 / max | 2537 / 3061 | 1942 / 4159 |
| `hash-sizes?region` max | 5809 | 2866 |
| node health max | 5719 | 1110 |
| `packets?expand` max | 3912 | 2570 |
| calls over 5 s, excluding `/paths` | 2 | 0 |
| **After ANALYZE** (two runs) | | |
| `healthz` p95 / max | 444-667 / 2139-4356 | 189-335 / 1377-3238 |
| `topology?region` max | 3401-5363 | 1440-1927 |
| `/paths` p50 | 1466-4736 | 1125-2648 |
| calls over 5 s | 3 | 0 |

The two builds were measured about 50 minutes apart, so the background
traffic was not identical.

An earlier version of this branch, without `fbf0d7ef`, raised `healthz`
p95 to 2.7-2.9 s in the same setup, because it parsed every `/paths`
candidate's path JSON under the read lock. Without `4094d215`,
`topology?region` reached 8-17 s during `ANALYZE` in three cycles. The
table is for the final branch.

## Not in this PR

- The query count of `/paths` (1 to 3 per candidate,
`resolved_index.go:160`). It still dominates that endpoint, at p95 8 to
15 s on staging. It is its own item in #2146.
- Batching the resolved_path queries.
- The other per-endpoint items in #2146 (reach, channels, perf,
observers, config/regions, battery, neighbors).
- A cache's first lookup still queries inline, under the lock where the
caller holds it. That happens once per key per process, by design, and
the invariant test allows it explicitly.
- `cmd/ingestor` is unchanged. No measurement on an instance the size of
the ones in #2146.

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-09 19:58:42 +02:00

51 lines
1.1 KiB
Go

package main
import "sync"
// cacheRefresher runs at most one background refresh per key. The node,
// region-observer and area-node caches serve their stale value while it runs,
// so callers holding PacketStore.mu never wait on SQL (#2146). The zero value
// is ready to use.
type cacheRefresher struct {
mu sync.Mutex
inFlight map[string]bool
}
// start runs fn in a new goroutine unless a refresh for key is already
// running.
func (r *cacheRefresher) start(key string, fn func()) {
r.mu.Lock()
if r.inFlight[key] {
r.mu.Unlock()
return
}
if r.inFlight == nil {
r.inFlight = make(map[string]bool)
}
r.inFlight[key] = true
r.mu.Unlock()
go func() {
defer func() {
r.mu.Lock()
delete(r.inFlight, key)
r.mu.Unlock()
}()
fn()
}()
}
func (r *cacheRefresher) running(key string) bool {
r.mu.Lock()
defer r.mu.Unlock()
return r.inFlight[key]
}
// beforeCacheLoad calls the test hook, if any, right before a cache runs its
// SQL.
func (s *PacketStore) beforeCacheLoad(kind string) {
if s.cacheLoadHook != nil {
s.cacheLoadHook(kind)
}
}