navidrome/db/optimize_test.go

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

199 lines
7.2 KiB
Go
Raw Permalink Normal View History

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
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"))
})
fix(scanner): stop DB lock starvation during scans on slow storage (#6201) * fix(artwork): pause the artwork worker while a scan is running The artwork worker added in 0.64 writes to the database continuously, including while a scan runs. On slow storage the scanner holds the write lock for many seconds per folder, so the two writers keep timing each other out: artwork writes fail with "database is locked", and a single busy timeout on the scanner side aborts the whole scan. The worker now stops dispatching queue items while scanner.IsScanning reports true, including mid-batch, and resumes on the next poll after the scan ends. Artwork requests are unaffected, since they serve local art without the worker. * fix(db): run ANALYZE one index at a time so writers are not starved A full ANALYZE is a single write transaction, so every other write waits for it to finish and fails after the 15s busy timeout. On slow NAS storage it was measured taking over 26 minutes. The analysis now runs ANALYZE per index (per table for unindexed and WITHOUT ROWID tables), which produces the same sqlite_stat1 rows as a full ANALYZE, and pauses briefly between steps (up to 150ms, just above SQLite's longest busy-handler sleep) so waiting writers get the lock. * fix(scanner): ignore Synology @eaDir metadata folders Synology creates an @eaDir folder next to media files, holding one subfolder per file with generated thumbnails. The scanner and watcher treated them as regular folders, which on one reported library added tens of thousands of extra folders to every scan. * fix(db): analyze tables with only partial indexes as a whole A partial index does not record the table's row count, so a table whose only indexes are partial needs a table-level ANALYZE to get the sqlite_stat1 row a full ANALYZE would write. Navidrome's schema has no such table today, but the stepped analysis should match a full ANALYZE for any schema a future migration creates. * fix(scanner): retry busy folder saves and stop phase 1 on a fatal error On slow storage, a single SQLITE_BUSY while saving a folder aborted the whole scan, even when another writer held the lock only briefly. The folder save now runs as a retryable unit: on a busy error it waits (5s, 10s, 15s) and reruns the transaction, up to three times, before failing. Side effects that do not survive a rollback (the album ID map consumed by persistAlbum, the artwork queue items, the image-change record) are rebuilt per attempt or recorded only after a successful commit. When a folder save does fail, phase 1 used to keep walking the library and reading tags for every remaining folder, discarding the results, before reporting the error; a reporter saw 40 silent minutes. The walk now stops as soon as the save fails, and the walker honors cancellation instead of blocking on its channel. Because an early stop leaves folders unvisited, phase 1 no longer marks unvisited folders missing when the phase failed; the resumed scan handles them. * refactor(persistence): move busy retry into DataStore.WithTxRetry The scanner retried its folder save itself, which meant it had to know SQLite error codes. WithTxRetry now owns that policy: it reruns the block in a fresh transaction on SQLITE_BUSY, up to three times with growing delays, and runs it only once when already inside a transaction, since the outer transaction would still hold the lock. The block receives the context to use, and attempts that will be retried carry a marker so a busy statement in them is logged as a warning; only the final attempt logs errors. The scanner's inner error logs are folded into wrapped errors, so a recovered retry no longer prints error-level lines, and the folder path travels in the log context. * fix(persistence): join the enclosing transaction in a nested WithTxRetry Called on a store that is already inside a transaction, WithTxRetry went through WithTx, which opens a second, independent transaction on another connection. That transaction waits on the lock the outer one holds and fails with SQLITE_BUSY, and if it does succeed the outer transaction cannot roll it back. It now runs the block on the enclosing transaction, which owns the lock, the commit and the rollback. Found by a Codex (gpt-6-sol) review. * fix(scanner): retry the remaining scan writes on a busy database Every write step after phase 1 still aborted the whole scan on a single SQLITE_BUSY: phase 1 finalize, phase 2 moves and purge, phase 3 album saves and play count refreshes, the deferred playlist import flag, library ScanBegin, GC, the missing-artwork enqueue, tag counts, and the final library update. They now go through WithTxRetry. The phase 2 move had to be made rerun-safe first: it changed the target track's ID inside the transaction, so a rerun would have deleted the moved track itself, and it marked album annotations as handled even when the transaction rolled back. It now works on a copy per attempt and records the annotation reassignment only after a commit. Artist.RefreshStats is left alone: it updates artists in batches outside a transaction, and one transaction around all of them would hold the write lock for the whole refresh on slow storage. Phase 4 playlist imports go through the playlist service and are left for a follow-up. * fix(scanner): claim the album before moving its annotations The rerun-safe moveMatched checked processedAlbumAnnotations before its transaction and marked the album only after the commit. Phase 2 runs same-library and cross-library moves in separate pipeline stages, so two moves into one album could both pass the check; the second would reassign annotations again and overwrite the album's created_at. The album is now claimed under the lock before the transaction, as the old code effectively did, and the claim is released if the move fails so a later move can still reassign. Found by a Codex (gpt-6-sol) review. * fix(artwork): keep artwork housekeeping from writing during scans The artwork worker already pauses while a scan runs, but its housekeeping jobs did not: the hourly missing-artwork recheck (a bulk INSERT ... SELECT over albums and artists), the startup run of the same recheck, and the daily prune all kept competing with the scanner for the write lock. They now run through LockForMaintenance, like the scheduled DB analysis: they skip while a scan is running and keep a scan from starting until they finish. Skipping the recheck loses nothing, since each scan with changes queues missing artwork at its end. * refactor(scanner): log retried step errors once, from the caller Blocks passed to WithTxRetry still logged their own errors at error level on every attempt, so a busy error that a retry absorbed printed several error lines (GC printed three). They now return wrapped errors and the callers, which already log them, report the final outcome once. Also: drop a leftover variable in phase 1 finalize, check the walk context once, stop repeating the folder field that is already in the log context, stop shadowing finalize's err in phase 3, and format the WithTxRetry scope the same way as WithTx. * test(scanner): make the scanner suite's temp DB cleanup best effort Which DB file the process-wide DB handle opens depends on which spec touches it first. When the Scanner container wins the random order, its temp DB stays open until db.Close after RunSpecs, and on Windows removing the temp dir fails with 'being used by another process'. Ginkgo pins that on the container's last spec, which is now one of the busy-database specs. The sibling suites skip Windows for the same reason; this one now removes its temp dir on a best-effort basis instead, so it keeps running there.
2026-09-23 17:04:50 -04:00
It("produces the same statistics as a single full ANALYZE", func() {
putProperty(consts.DBAnalyzePendingKey, "1")
for _, stmt := range []string{
"create table unindexed(id integer primary key, v int)",
"insert into unindexed(v) select flag from analyze_probe",
"create table no_rowid(k text primary key, v int) without rowid",
"insert into no_rowid select 'k' || id, id % 7 from analyze_probe",
"create index no_rowid_v on no_rowid(v)",
"create table partial_only(id integer primary key, v int)",
"insert into partial_only(v) select id % 5 from analyze_probe",
"create index partial_only_v on partial_only(v) where v = 1",
"analyze",
} {
_, err := database.Exec(stmt)
Expect(err).ToNot(HaveOccurred())
}
statRows := func() []string {
rows, err := database.Query("select tbl || '|' || coalesce(idx, '') || '|' || stat from sqlite_stat1 order by 1")
Expect(err).ToNot(HaveOccurred())
defer rows.Close()
var res []string
for rows.Next() {
var s string
Expect(rows.Scan(&s)).To(Succeed())
res = append(res, s)
}
return res
}
fullAnalyze := statRows()
_, err := database.Exec("delete from sqlite_stat1")
Expect(err).ToNot(HaveOccurred())
Expect(db.OptimizeDBAt(ctx, database, now)).To(Succeed())
Expect(statRows()).To(Equal(fullAnalyze))
})
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
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))
})
})