diff --git a/cmd/server/analytics_recomputer.go b/cmd/server/analytics_recomputer.go index 9917930d..82a51128 100644 --- a/cmd/server/analytics_recomputer.go +++ b/cmd/server/analytics_recomputer.go @@ -152,6 +152,7 @@ type AnalyticsRecomputeIntervals struct { Channels time.Duration HashCollisions time.Duration HashSizes time.Duration + Roles time.Duration } func pickInterval(override, def time.Duration) time.Duration { @@ -219,9 +220,14 @@ func (s *PacketStore) StartAnalyticsRecomputers(defaultInterval time.Duration, o "hash-sizes", pickInterval(ov.HashSizes, defaultInterval), func() interface{} { return s.computeAnalyticsHashSizesWithCapability("") }, ) + s.recompRoles = newAnalyticsRecomputer( + "roles", pickInterval(ov.Roles, defaultInterval), + func() interface{} { return s.computeAnalyticsRoles() }, + ) all := []*analyticsRecomputer{ s.recompTopology, s.recompRF, s.recompDistance, s.recompChannels, s.recompHashCollisions, s.recompHashSizes, + s.recompRoles, } s.analyticsRecomputerMu.Unlock() diff --git a/cmd/server/config.go b/cmd/server/config.go index 3f2c3706..00f83085 100644 --- a/cmd/server/config.go +++ b/cmd/server/config.go @@ -540,8 +540,7 @@ func (c *Config) IsObserverBlacklisted(id string) bool { // data slowly." Lower values give fresher data at higher CPU cost. // // RecomputeIntervalSeconds keys (all optional): -// -// topology, rf, distance, channels, hashCollisions, hashSizes +// topology, rf, distance, channels, hashCollisions, hashSizes, roles type AnalyticsConfig struct { DefaultIntervalSeconds int `json:"defaultIntervalSeconds,omitempty"` RecomputeIntervalSeconds map[string]int `json:"recomputeIntervalSeconds,omitempty"` @@ -577,5 +576,6 @@ func (c *Config) AnalyticsRecomputeIntervals() AnalyticsRecomputeIntervals { out.Channels = get("channels") out.HashCollisions = get("hashCollisions") out.HashSizes = get("hashSizes") + out.Roles = get("roles") return out } diff --git a/cmd/server/main.go b/cmd/server/main.go index f258851c..7c0a1fb2 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -362,6 +362,21 @@ func main() { defer stopAnalyticsRecomp() log.Printf("[analytics-recompute] background recompute enabled (default=%s)", cfg.AnalyticsDefaultRecomputeInterval()) + // Steady-state repeater-enrichment recomputer (issue #1262). + // Prewarms the bulk caches feeding handleNodes so the very first + // /api/nodes?limit=2000 from live.js's SPA bootstrap hits a + // populated cache instead of paying a 15.7s on-thread rebuild. + // Uses the configured RelayActiveHours window and the same + // default recompute interval as the other analytics caches. + relayWindowHours := cfg.GetHealthThresholds().RelayActiveHours + stopRepeaterEnrichRecomp := store.StartRepeaterEnrichmentRecomputer( + relayWindowHours, + cfg.AnalyticsDefaultRecomputeInterval(), + ) + defer stopRepeaterEnrichRecomp() + log.Printf("[repeater-enrich-recompute] background recompute enabled (window=%.1fh, interval=%s)", + relayWindowHours, cfg.AnalyticsDefaultRecomputeInterval()) + // Auto-prune old packets if retention.packetDays is configured vacuumPages := cfg.IncrementalVacuumPages() var stopPrune func() diff --git a/cmd/server/nodes_perf_limit2000_test.go b/cmd/server/nodes_perf_limit2000_test.go new file mode 100644 index 00000000..e03a7ad3 --- /dev/null +++ b/cmd/server/nodes_perf_limit2000_test.go @@ -0,0 +1,119 @@ +package main + +import ( + "fmt" + "net/http" + "net/http/httptest" + "testing" + "time" +) + +// TestHandleNodesLimit2000ColdMiss is a regression guard for issue #1262. +// +// Background: PR #1260 added a 15s-TTL bulk-cache for repeater +// enrichment in handleNodes (GetRepeaterRelayInfoMap / +// GetRepeaterUsefulnessScoreMap). On warm hits the request is ~40ms. +// On the very first request after server startup (or after the 15s TTL +// expires) the cache rebuild runs on the request-serving goroutine and +// is O(byPathHop + parsed timestamps). On staging (75k tx, 600 nodes) +// the cold rebuild took 15.7s. +// +// /api/nodes?limit=2000 is the SPA's hop-resolver bootstrap call (see +// public/live.js) so EVERY cold SPA load eats the cold-rebuild cost. +// +// Acceptance: /api/nodes?limit=2000 must return in <2s on a +// realistic-shape fleet WITHOUT a prior warmup request — i.e. once the +// store has been initialized and the steady-state repeater-enrichment +// recomputer prewarm has run. +func TestHandleNodesLimit2000ColdMiss(t *testing.T) { + if testing.Short() { + t.Skip("perf test") + } + srv, router := setupTestServer(t) + conn := srv.db.conn + + // Seed 600 nodes — 50 repeaters/rooms with most-recent last_seen so + // they sit at the top of the limit=2000 page, plus 550 stale + // companions. + tx, err := conn.Begin() + if err != nil { + t.Fatal(err) + } + stmt, err := tx.Prepare(`INSERT INTO nodes + (public_key, name, role, lat, lon, last_seen, first_seen, advert_count, foreign_advert) + VALUES (?, ?, ?, 0, 0, ?, '2026-01-01T00:00:00Z', 1, 0)`) + if err != nil { + t.Fatal(err) + } + now := time.Now().UTC() + for i := 0; i < 50; i++ { + pk := fmt.Sprintf("pkrepeat%056x", i) + ts := now.Add(-time.Duration(i) * time.Minute).Format(time.RFC3339Nano) + if _, err := stmt.Exec(pk, fmt.Sprintf("rep%d", i), "repeater", ts); err != nil { + t.Fatal(err) + } + } + for i := 0; i < 550; i++ { + pk := fmt.Sprintf("pkcompan%056x", i) + ts := now.Add(-time.Duration(60+i) * time.Minute).Format(time.RFC3339Nano) + if _, err := stmt.Exec(pk, fmt.Sprintf("comp%d", i), "companion", ts); err != nil { + t.Fatal(err) + } + } + if err := tx.Commit(); err != nil { + t.Fatal(err) + } + + // Seed the in-memory packet store: a non-trivial body of non-advert + // traffic where each repeater appears as a path hop on many txs. + // This is what makes the bulk-cache rebuild expensive. + const numTx = 150000 + const hopsPerTx = 6 + pt2 := 2 + store := srv.store + for i := 0; i < numTx; i++ { + txID := 100000 + i + ts := now.Add(-time.Duration(i) * time.Second).Format(time.RFC3339Nano) + stx := &StoreTx{ + ID: txID, + Hash: fmt.Sprintf("h%d", txID), + FirstSeen: ts, + PayloadType: &pt2, + } + store.byPayloadType[pt2] = append(store.byPayloadType[pt2], stx) + // Shared 1-byte prefix bucket to mirror production hop-prefix + // collisions. + store.byPathHop["pk"] = append(store.byPathHop["pk"], stx) + for h := 0; h < hopsPerTx; h++ { + repIdx := (i + h) % 50 + pk := fmt.Sprintf("pkrepeat%056x", repIdx) + store.byPathHop[pk] = append(store.byPathHop[pk], stx) + } + } + + // Steady-state repeater-enrichment recomputer (the fix for #1262) + // prewarms the bulk caches at startup so the first handler request + // — which is /api/nodes?limit=2000 from live.js on every cold SPA + // load — hits the cache instead of rebuilding it on-thread. + stop := store.StartRepeaterEnrichmentRecomputer(24, 5*time.Minute) + defer stop() + + // NO HTTP warmup — we are explicitly measuring the first + // limit=2000 request, the way live.js sees it. + + start := time.Now() + req := httptest.NewRequest("GET", "/api/nodes?limit=2000", nil) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + elapsed := time.Since(start) + if w.Code != http.StatusOK { + t.Fatalf("status=%d body=%s", w.Code, w.Body.String()) + } + + const budget = 2 * time.Second + t.Logf("/api/nodes?limit=2000 elapsed=%v on %d nodes, %d tx", elapsed, 600, numTx) + if elapsed > budget { + t.Fatalf("/api/nodes?limit=2000 cold-miss too slow for #1262: %v (budget %v) on %d nodes, %d tx", + elapsed, budget, 600, numTx) + } +} diff --git a/cmd/server/nodes_perf_test.go b/cmd/server/nodes_perf_test.go new file mode 100644 index 00000000..a1f8921e --- /dev/null +++ b/cmd/server/nodes_perf_test.go @@ -0,0 +1,127 @@ +package main + +import ( + "fmt" + "net/http" + "net/http/httptest" + "testing" + "time" +) + +// TestHandleNodesPerfLargeFleet asserts the /api/nodes endpoint (no `limit` +// param — relying on the server-side default) returns in well under 2s on a +// realistic-shape fleet: 600 nodes, ~50 of them repeaters/rooms with rich +// path-hop activity, and a non-trivial byPayloadType + byPathHop index. +// +// Regression guard for issue #1257: +// /api/nodes (no limit) → 32.9s, 30KB on staging (637 nodes) +// /api/nodes?limit=2000 → 4.9s, 360KB +// +// Root cause class: per-repeater enrichment in handleNodes calls +// store.GetRepeaterRelayInfo + GetRepeaterUsefulnessScore separately for +// each node in the page. Each call takes its own RLock and walks +// byPathHop[pk] / byPayloadType, doing expensive timestamp parsing. +// For the default-page case (top-50 by last_seen, mostly hot repeaters) +// that is hundreds of thousands of timestamp parses per request. +// +// Budget: 2s. On the broken implementation with this fixture the +// endpoint blows the budget; with batched/cached per-page enrichment it +// completes in well under 500ms. +func TestHandleNodesPerfLargeFleet(t *testing.T) { + if testing.Short() { + t.Skip("perf test") + } + srv, router := setupTestServer(t) + conn := srv.db.conn + + // Seed 600 nodes — 50 repeaters/rooms with most-recent last_seen so + // they land on the default page, plus 550 stale companions. + tx, err := conn.Begin() + if err != nil { + t.Fatal(err) + } + stmt, err := tx.Prepare(`INSERT INTO nodes + (public_key, name, role, lat, lon, last_seen, first_seen, advert_count, foreign_advert) + VALUES (?, ?, ?, 0, 0, ?, '2026-01-01T00:00:00Z', 1, 0)`) + if err != nil { + t.Fatal(err) + } + now := time.Now().UTC() + for i := 0; i < 50; i++ { + pk := fmt.Sprintf("pkrepeat%056x", i) + ts := now.Add(-time.Duration(i) * time.Minute).Format(time.RFC3339Nano) + if _, err := stmt.Exec(pk, fmt.Sprintf("rep%d", i), "repeater", ts); err != nil { + t.Fatal(err) + } + } + for i := 0; i < 550; i++ { + pk := fmt.Sprintf("pkcompan%056x", i) + ts := now.Add(-time.Duration(60+i) * time.Minute).Format(time.RFC3339Nano) + if _, err := stmt.Exec(pk, fmt.Sprintf("comp%d", i), "companion", ts); err != nil { + t.Fatal(err) + } + } + if err := tx.Commit(); err != nil { + t.Fatal(err) + } + + // Seed the in-memory packet store: a body of non-advert traffic with + // each repeater appearing as a path hop on many of them. This is what + // makes the per-node GetRepeaterRelayInfo / GetRepeaterUsefulnessScore + // calls expensive on the broken impl. + const numTx = 150000 + const hopsPerTx = 6 + pt2 := 2 // non-advert payload type + store := srv.store + // Also index every tx under a single shared 1-byte prefix so the + // GetRepeaterRelayInfo prefix-collision branch fans every per-node + // call through the full non-advert tx set (matches production where + // many repeaters share a 1-byte hop prefix). + for i := 0; i < numTx; i++ { + txID := 100000 + i + ts := now.Add(-time.Duration(i) * time.Second).Format(time.RFC3339Nano) + stx := &StoreTx{ + ID: txID, + Hash: fmt.Sprintf("h%d", txID), + FirstSeen: ts, + PayloadType: &pt2, + } + store.byPayloadType[pt2] = append(store.byPayloadType[pt2], stx) + store.byPathHop["pk"] = append(store.byPathHop["pk"], stx) + // Index each repeater under byPathHop so per-node enrichment walks + // a non-trivial slice. + for h := 0; h < hopsPerTx; h++ { + repIdx := (i + h) % 50 + pk := fmt.Sprintf("pkrepeat%056x", repIdx) + store.byPathHop[pk] = append(store.byPathHop[pk], stx) + } + } + + // Warm-up to amortize first-call costs (cache misses, prepare). Note: + // the per-node Repeater* enrichment is NOT cached, so this warmup + // does not hide the perf bug — it only amortizes one-shot prep. + { + req := httptest.NewRequest("GET", "/api/nodes?limit=1", nil) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + if w.Code != http.StatusOK { + t.Fatalf("warmup status=%d body=%s", w.Code, w.Body.String()) + } + } + + start := time.Now() + req := httptest.NewRequest("GET", "/api/nodes", nil) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + elapsed := time.Since(start) + if w.Code != http.StatusOK { + t.Fatalf("status=%d body=%s", w.Code, w.Body.String()) + } + + const budget = 2 * time.Second + t.Logf("/api/nodes (no limit) elapsed=%v on %d nodes, %d tx", elapsed, 600, numTx) + if elapsed > budget { + t.Fatalf("/api/nodes (no limit) too slow for #1257: %v (budget %v) on %d nodes, %d tx", + elapsed, budget, 600, numTx) + } +} diff --git a/cmd/server/repeater_enrich_bulk.go b/cmd/server/repeater_enrich_bulk.go new file mode 100644 index 00000000..e53ee542 --- /dev/null +++ b/cmd/server/repeater_enrich_bulk.go @@ -0,0 +1,265 @@ +package main + +import ( + "strings" + "time" +) + +// repeaterEnrichTTL bounds how stale the per-page bulk enrichment caches +// for handleNodes may be. Same 15s budget as GetNodeHashSizeInfo — the +// numbers feed an at-a-glance status column, not an alerting path, so +// up-to-15s freshness is fine and keeps the request path O(page) instead +// of O(page × byPathHop[pk] × parsed timestamps). +const repeaterEnrichTTL = 15 * time.Second + +// GetRepeaterRelayInfoMap returns a cached pubkey → RepeaterRelayInfo +// map covering EVERY pubkey that currently appears as a path hop in any +// non-advert StoreTx. This is the bulk equivalent of calling +// GetRepeaterRelayInfo(pk, windowHours) once per node. +// +// Why this exists (issue #1257): handleNodes used to call the per-node +// helper inside a per-page loop. Each call grabbed its own RLock and +// re-parsed FirstSeen on every StoreTx indexed under that pubkey's +// byPathHop entry (plus, when the pubkey was >= 2 hex chars, the 1-byte +// prefix bucket — which on busy networks fans out to almost the whole +// non-advert tx set). For the default top-50 page of hot repeaters this +// burned 50 lock acquisitions and hundreds of thousands of timestamp +// parses per request, dominating /api/nodes latency. +// +// The cached map is keyed by lowercase pubkey/hop key (same shape as +// byPathHop). Lookups should use strings.ToLower(pk). +// +// The cache is invalidated by TTL only — never by ingest. With a 15s +// budget that's acceptable for a status column; if a fresher signal is +// ever needed for a non-status caller, expose a non-cached path. +func (s *PacketStore) GetRepeaterRelayInfoMap(windowHours float64) map[string]RepeaterRelayInfo { + s.repeaterEnrichMu.Lock() + if s.repeaterRelayCache != nil && + time.Since(s.repeaterRelayAt) < repeaterEnrichTTL && + s.repeaterRelayCacheWin == windowHours { + cached := s.repeaterRelayCache + s.repeaterEnrichMu.Unlock() + return cached + } + s.repeaterEnrichMu.Unlock() + + result := s.computeRepeaterRelayInfoMap(windowHours) + + s.repeaterEnrichMu.Lock() + s.repeaterRelayCache = result + s.repeaterRelayCacheWin = windowHours + s.repeaterRelayAt = time.Now() + s.repeaterEnrichMu.Unlock() + return result +} + +// computeRepeaterRelayInfoMap walks byPathHop once under a single RLock, +// pre-parses every FirstSeen timestamp once (not once-per-pubkey-bucket), +// and emits one RepeaterRelayInfo per hop key. +// +// Time-complexity invariant: O(unique-tx-in-byPathHop + total-key-bucket +// entries). Memory: one map entry per byPathHop key. Both are bounded by +// the same eviction policy that bounds byPathHop itself. +func (s *PacketStore) computeRepeaterRelayInfoMap(windowHours float64) map[string]RepeaterRelayInfo { + s.mu.RLock() + + // Snapshot the slices (header copy) so we can release the lock before + // the expensive parse pass. Slice headers point at the live underlying + // arrays but those are append-only-by-id; the worst-case race here is + // that ingest grows a slice we already snapshotted (we miss the new + // tail), which is acceptable for a 15s-TTL status read. + snap := make(map[string][]*StoreTx, len(s.byPathHop)) + for k, list := range s.byPathHop { + snap[k] = list + } + + // Build a tx-id-keyed pre-parsed cache so the inner loop doesn't + // re-parse the same FirstSeen N times when the same tx is indexed + // under multiple hop keys (very common — every hop on a path indexes + // the tx). + type parsedTx struct { + t time.Time + ok bool + pt int + } + parseCache := make(map[int]parsedTx, 1<<14) + for _, list := range snap { + for _, tx := range list { + if tx == nil { + continue + } + if _, ok := parseCache[tx.ID]; ok { + continue + } + pt := -1 + if tx.PayloadType != nil { + pt = *tx.PayloadType + } + t, ok := parseRelayTS(tx.FirstSeen) + parseCache[tx.ID] = parsedTx{t: t, ok: ok, pt: pt} + } + } + s.mu.RUnlock() + + now := time.Now().UTC() + cutoff1h := now.Add(-1 * time.Hour) + cutoff24h := now.Add(-24 * time.Hour) + var windowCutoff time.Time + if windowHours > 0 { + windowCutoff = now.Add(-time.Duration(windowHours * float64(time.Hour))) + } + + out := make(map[string]RepeaterRelayInfo, len(snap)) + for key, list := range snap { + info := RepeaterRelayInfo{WindowHours: windowHours} + // When key looks like a full pubkey (>= 2 hex chars), also fold + // in the matching 1-byte raw-prefix bucket to mirror + // GetRepeaterRelayInfo's behavior. We dedup by tx ID. + var seen map[int]bool + if len(key) >= 2 { + prefix := key[:2] + if prefix != key { + if extra := snap[prefix]; len(extra) > 0 { + seen = make(map[int]bool, len(list)+len(extra)) + } + } + } + visit := func(txs []*StoreTx) { + for _, tx := range txs { + if tx == nil { + continue + } + if seen != nil { + if seen[tx.ID] { + continue + } + seen[tx.ID] = true + } + p, ok := parseCache[tx.ID] + if !ok { + continue + } + if p.pt == payloadTypeAdvert { + continue + } + if !p.ok { + continue + } + if p.t.After(cutoff24h) { + info.RelayCount24h++ + if p.t.After(cutoff1h) { + info.RelayCount1h++ + } + } + if info.LastRelayed == "" || tx.FirstSeen > info.LastRelayed { + info.LastRelayed = tx.FirstSeen + if windowHours > 0 && p.t.After(windowCutoff) { + info.RelayActive = true + } else if windowHours > 0 { + info.RelayActive = false + } + } + } + } + visit(list) + if seen != nil { + prefix := key[:2] + if prefix != key { + visit(snap[prefix]) + } + } + out[key] = info + } + return out +} + +// GetRepeaterUsefulnessScoreMap returns a cached pubkey → 0..1 score +// for every pubkey appearing in byPathHop. Bulk equivalent of +// GetRepeaterUsefulnessScore. See GetRepeaterRelayInfoMap for the +// motivation (#1257). +func (s *PacketStore) GetRepeaterUsefulnessScoreMap() map[string]float64 { + s.repeaterEnrichMu.Lock() + if s.repeaterUsefulCache != nil && time.Since(s.repeaterUsefulAt) < repeaterEnrichTTL { + cached := s.repeaterUsefulCache + s.repeaterEnrichMu.Unlock() + return cached + } + s.repeaterEnrichMu.Unlock() + + result := s.computeRepeaterUsefulnessScoreMap() + + s.repeaterEnrichMu.Lock() + s.repeaterUsefulCache = result + s.repeaterUsefulAt = time.Now() + s.repeaterEnrichMu.Unlock() + return result +} + +func (s *PacketStore) computeRepeaterUsefulnessScoreMap() map[string]float64 { + s.mu.RLock() + defer s.mu.RUnlock() + + totalNonAdvert := 0 + for pt, list := range s.byPayloadType { + if pt == payloadTypeAdvert { + continue + } + totalNonAdvert += len(list) + } + out := make(map[string]float64, len(s.byPathHop)) + if totalNonAdvert == 0 { + return out + } + denom := float64(totalNonAdvert) + for key, list := range s.byPathHop { + relayed := 0 + for _, tx := range list { + if tx == nil { + continue + } + if tx.PayloadType != nil && *tx.PayloadType == payloadTypeAdvert { + continue + } + relayed++ + } + if relayed == 0 { + continue + } + score := float64(relayed) / denom + if score < 0 { + score = 0 + } else if score > 1 { + score = 1 + } + out[key] = score + } + return out +} + +// lookupRelayInfo is a small helper to make handleNodes' map lookup +// case-insensitive (byPathHop keys are lowercase; pubkeys arriving from +// the DB row may be either case). +func lookupRelayInfo(m map[string]RepeaterRelayInfo, pubkey string) (RepeaterRelayInfo, bool) { + if v, ok := m[pubkey]; ok { + return v, true + } + if lc := strings.ToLower(pubkey); lc != pubkey { + if v, ok := m[lc]; ok { + return v, true + } + } + return RepeaterRelayInfo{}, false +} + +// lookupUsefulnessScore mirrors lookupRelayInfo for the score map. +func lookupUsefulnessScore(m map[string]float64, pubkey string) float64 { + if v, ok := m[pubkey]; ok { + return v + } + if lc := strings.ToLower(pubkey); lc != pubkey { + if v, ok := m[lc]; ok { + return v + } + } + return 0 +} diff --git a/cmd/server/repeater_enrich_recomputer.go b/cmd/server/repeater_enrich_recomputer.go new file mode 100644 index 00000000..0400f853 --- /dev/null +++ b/cmd/server/repeater_enrich_recomputer.go @@ -0,0 +1,104 @@ +package main + +import ( + "sync" + "time" +) + +// repeaterEnrichmentRecomputerInterval is the default tick interval +// for the steady-state recompute of the repeater enrichment bulk +// caches. The on-request 15s-TTL fallback in repeater_enrich_bulk.go +// is kept as a safety net — the recomputer just makes sure the cache +// is populated before any request arrives. +// +// 5min mirrors the analytics_recomputer default from #1240 and is +// plenty fresh for an at-a-glance status column. +const repeaterEnrichmentRecomputerDefaultInterval = 5 * time.Minute + +// StartRepeaterEnrichmentRecomputer is the steady-state background +// recompute loop for the repeater enrichment bulk caches consumed by +// handleNodes (GetRepeaterRelayInfoMap + GetRepeaterUsefulnessScoreMap). +// +// Why this exists (issue #1262): PR #1260 added a 15s-TTL bulk cache, +// but the rebuild itself runs on the request-serving goroutine on the +// first request after startup or after the TTL expires. On staging +// (75k tx, 600 nodes) that cold rebuild took 15.7s and was triggered +// by every cold SPA load via live.js's /api/nodes?limit=2000 call. +// +// On Start this does an initial synchronous compute (so the next +// request hits cache) and then ticks every `interval` to keep the +// snapshot fresh — same pattern as analytics_recomputer.go (#1240). +// +// Returns a stop closure that signals the goroutine and waits for it +// to exit (with a 5s defensive timeout). +// +// Safe to call multiple times: subsequent calls are no-ops and return +// a no-op stop closure (the original goroutine retains ownership). +func (s *PacketStore) StartRepeaterEnrichmentRecomputer(windowHours float64, interval time.Duration) func() { + if interval <= 0 { + interval = repeaterEnrichmentRecomputerDefaultInterval + } + + s.repeaterEnrichRecompMu.Lock() + if s.repeaterEnrichRecompStarted { + s.repeaterEnrichRecompMu.Unlock() + return func() {} + } + s.repeaterEnrichRecompStarted = true + stop := make(chan struct{}) + done := make(chan struct{}) + s.repeaterEnrichRecompStop = stop + s.repeaterEnrichRecompDone = done + s.repeaterEnrichRecompMu.Unlock() + + // Initial synchronous prewarm — the entire point of this recomputer + // is to make sure the very first /api/nodes?limit=2000 from + // live.js's SPA bootstrap (issue #1262) hits a populated cache + // instead of paying the on-thread rebuild cost. + recomputeRepeaterEnrichmentSafe(s, windowHours) + + var stopOnce sync.Once + go func() { + defer close(done) + t := time.NewTicker(interval) + defer t.Stop() + for { + select { + case <-t.C: + recomputeRepeaterEnrichmentSafe(s, windowHours) + case <-stop: + return + } + } + }() + + return func() { + stopOnce.Do(func() { + close(stop) + }) + select { + case <-done: + case <-time.After(5 * time.Second): + } + } +} + +// recomputeRepeaterEnrichmentSafe runs both bulk-cache compute paths +// behind a panic recover — a panic in compute must not kill the +// background goroutine (the previous snapshot remains valid). +func recomputeRepeaterEnrichmentSafe(s *PacketStore, windowHours float64) { + defer func() { _ = recover() }() + // Bypass the 15s-TTL gate by forcing a fresh recompute and + // installing the result. The public Get* helpers would return the + // existing cache when within TTL; we want to refresh proactively. + relay := s.computeRepeaterRelayInfoMap(windowHours) + useful := s.computeRepeaterUsefulnessScoreMap() + now := time.Now() + s.repeaterEnrichMu.Lock() + s.repeaterRelayCache = relay + s.repeaterRelayCacheWin = windowHours + s.repeaterRelayAt = now + s.repeaterUsefulCache = useful + s.repeaterUsefulAt = now + s.repeaterEnrichMu.Unlock() +} diff --git a/cmd/server/resolve_with_context_bench_test.go b/cmd/server/resolve_with_context_bench_test.go new file mode 100644 index 00000000..953145be --- /dev/null +++ b/cmd/server/resolve_with_context_bench_test.go @@ -0,0 +1,123 @@ +package main + +import ( + "fmt" + "testing" + "time" +) + +// buildResolveTier1HotFixture constructs the synthetic graph + pm shape +// used by both the benchmark and the regression-guard test below. Shape: +// ambiguous prefix "ab" → numCands candidates, plus numContext context +// pubkeys each with edges into the first 3 candidates. This drives the +// tier-1 inner loop to its full path length on every resolve call. +func buildResolveTier1HotFixture(numCands, numContext int) (*prefixMap, *NeighborGraph, []string) { + nodes := make([]nodeInfo, 0, numCands+numContext) + for i := 0; i < numCands; i++ { + nodes = append(nodes, nodeInfo{ + PublicKey: fmt.Sprintf("ab%010x", i*0x10101010+1), + Role: "repeater", + Name: fmt.Sprintf("C%d", i), + }) + } + contextPubkeys := make([]string, 0, numContext) + for i := 0; i < numContext; i++ { + pk := fmt.Sprintf("c%011x", i*0x12345) + nodes = append(nodes, nodeInfo{PublicKey: pk, Role: "repeater", Name: fmt.Sprintf("X%d", i)}) + contextPubkeys = append(contextPubkeys, pk) + } + pm := buildPrefixMap(nodes) + + graph := NewNeighborGraph() + now := time.Now() + addEdge := func(a, b string, count int, observers ...string) { + obs := make(map[string]bool, len(observers)) + for _, o := range observers { + obs[o] = true + } + key := makeEdgeKey(a, b) + e := &NeighborEdge{ + NodeA: key.A, + NodeB: key.B, + Count: count, + FirstSeen: now.Add(-1 * time.Hour), + LastSeen: now, + Observers: obs, + } + graph.edges[key] = e + graph.byNode[key.A] = append(graph.byNode[key.A], e) + graph.byNode[key.B] = append(graph.byNode[key.B], e) + } + winnerPK := nodes[0].PublicKey + for _, cpk := range contextPubkeys { + addEdge(cpk, winnerPK, 20, "obs1", "obs2", "obs3") + for k := 1; k < 3 && k < numCands; k++ { + addEdge(cpk, nodes[k].PublicKey, 3, "obs1") + } + } + return pm, graph, contextPubkeys +} + +// BenchmarkResolveWithContextTier1Hot reproduces the analytics-topology hot +// path that regressed between prod d818527 and master (issue #1247). +// +// Shape: ambiguous prefix → N candidates → C context pubkeys. This is +// representative of the per-tx work done inside computeAnalyticsTopology / +// computeAnalyticsRF when calling resolveHop on every hop of every tx with a +// fully-populated aggregate hop context (5k+ contextPubkeys at the staging +// scale). +// +// Before the #1247 fix: ~200 µs/op on this shape (the regressed master). +// After: <50 µs/op on the same shape (≥4× improvement, well clear of the +// 2× regression-guard threshold asserted by TestResolveWithContextTier1Floor). +func BenchmarkResolveWithContextTier1Hot(b *testing.B) { + pm, graph, contextPubkeys := buildResolveTier1HotFixture(8, 64) + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + _, _, _ = pm.resolveWithContext("ab", contextPubkeys, graph) + } +} + +// TestResolveWithContextTier1Floor is the assertion-style regression guard +// for #1247. It runs the same hot shape as the benchmark and asserts that +// the per-call cost stays well under the regressed baseline. +// +// Methodology: 2000 calls measured under -short=false; total budget 200 ms +// allows ~100 µs/call which is 2× the post-fix ceiling but ~2× UNDER the +// pre-fix 200 µs/op number. If a future change reintroduces the per- +// (cand, ctx) graph.Neighbors lookup or the strings.EqualFold tax, the +// test fails and the change is forced to justify the regression. +func TestResolveWithContextTier1Floor(t *testing.T) { + if testing.Short() { + t.Skip("skipping perf floor under -short") + } + pm, graph, contextPubkeys := buildResolveTier1HotFixture(8, 64) + const iters = 2000 + // Warm up — first call allocates lookup maps; we measure steady state. + for i := 0; i < 50; i++ { + _, _, _ = pm.resolveWithContext("ab", contextPubkeys, graph) + } + t0 := time.Now() + for i := 0; i < iters; i++ { + _, _, _ = pm.resolveWithContext("ab", contextPubkeys, graph) + } + elapsed := time.Since(t0) + perCall := elapsed / iters + // 500 µs/call is the CI-floor-safe ceiling. Rationale: + // - Post-fix steady-state on arm64 dev hardware: ~50 µs/call. + // - x86_64 GitHub-hosted runners measure ~340 µs/call on this + // microbenchmark (≈5–7× slower than the arm64 dev box due to + // shared-tenant CPU contention and cache behavior on this shape). + // - Pre-fix regressed master measured ~1500 µs/call+ on the same + // runners, so 500 µs still catches the regression class with + // ~3× headroom and avoids CI-flake from runner variance. + // If a future change reintroduces the per-(cand, ctx) Neighbors + // lookup or the EqualFold tax, this test still fails loudly. + const ceiling = 500 * time.Microsecond + if perCall > ceiling { + t.Fatalf("resolveWithContext tier-1 perf regressed: %v/call (>%v ceiling); see #1247", perCall, ceiling) + } + t.Logf("resolveWithContext tier-1: %v/call (ceiling %v)", perCall, ceiling) +} + diff --git a/cmd/server/role_analytics.go b/cmd/server/role_analytics.go index 1519a854..6760b3e3 100644 --- a/cmd/server/role_analytics.go +++ b/cmd/server/role_analytics.go @@ -111,23 +111,56 @@ func computeRoleAnalytics(nodesByPubkey map[string]string, skewByPubkey map[stri return resp } -// handleAnalyticsRoles serves /api/analytics/roles. +// handleAnalyticsRoles serves /api/analytics/roles. Reads from the +// steady-state recomputer snapshot (issue #1256) so the request never +// holds s.mu.RLock for a full clock-skew recompute over the advert +// transmissions — that path hung >60s on staging with 78k tx. func (s *Server) handleAnalyticsRoles(w http.ResponseWriter, r *http.Request) { if s.store == nil { writeJSON(w, RoleAnalyticsResponse{Roles: []RoleStats{}}) return } - nodes, _ := s.store.getCachedNodesAndPM() + writeJSON(w, s.store.GetAnalyticsRoles()) +} + +// GetAnalyticsRoles returns the role-distribution analytics, preferring +// the steady-state recomputer snapshot (issue #1256). Falls back to an +// on-request compute path if the recomputer is not yet running (e.g. +// during the brief startup window before the initial compute completes +// — Start runs it synchronously, so this fallback is effectively only +// hit in tests that skip the recomputer entirely). +func (s *PacketStore) GetAnalyticsRoles() RoleAnalyticsResponse { + s.analyticsRecomputerMu.RLock() + rc := s.recompRoles + s.analyticsRecomputerMu.RUnlock() + if rc != nil { + if v := rc.Load(); v != nil { + if r, ok := v.(RoleAnalyticsResponse); ok { + s.cacheMu.Lock() + s.cacheHits++ + s.cacheMu.Unlock() + return r + } + } + } + return s.computeAnalyticsRoles() +} + +// computeAnalyticsRoles runs the actual role aggregation. Used by the +// background recomputer (issue #1256) and as a fallback for callers +// arriving before the snapshot is populated. +func (s *PacketStore) computeAnalyticsRoles() RoleAnalyticsResponse { + nodes, _ := s.getCachedNodesAndPM() roles := make(map[string]string, len(nodes)) for _, n := range nodes { roles[n.PublicKey] = n.Role } skewMap := make(map[string]*NodeClockSkew) - for _, cs := range s.store.GetFleetClockSkew() { + for _, cs := range s.GetFleetClockSkew() { if cs == nil { continue } skewMap[cs.Pubkey] = cs } - writeJSON(w, computeRoleAnalytics(roles, skewMap)) + return computeRoleAnalytics(roles, skewMap) } diff --git a/cmd/server/role_analytics_recompute_test.go b/cmd/server/role_analytics_recompute_test.go new file mode 100644 index 00000000..8fd1ab7d --- /dev/null +++ b/cmd/server/role_analytics_recompute_test.go @@ -0,0 +1,97 @@ +package main + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "testing" + "time" +) + +// TestRolesAnalyticsRecomputerRegistered asserts that the +// /api/analytics/roles endpoint is backed by the steady-state +// analytics recomputer (issue #1256). On master, roles was +// NOT wired into StartAnalyticsRecomputers — every request +// holds s.mu.RLock for the whole compute and triggers a fleet +// clock-skew recompute over 78k transmissions, hanging >60s. +// +// Post-fix: after StartAnalyticsRecomputers, the store exposes +// a recomputer for roles whose Load() returns a populated +// RoleAnalyticsResponse (initial sync compute), and the +// PacketStore.GetAnalyticsRoles() accessor returns from the +// snapshot in sub-millisecond time. +func TestRolesAnalyticsRecomputerRegistered(t *testing.T) { + db := setupTestDB(t) + defer db.Close() + store := NewPacketStore(db, nil) + + stop := store.StartAnalyticsRecomputers(50 * time.Millisecond) + defer stop() + + // Give the initial synchronous compute a beat to populate. + time.Sleep(100 * time.Millisecond) + + store.analyticsRecomputerMu.RLock() + rc := store.recompRoles + store.analyticsRecomputerMu.RUnlock() + if rc == nil { + t.Fatalf("recompRoles not registered after StartAnalyticsRecomputers (issue #1256 not fixed)") + } + v := rc.Load() + if v == nil { + t.Fatalf("recompRoles snapshot is nil after initial compute") + } + if _, ok := v.(RoleAnalyticsResponse); !ok { + t.Fatalf("recompRoles snapshot type = %T, want RoleAnalyticsResponse", v) + } + + // Accessor must hit the snapshot path. + t0 := time.Now() + resp := store.GetAnalyticsRoles() + dt := time.Since(t0) + if dt > 5*time.Millisecond { + t.Errorf("GetAnalyticsRoles latency = %v, want <5ms (snapshot path)", dt) + } + // Just confirm we got the response shape (empty store → empty roles). + _ = resp +} + +// TestRolesHandlerUsesRecomputer is a HTTP-level guard that the +// /api/analytics/roles handler returns from the recomputer snapshot +// quickly even when no clock skew engine state has been primed (the +// hang on staging was: every call drove a full clockSkew.Recompute +// on 78k adverts). With recomputer wired, the handler is an atomic +// pointer load + JSON encode. +func TestRolesHandlerSnapshotLatency(t *testing.T) { + db := setupTestDB(t) + defer db.Close() + store := NewPacketStore(db, nil) + stop := store.StartAnalyticsRecomputers(50 * time.Millisecond) + defer stop() + time.Sleep(100 * time.Millisecond) + + s := &Server{store: store} + + // p99 over 50 reads must be well under 2 s (issue acceptance). + worst := time.Duration(0) + for i := 0; i < 50; i++ { + rr := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodGet, "/api/analytics/roles", nil) + t0 := time.Now() + s.handleAnalyticsRoles(rr, req) + dt := time.Since(t0) + if dt > worst { + worst = dt + } + if rr.Code != http.StatusOK { + t.Fatalf("status = %d, want 200", rr.Code) + } + var out RoleAnalyticsResponse + if err := json.Unmarshal(rr.Body.Bytes(), &out); err != nil { + t.Fatalf("invalid json: %v", err) + } + } + if worst > 100*time.Millisecond { + t.Fatalf("worst-of-50 handler latency = %v, want <100ms (recomputer snapshot)", worst) + } +} diff --git a/cmd/server/routes.go b/cmd/server/routes.go index a5a71185..3346e430 100644 --- a/cmd/server/routes.go +++ b/cmd/server/routes.go @@ -1175,19 +1175,38 @@ func (s *Server) handleNodes(w http.ResponseWriter, r *http.Request) { hashInfo := s.store.GetNodeHashSizeInfo() mbCap := s.store.GetMultiByteCapMap() relayWindow := s.cfg.GetHealthThresholds().RelayActiveHours + // #1257: bulk-compute relay info + usefulness scores ONCE per + // request (cached 15s) instead of calling the per-node helpers + // inside the loop. The per-node calls each grabbed their own + // RLock and walked byPathHop[pk] + byPayloadType, blowing + // /api/nodes up to 30+s on busy networks. + var relayMap map[string]RepeaterRelayInfo + var usefulMap map[string]float64 + needsRelay := false + for _, node := range nodes { + if role, _ := node["role"].(string); role == "repeater" || role == "room" { + needsRelay = true + break + } + } + if needsRelay { + relayMap = s.store.GetRepeaterRelayInfoMap(relayWindow) + usefulMap = s.store.GetRepeaterUsefulnessScoreMap() + } for _, node := range nodes { if pk, ok := node["public_key"].(string); ok { EnrichNodeWithHashSize(node, hashInfo[pk]) EnrichNodeWithMultiByte(node, mbCap[pk]) if role, _ := node["role"].(string); role == "repeater" || role == "room" { - info := s.store.GetRepeaterRelayInfo(pk, relayWindow) + info, _ := lookupRelayInfo(relayMap, pk) + info.WindowHours = relayWindow if info.LastRelayed != "" { node["last_relayed"] = info.LastRelayed } node["relay_active"] = info.RelayActive node["relay_count_1h"] = info.RelayCount1h node["relay_count_24h"] = info.RelayCount24h - node["usefulness_score"] = s.store.GetRepeaterUsefulnessScore(pk) + node["usefulness_score"] = lookupUsefulnessScore(usefulMap, pk) } } } diff --git a/cmd/server/store.go b/cmd/server/store.go index 6f41315c..cd382844 100644 --- a/cmd/server/store.go +++ b/cmd/server/store.go @@ -164,6 +164,7 @@ type PacketStore struct { recompChannels *analyticsRecomputer recompHashCollisions *analyticsRecomputer recompHashSizes *analyticsRecomputer + recompRoles *analyticsRecomputer cacheHits int64 cacheMisses int64 // Rate-limited invalidation (fixes #533: caches cleared faster than hit) @@ -212,6 +213,27 @@ type PacketStore struct { multiByteCapCache map[string]*MultiByteCapEntry multiByteCapAt time.Time + // Cached per-pubkey relay info + usefulness score maps (#1257). These + // fold the previously per-node GetRepeaterRelayInfo / + // GetRepeaterUsefulnessScore loop in handleNodes into one O(N) pass + // per 15s TTL window — eliminating N RLock acquisitions and N× + // timestamp parses of the same byPathHop entries per request. + repeaterEnrichMu sync.Mutex + repeaterRelayCache map[string]RepeaterRelayInfo + repeaterRelayCacheWin float64 + repeaterRelayAt time.Time + repeaterUsefulCache map[string]float64 + repeaterUsefulAt time.Time + + // Steady-state recomputer for the two caches above (#1262). When + // started, an initial sync compute prewarms the caches so the very + // first /api/nodes?limit=2000 from live.js's SPA bootstrap hits a + // populated cache instead of paying the 15.7s on-thread rebuild. + repeaterEnrichRecompMu sync.Mutex + repeaterEnrichRecompStarted bool + repeaterEnrichRecompStop chan struct{} + repeaterEnrichRecompDone chan struct{} + // Precomputed distinct advert pubkey count (refcounted for eviction correctness). // Updated incrementally during Load/Ingest/Evict — avoids JSON parsing in GetPerfStoreStats. advertPubkeys map[string]int // pubkey → number of advert packets referencing it @@ -4061,6 +4083,21 @@ func isHexLower(s string) bool { return true } +// hasUpperASCII reports whether s contains any uppercase ASCII letter. +// Used by resolveWithContext tier-1 to skip the strings.ToLower allocation +// when the context pubkeys are already lowercased (the common case — see +// buildHopContextPubkeys / buildAggregateHopContextPubkeys, which lowercase +// on the way in). #1247. +func hasUpperASCII(s string) bool { + for i := 0; i < len(s); i++ { + c := s[i] + if c >= 'A' && c <= 'Z' { + return true + } + } + return false +} + // buildAggregateHopContextPubkeys gathers context across many txs for hot // loops that resolve hops outside any per-tx scope (subpath/topology // aggregations). Caller passes the slice of txs to consider; we union the @@ -5725,32 +5762,84 @@ func (pm *prefixMap) resolveWithContext(hop string, contextPubkeys []string, gra count int // observation count of the best-scoring edge } now := time.Now() - var scores []scored - for i, cand := range candidates { - candPK := strings.ToLower(cand.PublicKey) - bestScore := 0.0 - bestCount := 0 - for _, ctxPK := range contextPubkeys { - edges := graph.Neighbors(strings.ToLower(ctxPK)) - for _, e := range edges { - if e.Ambiguous { - continue - } - otherPK := e.NodeA - if strings.EqualFold(otherPK, ctxPK) { - otherPK = e.NodeB - } - if strings.EqualFold(otherPK, candPK) { - s := e.Score(now) * e.Confidence() - if s > bestScore { - bestScore = s - bestCount = e.Count - } - } + // PERF (#1247): hoist per-context work out of the candidate loop. + // The previous shape ran graph.Neighbors(ToLower(ctxPK)) and + // re-lowercased candPK on every (cand, ctxPK) pair, then used + // strings.EqualFold to compare two already-lowercased pubkeys. + // At analytics scale (5k+ contextPubkeys, ~30k resolveHop calls) + // this dominated computeAnalyticsTopology / computeAnalyticsRF + // CPU time (37% / 55% of those endpoints respectively per + // pprof). The new shape: + // 1. Lowercases ctx pubkeys at most once per call (skipped + // entirely when the input is already lowercased — the + // common case for analytics callers that go through + // buildHopContextPubkeys). + // 2. Lowercases candidate pubkeys at most once per call and + // uses raw == comparisons against NeighborEdge.NodeA/NodeB + // (which makeEdgeKey already lowercases). + // 3. Loops outer-ctx / inner-edge / matched-cand-lookup. The + // previous shape was outer-cand / inner-ctx / inner-edge, + // which called graph.Neighbors(ctxPK) — taking the graph + // RLock each time — once per (cand, ctx) pair instead of + // once per ctx. + lowerCtx := contextPubkeys + needLower := false + for _, p := range contextPubkeys { + if hasUpperASCII(p) { + needLower = true + break + } + } + if needLower { + lowerCtx = make([]string, len(contextPubkeys)) + for i, p := range contextPubkeys { + lowerCtx[i] = strings.ToLower(p) + } + } + candPKs := make([]string, len(candidates)) + bestScores := make([]float64, len(candidates)) + bestCounts := make([]int, len(candidates)) + needLowerCand := false + for i, c := range candidates { + if hasUpperASCII(c.PublicKey) { + needLowerCand = true + break + } + candPKs[i] = c.PublicKey + } + if needLowerCand { + for i, c := range candidates { + candPKs[i] = strings.ToLower(c.PublicKey) + } + } + candByPK := make(map[string]int, len(candidates)) + for i, pk := range candPKs { + candByPK[pk] = i + } + for _, ctxPK := range lowerCtx { + for _, e := range graph.Neighbors(ctxPK) { + if e.Ambiguous { + continue + } + otherPK := e.NodeA + if otherPK == ctxPK { + otherPK = e.NodeB + } + ci, ok := candByPK[otherPK] + if !ok { + continue + } + s := e.Score(now) * e.Confidence() + if s > bestScores[ci] { + bestScores[ci] = s + bestCounts[ci] = e.Count } } - if bestScore > 0 { - scores = append(scores, scored{i, bestScore, bestCount}) + } + var scores []scored + for i, s := range bestScores { + if s > 0 { + scores = append(scores, scored{i, s, bestCounts[i]}) } } diff --git a/config.example.json b/config.example.json index 8b682623..91076d5d 100644 --- a/config.example.json +++ b/config.example.json @@ -258,8 +258,9 @@ "distance": 300, "channels": 300, "hashCollisions": 300, - "hashSizes": 300 + "hashSizes": 300, + "roles": 300 } }, - "_comment_analytics": "Issue #1240. Each analytics endpoint (topology, rf, distance, channels, hashCollisions, hashSizes) is recomputed in the background on the configured interval and served from an atomic-pointer cache. Reads never block on compute. Default 300s (5 min) per endpoint reflects the operator principle: serving slightly stale data quickly beats real-time data slowly. Lower values = fresher data at higher CPU cost. Only the default query (no region/window) is precomputed; region- and window-filtered requests fall back to the legacy on-request compute + 60s TTL cache." + "_comment_analytics": "Issue #1240 + #1256. Each analytics endpoint (topology, rf, distance, channels, hashCollisions, hashSizes, roles) is recomputed in the background on the configured interval and served from an atomic-pointer cache. Reads never block on compute. Default 300s (5 min) per endpoint reflects the operator principle: serving slightly stale data quickly beats real-time data slowly. Lower values = fresher data at higher CPU cost. Only the default query (no region/window) is precomputed; region- and window-filtered requests fall back to the legacy on-request compute + 60s TTL cache." } diff --git a/public/perf.js b/public/perf.js index 8172914e..ba34b1ad 100644 --- a/public/perf.js +++ b/public/perf.js @@ -13,17 +13,17 @@ const el = document.getElementById('perfContent'); if (!el) return; try { - const [server, client, ioStats, sqliteStats, writeSources] = await Promise.all([ + // #1258: /api/health was awaited AFTER Promise.all, adding a full RTT + // (~50-200ms) on every 5s refresh. Issue it in parallel with the rest. + const [server, client, ioStats, sqliteStats, writeSources, health] = await Promise.all([ fetch('/api/perf').then(r => r.json()), Promise.resolve(window.apiPerf ? window.apiPerf() : null), fetch('/api/perf/io').then(r => r.json()).catch(() => null), fetch('/api/perf/sqlite').then(r => r.json()).catch(() => null), - fetch('/api/perf/write-sources').then(r => r.json()).catch(() => null) + fetch('/api/perf/write-sources').then(r => r.json()).catch(() => null), + fetch('/api/health').then(r => r.json()).catch(() => null) ]); - // Also fetch health telemetry - const health = await fetch('/api/health').then(r => r.json()).catch(() => null); - let html = ''; // Server overview @@ -230,8 +230,15 @@ html += ``; } - // Server endpoints table - const eps = Object.entries(server.endpoints); + // Server endpoints table — sort by total time (count * avg) DESC. + // #1258: header claimed "sorted by total time" but JSON map order is + // undefined and the frontend was not sorting. Slow endpoints could + // appear anywhere in the table, defeating the section's whole purpose. + const eps = Object.entries(server.endpoints).sort((a, b) => { + const ta = (a[1].count || 0) * (a[1].avgMs || 0); + const tb = (b[1].count || 0) * (b[1].avgMs || 0); + return tb - ta; + }); if (eps.length) { html += '

Server Endpoints (sorted by total time)

'; html += '
'; @@ -281,10 +288,28 @@ registerPage('perf', { init(app) { render(app); - interval = setInterval(refresh, 5000); + // #1258: don't burn CPU/network rebuilding the page (and its many cards + // + 3 large tables) every 5s while the tab is hidden. Pause polling on + // visibilitychange and resume on focus. Reduces background fetch traffic + // to zero and prevents a returning user from seeing a 100+ms thrash as + // a backlog of refreshes flush. + const tick = () => { + if (document.hidden) return; + refresh(); + }; + interval = setInterval(tick, 5000); + const onVis = () => { + if (!document.hidden) refresh(); + }; + document.addEventListener('visibilitychange', onVis); + this._onVis = onVis; }, destroy() { if (interval) { clearInterval(interval); interval = null; } + if (this._onVis) { + document.removeEventListener('visibilitychange', this._onVis); + this._onVis = null; + } } }); })(); diff --git a/test-perf-render-1258.js b/test-perf-render-1258.js new file mode 100644 index 00000000..3f4d8597 --- /dev/null +++ b/test-perf-render-1258.js @@ -0,0 +1,140 @@ +/* Tests for perf.js render performance (#1258). + * + * Failure modes we gate against: + * 1) /api/health awaited sequentially AFTER Promise.all → extra RTT + * 2) setInterval keeps polling even when document is hidden → wasted work + * 3) Endpoints table claims "sorted by total time" but renders in map order + */ +'use strict'; +const vm = require('vm'); +const fs = require('fs'); +const assert = require('assert'); + +let passed = 0, failed = 0; +function test(name, fn) { + const run = (r) => { if (r && typeof r.then === 'function') return r.then(() => { passed++; console.log(` ✅ ${name}`); }, e => { failed++; console.log(` ❌ ${name}: ${e.message}`); }); passed++; console.log(` ✅ ${name}`); }; + try { const r = fn(); if (r && typeof r.then === 'function') return r.then(() => { passed++; console.log(` ✅ ${name}`); }, e => { failed++; console.log(` ❌ ${name}: ${e.message}`); }); else { passed++; console.log(` ✅ ${name}`); } } + catch (e) { failed++; console.log(` ❌ ${name}: ${e.message}`); } +} + +function makeSandbox(opts = {}) { + let capturedHtml = ''; + const pages = {}; + let visState = opts.hidden ? 'hidden' : 'visible'; + const visListeners = []; + const ctx = { + window: { addEventListener: () => {}, apiPerf: null }, + document: { + getElementById: (id) => { + if (id === 'perfContent') return { set innerHTML(v) { capturedHtml = v; } }; + if (id === 'perfReset' || id === 'perfRefresh') return { addEventListener: () => {} }; + return null; + }, + addEventListener: (ev, fn) => { if (ev === 'visibilitychange') visListeners.push(fn); }, + removeEventListener: () => {}, + get visibilityState() { return visState; }, + get hidden() { return visState === 'hidden'; }, + }, + console, + Date, Math, Array, Object, String, Number, JSON, RegExp, Error, TypeError, + parseInt, parseFloat, isNaN, isFinite, + setTimeout: (fn, ms) => setTimeout(fn, ms), clearTimeout, + setInterval: (fn, ms) => { return setInterval(fn, ms); }, clearInterval, + performance: { now: () => Date.now() }, + Map, Set, Promise, + registerPage: (name, handler) => { pages[name] = handler; }, + _apiCache: { size: 0 }, + fetch: () => Promise.resolve({ json: () => Promise.resolve({}) }), + }; + ctx.window.document = ctx.document; + ctx.globalThis = ctx; + return { ctx, pages, getHtml: () => capturedHtml, + setVisibility(v) { visState = v; visListeners.forEach(fn => fn()); } }; +} + +function loadPerf() { + const sb = makeSandbox(); + const code = fs.readFileSync('public/perf.js', 'utf8'); + vm.runInNewContext(code, sb.ctx); + return sb; +} + +// ---------- 1) Health fetched in parallel ---------- +test('all initial fetches (including /api/health) issued in parallel', async () => { + const sb = loadPerf(); + const order = []; + let resolveAll; + const gate = new Promise(r => { resolveAll = r; }); + sb.ctx.fetch = (url) => { + order.push(url); + // Don't resolve until all 5 calls have been issued — proves they're parallel + return gate.then(() => ({ json: () => Promise.resolve({}) })); + }; + const p = sb.pages.perf.init({ set innerHTML(v) {} }); + // Microtask flush + await Promise.resolve(); + await Promise.resolve(); + await Promise.resolve(); + // Before any fetch resolves, all 5 URLs must have been started + assert.ok(order.includes('/api/health'), + `expected /api/health to be issued in parallel with the others, got: ${order.join(', ')}`); + resolveAll(); + await p; +}); + +// ---------- 2) setInterval pauses when tab hidden ---------- +test('refresh interval does not fire when document is hidden', async () => { + const sb = loadPerf(); + let fetchCount = 0; + sb.ctx.fetch = (url) => { + fetchCount++; + return Promise.resolve({ json: () => Promise.resolve({}) }); + }; + // Replace setInterval with fast firing + let timerFn = null; + sb.ctx.setInterval = (fn, ms) => { timerFn = fn; return 1; }; + sb.ctx.clearInterval = () => { timerFn = null; }; + + await sb.pages.perf.init({ set innerHTML(v) {} }); + await new Promise(r => setTimeout(r, 30)); + const baseline = fetchCount; + // Hide the tab, then fire the interval — should NOT issue fresh fetches + sb.setVisibility('hidden'); + if (timerFn) timerFn(); + await new Promise(r => setTimeout(r, 30)); + assert.strictEqual(fetchCount, baseline, + `refresh should be suppressed while hidden; baseline=${baseline} after=${fetchCount}`); +}); + +// ---------- 3) Endpoints table actually sorted by total time ---------- +test('endpoints table is sorted by total time descending', async () => { + const sb = loadPerf(); + // Map insertion order is preserved in JS object literals — put SLOW endpoint + // LAST to ensure the renderer is actively sorting, not relying on input order. + const perfData = { + totalRequests: 100, avgMs: 5, uptime: 3600, slowQueries: [], + endpoints: { + '/api/fast': { count: 1, avgMs: 1, p50Ms: 1, p95Ms: 1, maxMs: 1 }, + '/api/mid': { count: 10, avgMs: 10, p50Ms: 10, p95Ms: 10, maxMs: 10 }, + '/api/SLOW': { count: 100, avgMs: 100, p50Ms: 100, p95Ms: 100, maxMs: 100 }, + }, + }; + sb.ctx.fetch = (url) => { + if (url === '/api/perf') return Promise.resolve({ json: () => Promise.resolve(perfData) }); + return Promise.resolve({ json: () => Promise.resolve(null) }); + }; + await sb.pages.perf.init({ set innerHTML(v) {} }); + await new Promise(r => setTimeout(r, 30)); + const html = sb.getHtml(); + const iSlow = html.indexOf('/api/SLOW'); + const iMid = html.indexOf('/api/mid'); + const iFast = html.indexOf('/api/fast'); + assert.ok(iSlow > -1 && iMid > -1 && iFast > -1, 'all three endpoints must render'); + assert.ok(iSlow < iMid && iMid < iFast, + `expected SLOW < mid < fast in DOM order, got SLOW=${iSlow} mid=${iMid} fast=${iFast}`); +}); + +setTimeout(() => { + console.log(`\n${passed} passed, ${failed} failed\n`); + process.exit(failed ? 1 : 0); +}, 500);
EndpointCountAvgP50P95MaxTotal