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"`