mirror of
https://github.com/navidrome/navidrome.git
synced 2026-07-31 01:06:23 -04:00
* 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
163 lines
5.9 KiB
Go
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))
|
|
})
|
|
})
|