From a5aa3cdc410e0a99a5ec39a14ce201fda8731936 Mon Sep 17 00:00:00 2001 From: efiten Date: Fri, 25 Sep 2026 00:08:54 +0200 Subject: [PATCH] perf(db): refresh SQLite planner statistics with a bounded ANALYZE (#2058) (#2072) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes #2058. `ANALYZE` has never run against these databases, so `sqlite_stat1` does not exist and the planner works from built-in guesses. On the channel queries it guesses wrong: it drives from the plain `idx_transmissions_payload_type` instead of `idx_tx_channel_hash`, the partial index (`WHERE payload_type = 5`) the schema already carries for that exact filter. @anieto's report did the diagnosis and the arithmetic. This adds the maintenance operation that was missing, at a value measured rather than assumed. ## The diagnosis transfers, the remedy needed measuring Measured on our 9.4 GB staging database: 1,250,489 transmissions, 14,169,329 observations, 2.7x and 7x the reported database. Region-filtered `GetChannels` produces the identical plan reported in #2058, down to both temp b-trees, so the problem is the same one. Wall time is the wrong metric here. The same query and the same plan measure **56.7s cold and 0.80s warm** on that file, so the OS page cache dominates. Counting page-cache misses instead: | analysis_limit | ANALYZE | driving index | page misses | |---|---|---|---| | none (no statistics) | - | `idx_transmissions_payload_type` | 143,442 | | 400 | 171 ms | `idx_transmissions_payload_type` | 143,449 | | 1000 | 171 ms | `idx_transmissions_payload_type` | 143,450 | | **10000** | **2.0 s** | **`idx_tx_channel_hash`** | **107,429** | | 0 (unbounded) | 242.9 s | `idx_tx_channel_hash` | 107,429 | 400, the value SQLite's documentation offers for the bounded form, changes nothing on this data: it samples too few rows to separate the 126,336-row partial index from the 920,700-row plain one. 10000 buys the entire plan change for 2.0 s, and the four-minute unbounded `ANALYZE` buys nothing beyond it. ## What it is worth, as measured 25% fewer pages read per query, 143,442 to 107,429, about 147 MB less at a 4 KB page. Warm wall time does not move: 0.80s either way. The gain lands on the cold path, the one that measured 56.7s, so the claim here is fewer pages read, not a warm speedup. This is smaller and differently shaped than the 3-4x in #2058. I cannot reproduce that ratio on a database of this size and am not claiming it. ## The change - `Store.RefreshPlannerStats(analysisLimit)` in `cmd/ingestor/db.go`: `PRAGMA analysis_limit=N` then `ANALYZE`, logging the duration and whether this was the first run. - Wired in `cmd/ingestor/main.go` next to the existing WAL checkpoint ticker: 24h, staggered 2 minutes past startup because it takes the write lock. - `db.analysisLimit` in `internal/dbconfig`, default 10000, negative disables it. It runs in the ingestor, not the server: `cmd/server/db.go:145` opens `mode=ro`, and `ANALYZE` writes. This respects the read/write separation invariant in AGENTS.md. `analysis_limit=0` means *no* limit to SQLite rather than "use a default", so an unset config maps to 10000 and a test covers that specific case. ## Two faults the measurement caught in my own first commit Both are in the history rather than hidden, because the second commit is the one that measured: 1. **`PRAGMA optimize` was the wrong statement.** It analyzes only tables the calling connection has itself queried during the session, and a maintenance call has queried none. Run against staging it wrote nothing and left `sqlite_stat1` absent; `PRAGMA optimize(0x03)` returned no statements at all. Verified on an empty database too (SQLite 3.45.1): `ANALYZE` creates `sqlite_stat1`, `PRAGMA optimize` does not. That difference is what makes the behavioural test a guard instead of a no-op. 2. **`analysis_limit=400` was the wrong value**, per the table above. ## Tests Six cases in `cmd/ingestor/refresh_planner_stats_test.go`: - statistics are actually written (the guard against returning to `PRAGMA optimize`) - the pragma reaches the connection, read back through `PRAGMA analysis_limit` - a negative limit leaves `sqlite_stat1` absent - two consecutive refreshes, since a ticker calls this repeatedly - the config default and the JSON round trip - the default is above the range measured ineffective, so lowering it back to 400 fails ## Not done, and one caveat - **Correction to an earlier version of this description**, which said the Go tests could not run locally because this box has no C compiler. That was wrong: `CGO_ENABLED=0` and `gcc` being absent from `PATH` is not the same as no compiler, and a mingw-w64 toolchain is installed here. Run properly, all six tests pass locally, and so does the rest of `cmd/ingestor` apart from `TestWriteStatsAtomic_SymlinkAtDestIsReplaced`, which fails on `os.Symlink` with "A required privilege is not held by the client" on Windows without elevation and lives in `stats_file_test.go`, a file this branch does not touch. CI agrees: Go Build & Test and the ingestor race detector are both green. - The SQLite behaviours above were measured against 3.45.1 on the server, not against the amalgamation `mattn/go-sqlite3` bundles. - **No query rewrite.** #2058 explicitly left that out and so does this; the correctness caveats it lists (per-channel most-recent-message semantics, v2/v3 branches, `enc_` exclusion) are untouched here. - Staging carries limit-10000 statistics, matching what this code produces. Reversible: `DROP TABLE sqlite_stat1` was verified on a scratch database before any of it ran. - Whether a cold-start `ANALYZE` should also run before the 2 minute stagger is not addressed. The first query after a restart is the expensive one, and it can arrive first. 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_013YAR8fdNTzqjtsggq4xCX6 --------- Co-authored-by: Claude Opus 5 (1M context) --- cmd/ingestor/config.go | 15 +++ cmd/ingestor/db.go | 73 +++++++++++ cmd/ingestor/main.go | 22 ++++ cmd/ingestor/refresh_planner_stats_test.go | 146 +++++++++++++++++++++ internal/dbconfig/dbconfig.go | 1 + 5 files changed, 257 insertions(+) create mode 100644 cmd/ingestor/refresh_planner_stats_test.go diff --git a/cmd/ingestor/config.go b/cmd/ingestor/config.go index e892a14e..319399d9 100644 --- a/cmd/ingestor/config.go +++ b/cmd/ingestor/config.go @@ -310,6 +310,21 @@ func (c *Config) IncrementalVacuumPages() int { return 1024 } +// AnalysisLimit returns the per-index row cap for the planner stats refresh +// (#2058). A negative setting disables the refresh; zero means unset, matching +// IncrementalVacuumPages above. +// +// 10000 rather than the 400 SQLite's documentation offers: measured on the +// 9.4 GB staging database, 400 and 1000 leave the channel-query plan exactly as +// it was, 10000 produces the same plan as an unbounded ANALYZE, and it costs 2.0s +// against that ANALYZE's 242.9s. The full ladder is in Store.RefreshPlannerStats. +func (c *Config) AnalysisLimit() int { + if c.DB != nil && c.DB.AnalysisLimit != 0 { + return c.DB.AnalysisLimit + } + return 10000 +} + // ShouldValidateSignatures returns true (default) unless explicitly disabled. func (c *Config) ShouldValidateSignatures() bool { if c.ValidateSignatures != nil { diff --git a/cmd/ingestor/db.go b/cmd/ingestor/db.go index 98da680f..e0879b5e 100644 --- a/cmd/ingestor/db.go +++ b/cmd/ingestor/db.go @@ -1503,6 +1503,79 @@ func (s *Store) RunIncrementalVacuum(pages int) { } } +// RefreshPlannerStats rebuilds the query planner's cardinality statistics +// (#2058). +// +// Without a sqlite_stat1 table the planner works from built-in guesses, and on +// the channel queries it guesses wrong: it drives from the plain +// idx_transmissions_payload_type rather than idx_tx_channel_hash, the partial +// index (WHERE payload_type = 5) this schema already carries for that exact +// filter. +// +// Measured on the 9.4 GB staging database (1,250,489 transmissions, 14,169,329 +// observations), region-filtered GetChannels, counting page-cache misses +// because wall time there is dominated by the OS page cache (56.7s cold, 0.80s +// warm, for the same query and plan): +// +// analysis_limit ANALYZE driving index page misses +// none (no stats) - idx_transmissions_payload_type 143,442 +// 400 171ms idx_transmissions_payload_type 143,449 +// 1000 171ms idx_transmissions_payload_type 143,450 +// 10000 2.0s idx_tx_channel_hash 107,429 +// 0 (unbounded) 242.9s idx_tx_channel_hash 107,429 +// +// So 10000 buys the whole plan change, and the four-minute unbounded ANALYZE +// buys nothing beyond it. 400, the value SQLite's documentation offers for the +// bounded form, changes nothing at all on this data: it samples too few rows to +// separate the 126,336-row partial index from the 920,700-row plain one. +// +// ANALYZE, not PRAGMA optimize. Measured on the same database: optimize is a +// no-op here, because it only analyzes tables that the calling connection has +// itself queried during the session, and a maintenance call has queried none. +// PRAGMA optimize(0x03) returned no statements and sqlite_stat1 was not +// created. +// +// Note that analysis_limit=0 means *no* limit to SQLite, not "use a default". +// Config.AnalysisLimit maps an unset config to 10000 for that reason, and a +// negative value here disables the refresh. +// +// Returns whether the statistics were refreshed. This function owns its +// logging; callers need add nothing. +func (s *Store) RefreshPlannerStats(analysisLimit int) bool { + if analysisLimit < 0 { + return false + } + first := !s.hasPlannerStats() + start := time.Now() + // Tagged for /api/perf writer-lock visibility (#1340). + if _, err := s.instrumentedExec("analyze", fmt.Sprintf("PRAGMA analysis_limit=%d", analysisLimit)); err != nil { + log.Printf("[analyze] could not set analysis_limit: %v", err) + return false + } + if _, err := s.instrumentedExec("analyze", "ANALYZE"); err != nil { + log.Printf("[analyze] ANALYZE failed: %v", err) + return false + } + elapsed := time.Since(start).Round(time.Millisecond) + if first { + log.Printf("[analyze] planner statistics built in %v (analysis_limit=%d, first run against this database)", elapsed, analysisLimit) + } else { + log.Printf("[analyze] planner statistics refreshed in %v (analysis_limit=%d)", elapsed, analysisLimit) + } + return true +} + +// hasPlannerStats reports whether ANALYZE has ever run against this database. +// Used only to word the log line, so a query error reads as "no stats". +func (s *Store) hasPlannerStats() bool { + var n int + if err := s.db.QueryRow( + `SELECT count(*) FROM sqlite_master WHERE type='table' AND name='sqlite_stat1'`).Scan(&n); err != nil { + return false + } + return n > 0 +} + // Checkpoint runs a WAL checkpoint (TRUNCATE mode). // Returns the number of WAL frames checkpointed (0 if WAL was already empty). // TRUNCATE resets the WAL file to zero bytes when all frames are checkpointed; diff --git a/cmd/ingestor/main.go b/cmd/ingestor/main.go index ed6da8d8..406de597 100644 --- a/cmd/ingestor/main.go +++ b/cmd/ingestor/main.go @@ -481,6 +481,28 @@ func main() { }() log.Printf("[db] WAL checkpoint scheduled every 1h") + // Daily planner statistics refresh (#2058). Staggered 2 minutes past + // startup for the same reason as the checkpoint above: it takes the write + // lock, and should not compete with the initial ingest burst. Bounded by + // analysis_limit, measured at 2.0s on a 9.4 GB database, so it does not grow + // with the file the way an unbounded ANALYZE does (242.9s on the same file). + { + analysisLimit := cfg.AnalysisLimit() + if analysisLimit < 0 { + log.Printf("[analyze] planner statistics refresh disabled (db.analysisLimit=%d)", analysisLimit) + } else { + analyzeTicker := time.NewTicker(24 * time.Hour) + go func() { + time.Sleep(2 * time.Minute) + store.RefreshPlannerStats(analysisLimit) + for range analyzeTicker.C { + store.RefreshPlannerStats(analysisLimit) + } + }() + log.Printf("[analyze] planner statistics refresh scheduled every 24h (analysis_limit=%d)", analysisLimit) + } + } + // Daily neighbor_edges retention (#1287 — moved from cmd/server). { nDays := cfg.NeighborEdgesDaysOrDefault() diff --git a/cmd/ingestor/refresh_planner_stats_test.go b/cmd/ingestor/refresh_planner_stats_test.go new file mode 100644 index 00000000..4836cfc7 --- /dev/null +++ b/cmd/ingestor/refresh_planner_stats_test.go @@ -0,0 +1,146 @@ +package main + +import ( + "os" + "path/filepath" + "testing" + + "github.com/meshcore-analyzer/dbconfig" +) + +// #2058: the planner has no cardinality statistics because ANALYZE has never +// run, so it picks a plain index over the partial index built for the query. +// These pin the three things that make the refresh work at all: the statement is +// one that actually writes statistics, the pragma reaches the connection, and a +// negative limit leaves the database untouched. + +func hasStat1(t *testing.T, s *Store) bool { + t.Helper() + var n int + if err := s.db.QueryRow( + `SELECT count(*) FROM sqlite_master WHERE type='table' AND name='sqlite_stat1'`).Scan(&n); err != nil { + t.Fatalf("query sqlite_master: %v", err) + } + return n > 0 +} + +// This is the guard against going back to PRAGMA optimize, which is what the +// first draft of this change used. Measured against the 9.4 GB staging database: +// optimize analyzes only tables the calling connection has itself queried during +// the session, so from a maintenance call it writes nothing and sqlite_stat1 +// never appears. A fresh store here has queried nothing either, so this test +// fails on that mistake instead of passing on a no-op. +func TestRefreshPlannerStatsWritesStatistics_Issue2058(t *testing.T) { + s := newTestStore(t) + defer s.Close() + + if hasStat1(t, s) { + t.Fatal("a fresh store already carries sqlite_stat1, so this test cannot tell whether the refresh did anything") + } + + if !s.RefreshPlannerStats(10000) { + t.Fatal("RefreshPlannerStats reported no refresh") + } + + if !hasStat1(t, s) { + t.Error("sqlite_stat1 was not created, so the planner still has no statistics") + } +} + +func TestRefreshPlannerStatsAppliesTheLimit_Issue2058(t *testing.T) { + s := newTestStore(t) + defer s.Close() + + s.RefreshPlannerStats(250) + + // analysis_limit is per connection. The store runs SetMaxOpenConns(1) + // (db.go:142), which is the only reason setting it through Exec is sound + // here: on a multi-connection pool the pragma could land on a connection + // the ANALYZE never uses, and the limit would silently not apply. + var limit int + if err := s.db.QueryRow("PRAGMA analysis_limit").Scan(&limit); err != nil { + t.Fatalf("read back analysis_limit: %v", err) + } + if limit != 250 { + t.Errorf("analysis_limit did not reach the connection: want 250, got %d", limit) + } +} + +func TestRefreshPlannerStatsNegativeLimitIsANoop_Issue2058(t *testing.T) { + s := newTestStore(t) + defer s.Close() + + if s.RefreshPlannerStats(-1) { + t.Error("a negative limit must not report a refresh") + } + if hasStat1(t, s) { + t.Error("a negative limit still built sqlite_stat1; the refresh is not actually disabled") + } +} + +func TestRefreshPlannerStatsIsRepeatable_Issue2058(t *testing.T) { + s := newTestStore(t) + defer s.Close() + + // The ticker calls this every 24h for the life of the process. A second + // call must not error or undo the first, which is the part a single-call + // test would not notice. + s.RefreshPlannerStats(10000) + if !s.RefreshPlannerStats(10000) { + t.Fatal("the second refresh reported failure") + } + if !hasStat1(t, s) { + t.Error("sqlite_stat1 disappeared across two refreshes") + } +} + +func TestAnalysisLimitConfigDefault_Issue2058(t *testing.T) { + cases := []struct { + name string + cfg *Config + want int + }{ + // Zero means "no limit" to SQLite, so an unset config must not be + // passed through as 0: that would turn a 2 second refresh into the + // 242.9s unbounded ANALYZE measured on the staging database. + {"no db section", &Config{}, 10000}, + {"db section, limit unset", &Config{DB: &dbconfig.DBConfig{}}, 10000}, + {"explicit limit", &Config{DB: &dbconfig.DBConfig{AnalysisLimit: 1000}}, 1000}, + {"disabled", &Config{DB: &dbconfig.DBConfig{AnalysisLimit: -1}}, -1}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + if got := tc.cfg.AnalysisLimit(); got != tc.want { + t.Errorf("AnalysisLimit() = %d, want %d", got, tc.want) + } + }) + } +} + +// The default is not a free choice: 400 and 1000 were measured to leave the +// channel-query plan unchanged on the staging database, so a well-meant edit +// back to SQLite's documented 400 would quietly return this to a no-op. +func TestAnalysisLimitDefaultIsHighEnoughToMatter_Issue2058(t *testing.T) { + const measuredIneffective = 1000 + if got := (&Config{}).AnalysisLimit(); got <= measuredIneffective { + t.Errorf("default analysis_limit is %d; %d and below were measured to leave the plan unchanged on a 9.4 GB database", + got, measuredIneffective) + } +} + +func TestAnalysisLimitSurvivesTheConfigFile_Issue2058(t *testing.T) { + // The knob is only useful if it survives the config file. The field lives in + // internal/dbconfig, so a wrong json tag there would leave the accessor + // returning the default however the operator set it. + path := filepath.Join(t.TempDir(), "config.json") + if err := os.WriteFile(path, []byte(`{"db":{"analysisLimit":123}}`), 0o600); err != nil { + t.Fatal(err) + } + cfg, err := LoadConfig(path) + if err != nil { + t.Fatalf("LoadConfig: %v", err) + } + if got := cfg.AnalysisLimit(); got != 123 { + t.Errorf("analysisLimit did not survive the config file: got %d, want 123", got) + } +} diff --git a/internal/dbconfig/dbconfig.go b/internal/dbconfig/dbconfig.go index 7526fa67..21ac7941 100644 --- a/internal/dbconfig/dbconfig.go +++ b/internal/dbconfig/dbconfig.go @@ -6,6 +6,7 @@ package dbconfig type DBConfig struct { VacuumOnStartup bool `json:"vacuumOnStartup"` // one-time full VACUUM on startup if auto_vacuum is not INCREMENTAL IncrementalVacuumPages int `json:"incrementalVacuumPages"` // pages returned to OS per reaper cycle (default 1024) + AnalysisLimit int `json:"analysisLimit"` // index rows ANALYZE visits per index (default 10000); negative disables the planner stats refresh (#2058) // Load controls chunked startup loading (#1009). Load *LoadConfig `json:"load,omitempty"`