diff --git a/cmd/root.go b/cmd/root.go index 08773176a..b231aae0d 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -86,7 +86,7 @@ func runNavidrome(ctx context.Context) { g.Go(startPlaybackServer(ctx)) g.Go(schedulePeriodicBackup(ctx)) g.Go(startInsightsCollector(ctx)) - g.Go(scheduleDBOptimizer(ctx)) + g.Go(scheduleDBAnalyzer(ctx)) g.Go(startPluginManager(ctx)) g.Go(runInitialScan(ctx)) if conf.Server.Scanner.Enabled { @@ -275,16 +275,24 @@ func schedulePeriodicBackup(ctx context.Context) func() error { } } -func scheduleDBOptimizer(ctx context.Context) func() error { +func scheduleDBAnalyzer(ctx context.Context) func() error { return func() error { - log.Info(ctx, "Scheduling DB optimizer", "schedule", consts.OptimizeDBSchedule) + if !conf.Server.EnableScheduledDBAnalyze { + log.Info(ctx, "Scheduled DB analysis is DISABLED") + return nil + } + log.Info(ctx, "Scheduling DB analysis check", "schedule", consts.DBAnalyzeCheckSchedule) schedulerInstance := scheduler.GetInstance() - _, err := schedulerInstance.Add(consts.OptimizeDBSchedule, func() { - if scanner.IsScanning() { - log.Debug(ctx, "Skipping DB optimization because a scan is in progress") + _, err := schedulerInstance.Add(consts.DBAnalyzeCheckSchedule, func() { + release, ok := scanner.LockForMaintenance() + if !ok { + log.Debug(ctx, "Skipping DB analysis check because a scan is in progress") return } - db.Optimize(ctx) + defer release() + if _, err := db.OptimizeIfNeeded(ctx); err != nil { + log.Error(ctx, "Error analyzing DB", err) + } }) return err } diff --git a/cmd/scan.go b/cmd/scan.go index d8a563396..320b401d4 100644 --- a/cmd/scan.go +++ b/cmd/scan.go @@ -4,6 +4,7 @@ import ( "bufio" "context" "encoding/gob" + "errors" "fmt" "os" "strings" @@ -43,15 +44,20 @@ var scanCmd = &cobra.Command{ }, } -func trackScanInteractively(ctx context.Context, progress <-chan *scanner.ProgressInfo) { +func trackScanInteractively(ctx context.Context, progress <-chan *scanner.ProgressInfo) (bool, error) { + var changesDetected bool + var scanErrors []error for status := range pl.ReadOrDone(ctx, progress) { if status.Warning != "" { log.Warn(ctx, "Scan warning", "error", status.Warning) } if status.Error != "" { log.Error(ctx, "Scan error", "error", status.Error) + scanErrors = append(scanErrors, errors.New(status.Error)) + } + if status.ChangesDetected { + changesDetected = true } - // Discard the progress status, we only care about errors } if fullScan { @@ -59,6 +65,7 @@ func trackScanInteractively(ctx context.Context, progress <-chan *scanner.Progre } else { log.Info("Finished rescan") } + return changesDetected, errors.Join(scanErrors...) } func trackScanAsSubprocess(ctx context.Context, progress <-chan *scanner.ProgressInfo) { @@ -95,6 +102,16 @@ func runScanner(ctx context.Context) { log.Info(ctx, "Scanning specific folders", "numTargets", len(scanTargets)) } + effectiveFullScan := fullScan + if !subprocess { + effectiveFullScan = scanner.EffectiveFullScan(ctx, ds, fullScan, scanTargets) + if effectiveFullScan { + if err := db.MarkOptimizePending(ctx); err != nil { + log.Error(ctx, "Error marking DB analysis pending", err) + } + } + } + progress, err := scanner.CallScan(ctx, ds, pls, fullScan, scanTargets) if err != nil { log.Fatal(ctx, "Failed to scan", err) @@ -104,7 +121,21 @@ func runScanner(ctx context.Context) { if subprocess { trackScanAsSubprocess(ctx, progress) } else { - trackScanInteractively(ctx, progress) + changesDetected, scanErr := trackScanInteractively(ctx, progress) + runPostScanAnalysis(ctx, changesDetected, effectiveFullScan, scanErr) + } +} + +func runPostScanAnalysis(ctx context.Context, changesDetected, effectiveFullScan bool, scanErr error) { + if changesDetected { + if err := db.MarkOptimizePending(ctx); err != nil { + log.Error(ctx, "Error marking DB analysis pending", err) + } + } + if effectiveFullScan && scanErr == nil { + if err := db.Optimize(ctx); err != nil { + log.Error(ctx, "Error analyzing DB", err) + } } } diff --git a/cmd/scan_test.go b/cmd/scan_test.go index beeecca19..309d09f98 100644 --- a/cmd/scan_test.go +++ b/cmd/scan_test.go @@ -1,14 +1,29 @@ package cmd import ( + "context" "os" "path/filepath" "github.com/navidrome/navidrome/model" + "github.com/navidrome/navidrome/scanner" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" ) +var _ = Describe("trackScanInteractively", func() { + It("reports changes and scan errors", func() { + progress := make(chan *scanner.ProgressInfo, 2) + progress <- &scanner.ProgressInfo{ChangesDetected: true} + progress <- &scanner.ProgressInfo{Error: "scan failed"} + close(progress) + + changesDetected, err := trackScanInteractively(context.Background(), progress) + Expect(changesDetected).To(BeTrue()) + Expect(err).To(MatchError("scan failed")) + }) +}) + var _ = Describe("readTargetsFromFile", func() { var tempDir string diff --git a/conf/configuration.go b/conf/configuration.go index 8646bf075..e939ebb7e 100644 --- a/conf/configuration.go +++ b/conf/configuration.go @@ -51,6 +51,7 @@ type configOptions struct { EnableExternalServices bool EnableM3UExternalAlbumArt bool EnableInsightsCollector bool + EnableScheduledDBAnalyze bool EnableMediaFileCoverArt bool TranscodingCacheSize string ImageCacheSize string @@ -147,7 +148,6 @@ type configOptions struct { DevEnablePluginsInsights bool DevPluginCompilationTimeout time.Duration DevExternalArtistFetchMultiplier float64 - DevOptimizeDB bool DevPreserveUnicodeInExternalCalls bool DevEnableMediaFileProbe bool } @@ -800,6 +800,7 @@ func setViperDefaults() { viper.SetDefault("defaultdownloadableshare", false) viper.SetDefault("gatrackingid", "") viper.SetDefault("enableinsightscollector", true) + viper.SetDefault("enablescheduleddbanalyze", true) viper.SetDefault("enablelogredacting", true) viper.SetDefault("authrequestlimit", 5) viper.SetDefault("authwindowlength", 20*time.Second) @@ -891,7 +892,6 @@ func setViperDefaults() { viper.SetDefault("devenablepluginsinsights", true) viper.SetDefault("devplugincompilationtimeout", time.Minute) viper.SetDefault("devexternalartistfetchmultiplier", 1.5) - viper.SetDefault("devoptimizedb", true) viper.SetDefault("devpreserveunicodeinexternalcalls", false) viper.SetDefault("devenablemediafileprobe", true) } diff --git a/conf/configuration_test.go b/conf/configuration_test.go index 9c25a0d19..e43c91a4b 100644 --- a/conf/configuration_test.go +++ b/conf/configuration_test.go @@ -58,6 +58,19 @@ var _ = Describe("Configuration", func() { }) }) + Describe("scheduled DB analysis", func() { + It("is enabled by default", func() { + conf.Load(true) + Expect(conf.Server.EnableScheduledDBAnalyze).To(BeTrue()) + }) + + It("can be disabled", func() { + viper.Set("enablescheduleddbanalyze", false) + conf.Load(true) + Expect(conf.Server.EnableScheduledDBAnalyze).To(BeFalse()) + }) + }) + Describe("ValidateURL", func() { It("accepts a valid http URL", func() { fn := conf.ValidateURL("TestOption", "http://example.com/path") diff --git a/consts/consts.go b/consts/consts.go index 3795b590a..73f89b450 100644 --- a/consts/consts.go +++ b/consts/consts.go @@ -20,6 +20,10 @@ const ( LastScanErrorKey = "LastScanError" LastScanTypeKey = "LastScanType" LastScanStartTimeKey = "LastScanStartTime" + LastDBAnalyzeAtKey = "LastDBAnalyzeAt" + LastDBAnalyzeAttemptAtKey = "LastDBAnalyzeAttemptAt" + DBAnalyzePendingKey = "DBAnalyzePending" + DBAnalyzeFailureCountKey = "DBAnalyzeFailureCount" UIAuthorizationHeader = "X-ND-Authorization" UIClientUniqueIDHeader = "X-ND-Client-Unique-Id" @@ -28,7 +32,8 @@ const ( DefaultSessionTimeout = 48 * time.Hour CookieExpiry = 365 * 24 * 3600 // One year - OptimizeDBSchedule = "@every 24h" + DBAnalyzeCheckSchedule = "@every 30m" + DBAnalyzeMaxAge = 24 * time.Hour // DefaultEncryptionKey This is the encryption key used if none is specified in the `PasswordEncryptionKey` option // Never ever change this! Or it will break all Navidrome installations that don't set the config option diff --git a/core/metrics/insights.go b/core/metrics/insights.go index bcd0343c2..78391779a 100644 --- a/core/metrics/insights.go +++ b/core/metrics/insights.go @@ -223,6 +223,7 @@ var staticData = sync.OnceValue(func() insights.Data { data.Config.ScanSchedule = conf.Server.Scanner.Schedule data.Config.ScanWatcherWait = uint64(math.Trunc(conf.Server.Scanner.WatcherWait.Seconds())) data.Config.ScanOnStartup = conf.Server.Scanner.ScanOnStartup + data.Config.EnableScheduledDBAnalyze = conf.Server.EnableScheduledDBAnalyze data.Config.ReverseProxyConfigured = conf.Server.ExtAuth.TrustedSources != "" data.Config.HasCustomPID = conf.Server.PID.Track != consts.DefaultTrackPID || conf.Server.PID.Album != consts.DefaultAlbumPID data.Config.HasCustomTags = len(conf.Server.Tags) > 0 diff --git a/core/metrics/insights/data.go b/core/metrics/insights/data.go index 34648a49b..126d759bc 100644 --- a/core/metrics/insights/data.go +++ b/core/metrics/insights/data.go @@ -43,45 +43,46 @@ type Data struct { FileSuffixes map[string]int64 `json:"fileSuffixes,omitempty"` } `json:"library"` Config struct { - LogLevel string `json:"logLevel,omitempty"` - LogFileConfigured bool `json:"logFileConfigured,omitempty"` - TLSConfigured bool `json:"tlsConfigured,omitempty"` - ScannerEnabled bool `json:"scannerEnabled,omitempty"` - ScannerExtractor string `json:"scannerExtractor,omitempty"` - ScanSchedule string `json:"scanSchedule,omitempty"` - ScanWatcherWait uint64 `json:"scanWatcherWait,omitempty"` - ScanOnStartup bool `json:"scanOnStartup,omitempty"` - TranscodingCacheSize string `json:"transcodingCacheSize,omitempty"` - ImageCacheSize string `json:"imageCacheSize,omitempty"` - EnableArtworkPrecache bool `json:"enableArtworkPrecache,omitempty"` - EnableDownloads bool `json:"enableDownloads,omitempty"` - EnableSharing bool `json:"enableSharing,omitempty"` - EnableStarRating bool `json:"enableStarRating,omitempty"` - EnableLastFM bool `json:"enableLastFM,omitempty"` - EnableListenBrainz bool `json:"enableListenBrainz,omitempty"` - EnableDeezer bool `json:"enableDeezer,omitempty"` - EnableMediaFileCoverArt bool `json:"enableMediaFileCoverArt,omitempty"` - EnableJukebox bool `json:"enableJukebox,omitempty"` - EnablePrometheus bool `json:"enablePrometheus,omitempty"` - EnableArtworkUpload bool `json:"enableArtworkUpload,omitempty"` - CoverArtQuality int `json:"coverArtQuality,omitempty"` - EnableWebPEncoding bool `json:"enableWebPEncoding,omitempty"` - UICoverArtSize int `json:"uiCoverArtSize,omitempty"` - EnableCoverAnimation bool `json:"enableCoverAnimation,omitempty"` - EnableNowPlaying bool `json:"enableNowPlaying,omitempty"` - SessionTimeout uint64 `json:"sessionTimeout,omitempty"` - SearchFullString bool `json:"searchFullString,omitempty"` - SearchBackend string `json:"searchBackend,omitempty"` - RecentlyAddedByModTime bool `json:"recentlyAddedByModTime,omitempty"` - PreferSortTags bool `json:"preferSortTags,omitempty"` - BackupSchedule string `json:"backupSchedule,omitempty"` - BackupCount int `json:"backupCount,omitempty"` - DevActivityPanel bool `json:"devActivityPanel,omitempty"` - DefaultBackgroundURLSet bool `json:"defaultBackgroundURL,omitempty"` - HasSmartPlaylists bool `json:"hasSmartPlaylists,omitempty"` - ReverseProxyConfigured bool `json:"reverseProxyConfigured,omitempty"` - HasCustomPID bool `json:"hasCustomPID,omitempty"` - HasCustomTags bool `json:"hasCustomTags,omitempty"` + LogLevel string `json:"logLevel,omitempty"` + LogFileConfigured bool `json:"logFileConfigured,omitempty"` + TLSConfigured bool `json:"tlsConfigured,omitempty"` + ScannerEnabled bool `json:"scannerEnabled,omitempty"` + ScannerExtractor string `json:"scannerExtractor,omitempty"` + ScanSchedule string `json:"scanSchedule,omitempty"` + ScanWatcherWait uint64 `json:"scanWatcherWait,omitempty"` + ScanOnStartup bool `json:"scanOnStartup,omitempty"` + EnableScheduledDBAnalyze bool `json:"enableScheduledDBAnalyze,omitempty"` + TranscodingCacheSize string `json:"transcodingCacheSize,omitempty"` + ImageCacheSize string `json:"imageCacheSize,omitempty"` + EnableArtworkPrecache bool `json:"enableArtworkPrecache,omitempty"` + EnableDownloads bool `json:"enableDownloads,omitempty"` + EnableSharing bool `json:"enableSharing,omitempty"` + EnableStarRating bool `json:"enableStarRating,omitempty"` + EnableLastFM bool `json:"enableLastFM,omitempty"` + EnableListenBrainz bool `json:"enableListenBrainz,omitempty"` + EnableDeezer bool `json:"enableDeezer,omitempty"` + EnableMediaFileCoverArt bool `json:"enableMediaFileCoverArt,omitempty"` + EnableJukebox bool `json:"enableJukebox,omitempty"` + EnablePrometheus bool `json:"enablePrometheus,omitempty"` + EnableArtworkUpload bool `json:"enableArtworkUpload,omitempty"` + CoverArtQuality int `json:"coverArtQuality,omitempty"` + EnableWebPEncoding bool `json:"enableWebPEncoding,omitempty"` + UICoverArtSize int `json:"uiCoverArtSize,omitempty"` + EnableCoverAnimation bool `json:"enableCoverAnimation,omitempty"` + EnableNowPlaying bool `json:"enableNowPlaying,omitempty"` + SessionTimeout uint64 `json:"sessionTimeout,omitempty"` + SearchFullString bool `json:"searchFullString,omitempty"` + SearchBackend string `json:"searchBackend,omitempty"` + RecentlyAddedByModTime bool `json:"recentlyAddedByModTime,omitempty"` + PreferSortTags bool `json:"preferSortTags,omitempty"` + BackupSchedule string `json:"backupSchedule,omitempty"` + BackupCount int `json:"backupCount,omitempty"` + DevActivityPanel bool `json:"devActivityPanel,omitempty"` + DefaultBackgroundURLSet bool `json:"defaultBackgroundURL,omitempty"` + HasSmartPlaylists bool `json:"hasSmartPlaylists,omitempty"` + ReverseProxyConfigured bool `json:"reverseProxyConfigured,omitempty"` + HasCustomPID bool `json:"hasCustomPID,omitempty"` + HasCustomTags bool `json:"hasCustomTags,omitempty"` } `json:"config"` Plugins map[string]PluginInfo `json:"plugins,omitempty"` } diff --git a/db/db.go b/db/db.go index 6e5b2f569..3f3f61d71 100644 --- a/db/db.go +++ b/db/db.go @@ -6,6 +6,7 @@ import ( "embed" "fmt" "runtime" + "time" "github.com/mattn/go-sqlite3" "github.com/navidrome/navidrome/conf" @@ -47,12 +48,6 @@ func Db() *sql.DB { if err != nil { log.Fatal("Error opening database", err) } - if conf.Server.DevOptimizeDB { - _, err = db.Exec("PRAGMA optimize=0x10002") - if err != nil { - log.Error("Error applying PRAGMA optimize", err) - } - } return db }) } @@ -61,9 +56,6 @@ func Close(ctx context.Context) { // Ignore cancellations when closing the DB ctx = context.WithoutCancel(ctx) - // Run optimize before closing - Optimize(ctx) - log.Info(ctx, "Closing Database") err := Db().Close() if err != nil { @@ -102,11 +94,11 @@ func Init(ctx context.Context) func() { log.Fatal(ctx, "Failed to apply new migrations", err) } - if hasSchemaChanges && conf.Server.DevOptimizeDB { - log.Debug(ctx, "Applying PRAGMA optimize after schema changes") - _, err = db.ExecContext(ctx, "PRAGMA optimize") + if hasSchemaChanges { + log.Debug(ctx, "Running ANALYZE after schema changes") + err = optimizeAt(ctx, db, time.Now()) if err != nil { - log.Error(ctx, "Error applying PRAGMA optimize", err) + log.Error(ctx, "Error running ANALYZE", err) } } @@ -115,37 +107,6 @@ func Init(ctx context.Context) func() { } } -// Optimize runs PRAGMA optimize on each connection in the pool -func Optimize(ctx context.Context) { - if !conf.Server.DevOptimizeDB { - return - } - numConns := Db().Stats().OpenConnections - if numConns == 0 { - log.Debug(ctx, "No open connections to optimize") - return - } - log.Debug(ctx, "Optimizing open connections", "numConns", numConns) - var conns []*sql.Conn - for range numConns { - conn, err := Db().Conn(ctx) - conns = append(conns, conn) - if err != nil { - log.Error(ctx, "Error getting connection from pool", err) - continue - } - _, err = conn.ExecContext(ctx, "PRAGMA optimize;") - if err != nil { - log.Error(ctx, "Error running PRAGMA optimize", err) - } - } - - // Return all connections to the Connection Pool - for _, conn := range conns { - conn.Close() - } -} - type statusLogger struct{ numPending int } func (*statusLogger) Fatalf(format string, v ...any) { log.Fatal(fmt.Sprintf(format, v...)) } diff --git a/db/export_test.go b/db/export_test.go index 734a4462f..02b88cd66 100644 --- a/db/export_test.go +++ b/db/export_test.go @@ -2,6 +2,9 @@ package db // Definitions for testing private methods var ( - IsSchemaEmpty = isSchemaEmpty - BackupPath = backupPath + IsSchemaEmpty = isSchemaEmpty + BackupPath = backupPath + OptimizeDBAt = optimizeAt + OptimizeDBIfNeeded = optimizeIfNeeded + RecordAnalyzeFailure = recordAnalyzeFailure ) diff --git a/db/migrations/migration.go b/db/migrations/migration.go index 9b1098af1..df1c392a5 100644 --- a/db/migrations/migration.go +++ b/db/migrations/migration.go @@ -7,7 +7,6 @@ import ( "strings" "sync" - "github.com/navidrome/navidrome/conf" "github.com/navidrome/navidrome/consts" ) @@ -21,13 +20,6 @@ func notice(ctx context.Context, tx *sql.Tx, msg string) { // Call this in migrations that requires a full rescan func forceFullRescan(ctx context.Context, tx *sql.Tx) error { - // If a full scan is required, most probably the query optimizer is outdated, so we run `analyze`. - if conf.Server.DevOptimizeDB { - _, err := tx.ExecContext(ctx, `ANALYZE;`) - if err != nil { - return err - } - } _, err := tx.ExecContext(ctx, fmt.Sprintf(` INSERT OR REPLACE into property (id, value) values ('%s', '1'); `, consts.FullScanAfterMigrationFlagKey)) diff --git a/db/optimize.go b/db/optimize.go new file mode 100644 index 000000000..f46906c4e --- /dev/null +++ b/db/optimize.go @@ -0,0 +1,224 @@ +package db + +import ( + "context" + "database/sql" + "errors" + "fmt" + "strconv" + "sync" + "time" + + "github.com/navidrome/navidrome/consts" + "github.com/navidrome/navidrome/log" +) + +var analyzeMux sync.Mutex + +// Optimize refreshes the query-planner statistics with a full ANALYZE. PRAGMA optimize is avoided +// because its limited analysis misestimates Navidrome's low-cardinality indexes. +func Optimize(ctx context.Context) error { + analyzeMux.Lock() + defer analyzeMux.Unlock() + start := time.Now() + if err := optimizeAt(ctx, Db(), start); err != nil { + return err + } + log.Info(ctx, "DB analysis complete", "elapsed", time.Since(start)) + return nil +} + +// OptimizeIfNeeded refreshes statistics when they are stale or a database-changing operation +// marked them for refresh. +func OptimizeIfNeeded(ctx context.Context) (bool, error) { + analyzeMux.Lock() + defer analyzeMux.Unlock() + start := time.Now() + ran, err := optimizeIfNeeded(ctx, Db(), start) + if err != nil || !ran { + return ran, err + } + log.Info(ctx, "DB analysis complete", "elapsed", time.Since(start)) + return true, nil +} + +func optimizeIfNeeded(ctx context.Context, db *sql.DB, now time.Time) (bool, error) { + due, err := optimizeDue(ctx, db, now) + if err != nil || !due { + return false, err + } + return true, optimizeAt(ctx, db, now) +} + +func optimizeDue(ctx context.Context, db *sql.DB, now time.Time) (bool, error) { + backingOff, err := analyzeRetryBackoffActive(ctx, db, now) + if err != nil || backingOff { + return false, err + } + + pending, found, err := getProperty(ctx, db, consts.DBAnalyzePendingKey) + if err != nil { + return false, err + } + if found && pending == "1" { + return true, nil + } + + value, found, err := getProperty(ctx, db, consts.LastDBAnalyzeAtKey) + if err != nil { + return false, err + } + if !found { + return true, nil + } + + lastAnalyze, valid := parseAnalyzeTime(value) + if !valid || lastAnalyze.After(now) { + return true, nil + } + return now.Sub(lastAnalyze) >= consts.DBAnalyzeMaxAge, nil +} + +func parseAnalyzeTime(value string) (time.Time, bool) { + parsed, err := time.Parse(time.RFC3339Nano, value) + return parsed, err == nil +} + +func analyzeRetryBackoffActive(ctx context.Context, db *sql.DB, now time.Time) (bool, error) { + value, found, err := getProperty(ctx, db, consts.DBAnalyzeFailureCountKey) + if err != nil || !found { + return false, err + } + failures, _ := strconv.Atoi(value) + if failures < 1 { + return false, nil + } + + value, found, err = getProperty(ctx, db, consts.LastDBAnalyzeAttemptAtKey) + if err != nil || !found { + return false, err + } + lastAttempt, valid := parseAnalyzeTime(value) + if !valid || lastAttempt.After(now) { + return false, nil + } + return now.Sub(lastAttempt) < analyzeRetryDelay(failures), nil +} + +func analyzeRetryDelay(failures int) time.Duration { + switch failures { + case 1: + return 30 * time.Minute + case 2: + return time.Hour + case 3: + return 2 * time.Hour + default: + return 24 * time.Hour + } +} + +// MarkOptimizePending requests a statistics refresh on the next scheduled maintenance check. +func MarkOptimizePending(ctx context.Context) error { + analyzeMux.Lock() + defer analyzeMux.Unlock() + return markOptimizePending(ctx, Db()) +} + +func markOptimizePending(ctx context.Context, db *sql.DB) error { + return putProperty(ctx, db, consts.DBAnalyzePendingKey, "1") +} + +func optimizeAt(ctx context.Context, db *sql.DB, now time.Time) error { + if err := markOptimizePending(ctx, db); err != nil { + return recordAnalyzeError(ctx, db, now, fmt.Errorf("marking ANALYZE pending: %w", err)) + } + log.Debug(ctx, "Refreshing query planner statistics") + _, err := db.ExecContext(ctx, "ANALYZE") + if err != nil { + return recordAnalyzeError(ctx, db, now, fmt.Errorf("running ANALYZE: %w", err)) + } + if err = recordAnalyzeSuccess(ctx, db, now); err != nil { + return recordAnalyzeError(ctx, db, now, err) + } + return nil +} + +func recordAnalyzeSuccess(ctx context.Context, db *sql.DB, now time.Time) error { + tx, err := db.BeginTx(ctx, nil) + if err != nil { + return fmt.Errorf("recording ANALYZE time: %w", err) + } + defer func() { _ = tx.Rollback() }() + if err = putProperty(ctx, tx, consts.LastDBAnalyzeAtKey, now.UTC().Format(time.RFC3339Nano)); err != nil { + return fmt.Errorf("recording ANALYZE time: %w", err) + } + if err = putProperty(ctx, tx, consts.DBAnalyzePendingKey, "0"); err != nil { + return fmt.Errorf("clearing pending ANALYZE: %w", err) + } + if err = putProperty(ctx, tx, consts.DBAnalyzeFailureCountKey, "0"); err != nil { + return fmt.Errorf("clearing ANALYZE failure count: %w", err) + } + if err = tx.Commit(); err != nil { + return fmt.Errorf("recording ANALYZE state: %w", err) + } + return nil +} + +func recordAnalyzeError(ctx context.Context, db *sql.DB, now time.Time, analyzeErr error) error { + if err := recordAnalyzeFailure(ctx, db, now); err != nil { + return errors.Join(analyzeErr, fmt.Errorf("recording ANALYZE failure: %w", err)) + } + return analyzeErr +} + +func recordAnalyzeFailure(ctx context.Context, db *sql.DB, now time.Time) error { + tx, err := db.BeginTx(ctx, nil) + if err != nil { + return err + } + defer func() { _ = tx.Rollback() }() + + value, found, err := getProperty(ctx, tx, consts.DBAnalyzeFailureCountKey) + if err != nil { + return err + } + failures := 0 + if found { + failures, _ = strconv.Atoi(value) + failures = max(failures, 0) + } + if err = putProperty(ctx, tx, consts.DBAnalyzePendingKey, "1"); err != nil { + return err + } + if err = putProperty(ctx, tx, consts.DBAnalyzeFailureCountKey, strconv.Itoa(failures+1)); err != nil { + return err + } + if err = putProperty(ctx, tx, consts.LastDBAnalyzeAttemptAtKey, now.UTC().Format(time.RFC3339Nano)); err != nil { + return err + } + return tx.Commit() +} + +type sqlExecer interface { + ExecContext(context.Context, string, ...any) (sql.Result, error) +} + +type sqlQueryer interface { + QueryRowContext(context.Context, string, ...any) *sql.Row +} + +func putProperty(ctx context.Context, db sqlExecer, key, value string) error { + _, err := db.ExecContext(ctx, `insert into property(id, value) values(?, ?) + on conflict(id) do update set value=excluded.value`, key, value) + return err +} + +func getProperty(ctx context.Context, db sqlQueryer, key string) (string, bool, error) { + var value string + err := db.QueryRowContext(ctx, "select value from property where id=?", key).Scan(&value) + if errors.Is(err, sql.ErrNoRows) { + return "", false, nil + } + return value, err == nil, err +} diff --git a/db/optimize_test.go b/db/optimize_test.go new file mode 100644 index 000000000..da9b3b9c9 --- /dev/null +++ b/db/optimize_test.go @@ -0,0 +1,162 @@ +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)) + }) +}) diff --git a/persistence/library_repository.go b/persistence/library_repository.go index 3789a71c9..5a0142423 100644 --- a/persistence/library_repository.go +++ b/persistence/library_repository.go @@ -173,15 +173,6 @@ func (r *libraryRepository) ScanEnd(id int) error { Set("last_scan_started_at", time.Time{}). Where(Eq{"id": id}) _, err := r.executeSQL(sq) - if err != nil { - return err - } - // https://www.sqlite.org/pragma.html#pragma_optimize - // Use mask 0x10000 to check table sizes without running ANALYZE - // Running ANALYZE can cause query planner issues with expression-based collation indexes - if conf.Server.DevOptimizeDB { - _, err = r.executeSQL(Expr("PRAGMA optimize=0x10000;")) - } return err } diff --git a/scanner/controller.go b/scanner/controller.go index 175b92e26..463718ba3 100644 --- a/scanner/controller.go +++ b/scanner/controller.go @@ -4,6 +4,8 @@ import ( "context" "errors" "fmt" + "slices" + "sync" "sync/atomic" "time" @@ -13,6 +15,7 @@ import ( "github.com/navidrome/navidrome/core/auth" "github.com/navidrome/navidrome/core/metrics" "github.com/navidrome/navidrome/core/playlists" + "github.com/navidrome/navidrome/db" "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" "github.com/navidrome/navidrome/model/request" @@ -211,6 +214,16 @@ func (s *controller) ScanFolders(requestCtx context.Context, fullScan bool, targ ctx := request.AddValues(s.rootCtx, requestCtx) ctx = auth.WithAdminUser(ctx, s.ds) + // A quick scan is promoted to a full one when it resumes an interrupted full scan; that happens + // inside the scanner (possibly in a subprocess), so mirror it here for the analysis gate. Must + // be read before the scan: ScanEnd clears the flag. + effectiveFullScan := EffectiveFullScan(ctx, s.ds, fullScan, targets) + if effectiveFullScan || s.includesUnscannedLibrary(ctx, targets) { + if err := db.MarkOptimizePending(ctx); err != nil { + log.Error(ctx, "Scanner: Error marking DB analysis pending", err) + } + } + // Send the initial scan status event s.sendMessage(ctx, &events.ScanStatus{Scanning: true, Count: 0, FolderCount: 0}) progress := make(chan *ProgressInfo, 100) @@ -229,6 +242,15 @@ func (s *controller) ScanFolders(requestCtx context.Context, fullScan bool, targ if scanError != nil { _ = s.ds.Property(ctx).Put(consts.LastScanErrorKey, scanError.Error()) } + // Refresh the query-planner statistics after a successful full scan. This must run in the + // server process: with the external scanner, an ANALYZE in the subprocess is invisible to the + // server's pooled connections; their shared schema cache keeps the old statistics until the + // process restarts. + if effectiveFullScan && scanError == nil { + if err := db.Optimize(ctx); err != nil { + log.Error(ctx, "Scanner: Error analyzing DB", err) + } + } // If changes were detected, send a refresh event to all clients if s.changesDetected { log.Debug(ctx, "Library changes imported. Sending refresh event") @@ -255,18 +277,73 @@ func (s *controller) ScanFolders(requestCtx context.Context, fullScan bool, targ // This is a global variable that is used to prevent multiple scans from running at the same time. // "There can be only one" - https://youtu.be/sqcLjcSloXs?si=VlsjEOjTJZ68zIyg -var running atomic.Bool +var ( + running atomic.Bool + scanMaintenanceMux sync.Mutex +) func lockScan(ctx context.Context) (func(), error) { if !running.CompareAndSwap(false, true) { log.Debug(ctx, "Scanner already running, ignoring request") return func() {}, ErrAlreadyScanning } + scanMaintenanceMux.Lock() return func() { + scanMaintenanceMux.Unlock() running.Store(false) }, nil } +// LockForMaintenance prevents a scan from starting while database maintenance is running. +func LockForMaintenance() (func(), bool) { + if !scanMaintenanceMux.TryLock() { + return func() {}, false + } + if running.Load() { + scanMaintenanceMux.Unlock() + return func() {}, false + } + return scanMaintenanceMux.Unlock, true +} + +// EffectiveFullScan reports whether a scan was requested as full or will resume an interrupted +// full scan in one of the included libraries. +func EffectiveFullScan(ctx context.Context, ds model.DataStore, fullScan bool, targets []model.ScanTarget) bool { + if fullScan { + return true + } + return anyIncludedLibrary(ctx, ds, targets, func(library model.Library) bool { + return library.FullScanInProgress + }) +} + +func (s *controller) includesUnscannedLibrary(ctx context.Context, targets []model.ScanTarget) bool { + return anyIncludedLibrary(ctx, s.ds, targets, func(library model.Library) bool { + return library.LastScanAt.IsZero() + }) +} + +// anyIncludedLibrary reports whether any library included in the scan (all of them when targets is +// empty) matches pred. +func anyIncludedLibrary(ctx context.Context, ds model.DataStore, targets []model.ScanTarget, pred func(model.Library) bool) bool { + libraries, err := ds.Library(ctx).GetAll() + if err != nil { + return false + } + if len(targets) == 0 { + return slices.ContainsFunc(libraries, pred) + } + + targeted := make(map[int]struct{}, len(targets)) + for _, target := range targets { + targeted[target.LibraryID] = struct{}{} + } + return slices.ContainsFunc(libraries, func(library model.Library) bool { + _, ok := targeted[library.ID] + return ok && pred(library) + }) +} + func (s *controller) trackProgress(ctx context.Context, progress <-chan *ProgressInfo) ([]string, error) { s.count.Store(0) s.folderCount.Store(0) diff --git a/scanner/controller_test.go b/scanner/controller_test.go index d60d432b4..e4814da64 100644 --- a/scanner/controller_test.go +++ b/scanner/controller_test.go @@ -55,3 +55,41 @@ var _ = Describe("Controller", func() { }) }) }) + +var _ = Describe("LockForMaintenance", func() { + It("allows only one database maintenance operation at a time", func() { + release, ok := scanner.LockForMaintenance() + Expect(ok).To(BeTrue()) + DeferCleanup(release) + + _, ok = scanner.LockForMaintenance() + Expect(ok).To(BeFalse()) + }) +}) + +var _ = Describe("EffectiveFullScan", func() { + var ds *tests.MockDataStore + + BeforeEach(func() { + libraries := &tests.MockLibraryRepo{} + libraries.SetData(model.Libraries{ + {ID: 1, FullScanInProgress: true}, + {ID: 2}, + }) + ds = &tests.MockDataStore{MockedLibrary: libraries} + }) + + It("detects an interrupted full scan in a targeted library", func() { + targets := []model.ScanTarget{{LibraryID: 1, FolderPath: "."}} + Expect(scanner.EffectiveFullScan(context.Background(), ds, false, targets)).To(BeTrue()) + }) + + It("detects an interrupted full scan when scanning all libraries", func() { + Expect(scanner.EffectiveFullScan(context.Background(), ds, false, nil)).To(BeTrue()) + }) + + It("ignores interrupted full scans in untargeted libraries", func() { + targets := []model.ScanTarget{{LibraryID: 2, FolderPath: "."}} + Expect(scanner.EffectiveFullScan(context.Background(), ds, false, targets)).To(BeFalse()) + }) +}) diff --git a/scanner/scanner.go b/scanner/scanner.go index 871b0c696..27e2b19d2 100644 --- a/scanner/scanner.go +++ b/scanner/scanner.go @@ -13,7 +13,6 @@ import ( "github.com/navidrome/navidrome/consts" "github.com/navidrome/navidrome/core/artwork" "github.com/navidrome/navidrome/core/playlists" - "github.com/navidrome/navidrome/db" "github.com/navidrome/navidrome/log" "github.com/navidrome/navidrome/model" "github.com/navidrome/navidrome/utils/run" @@ -161,9 +160,6 @@ func (s *scannerImpl) scanFolders(ctx context.Context, fullScan bool, targets [] // Update last_scan_completed_at for all libraries s.runUpdateLibraries(ctx, &state), - - // Optimize DB - s.runOptimize(ctx), ) if err != nil { log.Error(ctx, "Scanner: Finished with error", "duration", time.Since(startTime), err) @@ -280,15 +276,6 @@ func (s *scannerImpl) runRefreshStats(ctx context.Context, state *scanState) fun } } -func (s *scannerImpl) runOptimize(ctx context.Context) func() error { - return func() error { - start := time.Now() - db.Optimize(ctx) - log.Debug(ctx, "Scanner: Optimized DB", "elapsed", time.Since(start)) - return nil - } -} - func (s *scannerImpl) runUpdateLibraries(ctx context.Context, state *scanState) func() error { return func() error { start := time.Now() diff --git a/scanner/scanner_selective_test.go b/scanner/scanner_selective_test.go index 6c70eb268..17772bf9d 100644 --- a/scanner/scanner_selective_test.go +++ b/scanner/scanner_selective_test.go @@ -4,10 +4,12 @@ import ( "context" "path/filepath" "testing/fstest" + "time" "github.com/Masterminds/squirrel" "github.com/navidrome/navidrome/conf" "github.com/navidrome/navidrome/conf/configtest" + "github.com/navidrome/navidrome/consts" "github.com/navidrome/navidrome/core" "github.com/navidrome/navidrome/core/artwork" "github.com/navidrome/navidrome/core/metrics" @@ -80,7 +82,7 @@ var _ = Describe("ScanFolders", Ordered, func() { rock := template(_t{"albumartist": "Rock Artist", "album": "Rock Album"}) jazz := template(_t{"albumartist": "Jazz Artist", "album": "Jazz Album"}) pop := template(_t{"albumartist": "Pop Artist", "album": "Pop Album"}) - createFS(fstest.MapFS{ + fsys = createFS(fstest.MapFS{ "rock/track1.mp3": rock(track(1, "Rock Track 1")), "rock/track2.mp3": rock(track(2, "Rock Track 2")), "rock/subdir/track3.mp3": rock(track(3, "Rock Track 3")), @@ -122,6 +124,38 @@ var _ = Describe("ScanFolders", Ordered, func() { // Verify files in the pop folder were NOT scanned Expect(paths).ToNot(ContainElement("pop/track6.mp3")) + Expect(ds.Property(ctx).Get(consts.DBAnalyzePendingKey)).To(Equal("1")) + }) + }) + + Describe("Planner statistics maintenance", func() { + It("does not mark routine quick-scan changes for immediate analysis", func() { + rock := template(_t{"albumartist": "Rock Artist", "album": "Rock Album"}) + fsys = createFS(fstest.MapFS{ + "rock/track1.mp3": rock(track(1, "Rock Track 1")), + }) + _, err := s.ScanAll(ctx, true) + Expect(err).ToNot(HaveOccurred()) + Expect(ds.Property(ctx).Get(consts.DBAnalyzePendingKey)).To(Equal("0")) + + fsys.Add("rock/track2.mp3", rock(track(2, "Rock Track 2")), time.Now().Add(time.Second)) + _, err = s.ScanAll(ctx, false) + Expect(err).ToNot(HaveOccurred()) + Expect(ds.Property(ctx).Get(consts.DBAnalyzePendingKey)).To(Equal("0")) + }) + + It("does not treat an interrupted scan in an untargeted library as a full scan", func() { + otherLib := model.Library{ID: 2, Name: "Other Library", Path: "fake:///other"} + Expect(ds.Library(ctx).Put(&otherLib)).To(Succeed()) + Expect(ds.Library(ctx).ScanBegin(lib.ID, true)).To(Succeed()) + + lastAnalyze := "2026-07-09T12:00:00Z" + Expect(ds.Property(ctx).Put(consts.LastDBAnalyzeAtKey, lastAnalyze)).To(Succeed()) + Expect(ds.Property(ctx).Put(consts.DBAnalyzePendingKey, "0")).To(Succeed()) + + _, err := s.ScanFolders(ctx, false, []model.ScanTarget{{LibraryID: otherLib.ID, FolderPath: "."}}) + Expect(err).ToNot(HaveOccurred()) + Expect(ds.Property(ctx).Get(consts.LastDBAnalyzeAtKey)).To(Equal(lastAnalyze)) }) })