mirror of
https://github.com/Kpa-clawbot/meshcore-analyzer.git
synced 2026-10-23 22:12:50 +00:00
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) <noreply@anthropic.com>
This commit is contained in:
1 parent
3caa847323
commit
a5aa3cdc41
5 files changed
+257
No files matched your search
@@ -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 {
|
||||
|
||||
@@ -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;
|
||||
|
||||
@@ -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()
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
@@ -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"`
|
||||
|
||||
Reference in new issue
Block a user