mirror of
https://github.com/Kpa-clawbot/meshcore-analyzer.git
synced 2026-10-13 06:38:00 +00:00
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>
128 lines
4.6 KiB
Go
128 lines
4.6 KiB
Go
package main
|
|
|
|
import (
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
// #2146: resolved_path is fetched from SQLite on demand. The store functions
|
|
// that build response maps under s.mu must run that SQL only after releasing
|
|
// it, so a slow pool connection never holds the store lock.
|
|
|
|
// newResolvedPathStore loads one transmission whose shorter-path observation
|
|
// carries a resolved_path (the #810 fixture), so both the single-observation
|
|
// lookup and the best-of-transmission fallback run SQL.
|
|
func newResolvedPathStore(t *testing.T) *PacketStore {
|
|
t.Helper()
|
|
db := setupTestDB(t)
|
|
t.Cleanup(func() { db.Close() })
|
|
now := time.Now().UTC()
|
|
recent := now.Add(-1 * time.Hour).Format(time.RFC3339)
|
|
recentEpoch := now.Add(-1 * time.Hour).Unix()
|
|
db.conn.Exec(`INSERT INTO observers (id, name, last_seen, first_seen, packet_count) VALUES ('obs1','O1',?, '2026-01-01T00:00:00Z', 100)`, recent)
|
|
db.conn.Exec(`INSERT INTO observers (id, name, last_seen, first_seen, packet_count) VALUES ('obs2','O2',?, '2026-01-01T00:00:00Z', 100)`, recent)
|
|
db.conn.Exec(`INSERT INTO nodes (public_key, name, role, last_seen, first_seen, advert_count) VALUES ('aabbccdd11223344','R','repeater',?, '2026-01-01T00:00:00Z', 1)`, recent)
|
|
db.conn.Exec(`INSERT INTO transmissions (raw_hex, hash, first_seen, route_type, payload_type, decoded_json) VALUES ('AABB','testhash00000001',?,1,4,'{"pubKey":"aabbccdd11223344","type":"ADVERT"}')`, recent)
|
|
db.conn.Exec(`INSERT INTO observations (transmission_id, observer_idx, snr, rssi, path_json, timestamp) VALUES (1,1,12.5,-90,'["aa","bb","cc"]',?)`, recentEpoch)
|
|
db.conn.Exec(`INSERT INTO observations (transmission_id, observer_idx, snr, rssi, path_json, timestamp, resolved_path) VALUES (1,2,8.0,-95,'["aa","bb"]',?,'["aabbccdd11223344","eeff00112233aabb"]')`, recentEpoch-100)
|
|
|
|
store := NewPacketStore(db, nil)
|
|
if err := store.Load(); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
return store
|
|
}
|
|
|
|
// expectNoStoreLockDuringResolvedPathSQL fails the test when a resolved_path
|
|
// query runs while the calling goroutine holds s.mu. Background goroutines
|
|
// started by Load can hold s.mu briefly, so TryLock is retried: it keeps
|
|
// failing for the whole window only when the caller itself holds the lock.
|
|
func expectNoStoreLockDuringResolvedPathSQL(t *testing.T, s *PacketStore, caseName *string) (queries *int) {
|
|
t.Helper()
|
|
queries = new(int)
|
|
s.cacheLoadHook = func(kind string) {
|
|
if kind != "resolvedPath" {
|
|
return
|
|
}
|
|
*queries++
|
|
for deadline := time.Now().Add(time.Second); time.Now().Before(deadline); time.Sleep(time.Millisecond) {
|
|
if s.mu.TryLock() {
|
|
s.mu.Unlock()
|
|
return
|
|
}
|
|
}
|
|
t.Errorf("%s: resolved_path SQL ran while s.mu was held", *caseName)
|
|
}
|
|
return queries
|
|
}
|
|
|
|
func clearResolvedPathLRU(s *PacketStore) {
|
|
s.lruMu.Lock()
|
|
s.apiResolvedPathLRU = make(map[int][]*string)
|
|
s.lruOrder = nil
|
|
s.lruMu.Unlock()
|
|
}
|
|
|
|
func TestResolvedPathSQLRunsWithoutStoreLock(t *testing.T) {
|
|
s := newResolvedPathStore(t)
|
|
var caseName string
|
|
queries := expectNoStoreLockDuringResolvedPathSQL(t, s, &caseName)
|
|
|
|
s.mu.RLock()
|
|
tx := s.byHash["testhash00000001"]
|
|
s.mu.RUnlock()
|
|
|
|
hasRP := func(m map[string]interface{}) bool { return m != nil && m["resolved_path"] != nil }
|
|
cases := []struct {
|
|
name string
|
|
run func() bool
|
|
}{
|
|
{"QueryPackets", func() bool {
|
|
r := s.QueryPackets(PacketQuery{Limit: 10, ExpandObservations: true})
|
|
return len(r.Packets) == 1 && hasRP(r.Packets[0])
|
|
}},
|
|
{"QueryMultiNodePackets", func() bool {
|
|
r := s.QueryMultiNodePackets([]string{"aabbccdd11223344"}, 10, 0, "DESC", "", "")
|
|
return len(r.Packets) == 1 && hasRP(r.Packets[0])
|
|
}},
|
|
{"GetTransmissionByID", func() bool { return hasRP(s.GetTransmissionByID(tx.ID)) }},
|
|
{"GetPacketByHash", func() bool { return hasRP(s.GetPacketByHash("testhash00000001")) }},
|
|
{"GetPacketByID", func() bool {
|
|
// the observation carrying the resolved_path
|
|
for _, o := range tx.Observations {
|
|
if m := s.GetPacketByID(o.ID); hasRP(m) {
|
|
return true
|
|
}
|
|
}
|
|
return false
|
|
}},
|
|
{"GetObservationsForHash", func() bool {
|
|
for _, m := range s.GetObservationsForHash("testhash00000001") {
|
|
if hasRP(m) {
|
|
return true
|
|
}
|
|
}
|
|
return false
|
|
}},
|
|
{"GetNodeHealth", func() bool {
|
|
h, err := s.GetNodeHealth("aabbccdd11223344")
|
|
if err != nil || h == nil {
|
|
return false
|
|
}
|
|
rp, _ := h["recentPackets"].([]map[string]interface{})
|
|
return len(rp) == 1 && hasRP(rp[0])
|
|
}},
|
|
}
|
|
for _, c := range cases {
|
|
caseName = c.name
|
|
clearResolvedPathLRU(s)
|
|
before := *queries
|
|
if !c.run() {
|
|
t.Errorf("%s: want resolved_path in the response", c.name)
|
|
}
|
|
if *queries == before {
|
|
t.Errorf("%s: no resolved_path SQL ran, so the lock check proved nothing", c.name)
|
|
}
|
|
}
|
|
}
|