Files
navidrome/db/optimize_test.go
Deluan Quintão cc315dcc8c perf(db): keep query planner statistics trustworthy with full ANALYZE (#5740)
* perf(db): keep query planner statistics trustworthy with full ANALYZE

PRAGMA optimize's internal ANALYZE runs with a limited analysis budget
(~2000 rows) that writes wrong sqlite_stat1 entries for low-cardinality
indexes: on a 96K-track library it claimed (missing, library_id) narrows
to ~2000 rows when it matches the whole table. The planner then prefers
that index over the sort index and falls back to a full-table temp
B-tree sort per request, turning paginated song listings into
multi-second queries (reproduced at 5.5s on real hardware; ~90x slower
than with correct stats). Every index-creating migration re-triggered
the poisoning via the post-migration optimize, and the daily optimizer
could re-trigger it on large library changes. Setting analysis_limit on
the connection does not help: optimize ignores it.

Run a plain full ANALYZE instead: after migrations with schema changes,
and in db.Optimize (daily schedule and scan-end). Stats are stored in
the database file, so one connection suffices and the per-connection
pool loop is gone. The Optimize call at shutdown is removed: stats are
maintained at migration/scan/daily points, and an ANALYZE during
shutdown only delays it and races container stop timeouts.

* perf(db): drop startup PRAGMA optimize that re-poisons planner stats

The startup PRAGMA optimize=0x10002 runs SQLite's budget-limited internal
ANALYZE (bit 0x02), which writes truncated sqlite_stat1 rows for
low-cardinality indexes -- the exact statistics-poisoning this PR set out to
eliminate. Because DevOptimizeDB defaults to true, a restart with no pending
migrations would re-poison the planner until the next scan or daily Optimize.

Remove it: statistics are already refreshed with a full ANALYZE after
schema-changing migrations (Init) and via Optimize at scan-end and on the daily
schedule, so nothing on the startup path needs to touch them. Also clarify that
Optimize is a no-op unless DevOptimizeDB is enabled.

* chore(db): remove the DevOptimizeDB flag and skip Optimize on quick scans

The flag only gated the optimize/ANALYZE maintenance calls and there is
no reason to leave planner statistics unmaintained; the guards are gone
along with the flag. The scan-end Optimize now runs only after full
scans — quick scans barely move the statistics, and the daily schedule
covers drift.

* style(scanner): drop redundant comment in runOptimize

* chore(persistence): drop the no-op PRAGMA optimize from ScanEnd

Mask 0x10000 only selects candidate tables by size change; without the
0x02 action bit optimize does nothing (verified: sqlite_stat1 stays
stale after a 100x table growth). The scan-end statistics refresh is
db.Optimize's full ANALYZE, and the expression-collation-index concern
the old comment guarded against no longer applies.

* fix(scanner): run the post-scan ANALYZE in the server process

With the external scanner (the default), the scan pipeline runs in a
subprocess, so its ANALYZE was invisible to the server: SQLite loads
sqlite_stat1 into the process's shared schema cache, and an ANALYZE from
another process does not refresh it — verified with the production DSN
that even brand-new pool connections keep planning with the old
statistics until the server restarts. An in-process ANALYZE, by
contrast, is immediately visible to every pooled connection through the
same shared cache.

Move the full-scan Optimize from the scanner pipeline to the scan
controller, which always runs in the server process.

* fix(scanner): honor promoted full scans in the optimize gate

A quick scan resuming an interrupted full scan is promoted inside the
scanner (possibly in a subprocess); mirror the promotion in the
controller so the post-scan ANALYZE isn't skipped.

* refactor: apply cleanup review findings

- drop forceFullRescan's inline ANALYZE: Init already runs a full
  ANALYZE after any migration batch with schema changes, so upgrades
  including a full-rescan migration analyzed the whole DB twice
- resumingFullScan uses a filtered CountAll instead of fetching and
  scanning all libraries
- document why CallScan (CLI) deliberately skips the post-scan Optimize

* perf(db): make planner analysis maintenance resilient

Check analysis freshness every 30 minutes and refresh statistics when the last successful run is over 24 hours old or a scan marked them pending. Persist successful analysis state, retry skipped or failed maintenance, coordinate checks with scans, and cover standalone CLI full scans.

* perf(db): avoid analyzing routine quick-scan changes

Reserve pending analysis for full scans, unscanned libraries, and retry state. Incremental quick scans now rely on the 24-hour freshness window instead of triggering a full ANALYZE at the next maintenance check.

* fix(scan): analyze resumed full scans in CLI

* fix(db): back off failed analysis retries

* feat(db): allow disabling scheduled analysis

* test(db): remove redundant analysis coverage

* refactor(db): split ANALYZE maintenance into optimize.go and dedupe call sites

- move query-planner statistics code from db.go to its own optimize.go
  (and matching optimize_test.go)
- log ANALYZE elapsed time inside Optimize/OptimizeIfNeeded instead of
  repeating the timing block at every call site
- drop the LastDBAnalyzeAttemptAt write on success: it is only read
  while failures >= 1, and every failure rewrites it first
- extract runPostScanAnalysis (cmd) and anyIncludedLibrary (scanner)
  helpers
2026-07-13 12:04:29 -04:00

163 lines
5.9 KiB
Go

package db_test
import (
"context"
"database/sql"
"time"
"github.com/navidrome/navidrome/consts"
"github.com/navidrome/navidrome/db"
. "github.com/onsi/ginkgo/v2"
. "github.com/onsi/gomega"
)
var _ = Describe("Optimize", func() {
var (
ctx context.Context
database *sql.DB
now time.Time
)
BeforeEach(func() {
ctx = context.Background()
now = time.Date(2026, time.July, 9, 12, 0, 0, 0, time.UTC)
var err error
database, err = sql.Open(db.Dialect, "file::memory:")
Expect(err).ToNot(HaveOccurred())
DeferCleanup(database.Close)
_, err = database.Exec(`create table property(
id varchar(255) primary key,
value varchar(255) not null default ''
)`)
Expect(err).ToNot(HaveOccurred())
_, err = database.Exec("create table analyze_probe(id integer primary key, flag int)")
Expect(err).ToNot(HaveOccurred())
_, err = database.Exec(`insert into analyze_probe(flag)
with recursive s(x) as (select 1 union all select x+1 from s where x < 3000)
select 0 from s`)
Expect(err).ToNot(HaveOccurred())
_, err = database.Exec("create index probe_flag on analyze_probe(flag)")
Expect(err).ToNot(HaveOccurred())
_, err = database.Exec("analyze")
Expect(err).ToNot(HaveOccurred())
})
putProperty := func(key, value string) {
_, err := database.Exec(`insert into property(id, value) values(?, ?)
on conflict(id) do update set value=excluded.value`, key, value)
Expect(err).ToNot(HaveOccurred())
}
getProperty := func(key string) string {
var value string
Expect(database.QueryRow("select value from property where id=?", key).Scan(&value)).To(Succeed())
return value
}
poisonStats := func() {
_, err := database.Exec("update sqlite_stat1 set stat='3000 50' where idx='probe_flag'")
Expect(err).ToNot(HaveOccurred())
}
It("replaces poisoned planner statistics with full-quality ones", func() {
poisonStats()
putProperty(consts.DBAnalyzePendingKey, "1")
Expect(db.OptimizeDBAt(ctx, database, now)).To(Succeed())
var stat string
err := database.QueryRow("select stat from sqlite_stat1 where idx='probe_flag'").Scan(&stat)
Expect(err).ToNot(HaveOccurred())
// A full ANALYZE sees all 3000 rows share one value: avg rows per key = row count.
Expect(stat).To(Equal("3000 3000"))
Expect(getProperty(consts.LastDBAnalyzeAtKey)).To(Equal(now.Format(time.RFC3339Nano)))
Expect(getProperty(consts.DBAnalyzePendingKey)).To(Equal("0"))
})
It("runs when no previous analysis was recorded", func() {
ran, err := db.OptimizeDBIfNeeded(ctx, database, now)
Expect(err).ToNot(HaveOccurred())
Expect(ran).To(BeTrue())
Expect(getProperty(consts.LastDBAnalyzeAtKey)).To(Equal(now.Format(time.RFC3339Nano)))
})
It("skips a recent analysis when no refresh is pending", func() {
lastAnalyze := now.Add(-23 * time.Hour)
putProperty(consts.LastDBAnalyzeAtKey, lastAnalyze.Format(time.RFC3339Nano))
putProperty(consts.DBAnalyzePendingKey, "0")
poisonStats()
ran, err := db.OptimizeDBIfNeeded(ctx, database, now)
Expect(err).ToNot(HaveOccurred())
Expect(ran).To(BeFalse())
Expect(getProperty(consts.LastDBAnalyzeAtKey)).To(Equal(lastAnalyze.Format(time.RFC3339Nano)))
var stat string
Expect(database.QueryRow("select stat from sqlite_stat1 where idx='probe_flag'").Scan(&stat)).To(Succeed())
Expect(stat).To(Equal("3000 50"))
})
It("runs when the previous analysis is stale", func() {
putProperty(consts.LastDBAnalyzeAtKey, now.Add(-consts.DBAnalyzeMaxAge).Format(time.RFC3339Nano))
putProperty(consts.DBAnalyzePendingKey, "0")
ran, err := db.OptimizeDBIfNeeded(ctx, database, now)
Expect(err).ToNot(HaveOccurred())
Expect(ran).To(BeTrue())
Expect(getProperty(consts.LastDBAnalyzeAtKey)).To(Equal(now.Format(time.RFC3339Nano)))
})
It("runs when a refresh is pending even if the previous analysis is recent", func() {
putProperty(consts.LastDBAnalyzeAtKey, now.Format(time.RFC3339Nano))
putProperty(consts.DBAnalyzePendingKey, "1")
ran, err := db.OptimizeDBIfNeeded(ctx, database, now.Add(time.Hour))
Expect(err).ToNot(HaveOccurred())
Expect(ran).To(BeTrue())
Expect(getProperty(consts.DBAnalyzePendingKey)).To(Equal("0"))
})
DescribeTable("backs off after consecutive analysis failures",
func(failures string, retryDelay time.Duration) {
putProperty(consts.DBAnalyzePendingKey, "1")
putProperty(consts.DBAnalyzeFailureCountKey, failures)
putProperty(consts.LastDBAnalyzeAttemptAtKey, now.Format(time.RFC3339Nano))
ran, err := db.OptimizeDBIfNeeded(ctx, database, now.Add(retryDelay-time.Nanosecond))
Expect(err).ToNot(HaveOccurred())
Expect(ran).To(BeFalse())
ran, err = db.OptimizeDBIfNeeded(ctx, database, now.Add(retryDelay))
Expect(err).ToNot(HaveOccurred())
Expect(ran).To(BeTrue())
Expect(getProperty(consts.DBAnalyzeFailureCountKey)).To(Equal("0"))
Expect(getProperty(consts.DBAnalyzePendingKey)).To(Equal("0"))
},
Entry("for 30 minutes after the first failure", "1", 30*time.Minute),
Entry("for one hour after the second failure", "2", time.Hour),
Entry("for two hours after the third failure", "3", 2*time.Hour),
Entry("for 24 hours after the fourth failure", "4", 24*time.Hour),
)
It("records consecutive analysis failures", func() {
putProperty(consts.DBAnalyzeFailureCountKey, "2")
Expect(db.RecordAnalyzeFailure(ctx, database, now)).To(Succeed())
Expect(getProperty(consts.DBAnalyzeFailureCountKey)).To(Equal("3"))
Expect(getProperty(consts.LastDBAnalyzeAttemptAtKey)).To(Equal(now.Format(time.RFC3339Nano)))
Expect(getProperty(consts.DBAnalyzePendingKey)).To(Equal("1"))
})
It("does not record success when analysis fails", func() {
lastAnalyze := now.Add(-48 * time.Hour).Format(time.RFC3339Nano)
putProperty(consts.LastDBAnalyzeAtKey, lastAnalyze)
canceledCtx, cancel := context.WithCancel(ctx)
cancel()
Expect(db.OptimizeDBAt(canceledCtx, database, now)).To(MatchError(ContainSubstring("context canceled")))
Expect(getProperty(consts.LastDBAnalyzeAtKey)).To(Equal(lastAnalyze))
})
})