navidrome/cmd/root.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

416 lines
15 KiB
Go

package cmd
import (
"context"
"os"
"os/signal"
"strings"
"syscall"
"time"
"github.com/go-chi/chi/v5/middleware"
"github.com/navidrome/navidrome/conf"
"github.com/navidrome/navidrome/consts"
"github.com/navidrome/navidrome/db"
"github.com/navidrome/navidrome/log"
"github.com/navidrome/navidrome/model"
"github.com/navidrome/navidrome/resources"
"github.com/navidrome/navidrome/scanner"
"github.com/navidrome/navidrome/scheduler"
"github.com/navidrome/navidrome/server/backgrounds"
"github.com/spf13/cobra"
"github.com/spf13/viper"
"golang.org/x/sync/errgroup"
// Import adapters to register them
_ "github.com/navidrome/navidrome/adapters/deezer"
_ "github.com/navidrome/navidrome/adapters/gotaglib"
_ "github.com/navidrome/navidrome/adapters/lastfm"
_ "github.com/navidrome/navidrome/adapters/listenbrainz"
)
var (
cfgFile string
noBanner bool
rootCmd = &cobra.Command{
Use: "navidrome",
Short: "Navidrome is a self-hosted music server and streamer",
Long: `Navidrome is a self-hosted music server and streamer.
Complete documentation is available at https://www.navidrome.org/docs`,
PersistentPreRun: func(cmd *cobra.Command, args []string) {
preRun()
},
Run: func(cmd *cobra.Command, args []string) {
runNavidrome(cmd.Context())
},
PostRun: func(cmd *cobra.Command, args []string) {
postRun()
},
Version: consts.Version,
}
)
// Execute runs the root cobra command, which will start the Navidrome server by calling the runNavidrome function.
func Execute() {
ctx, cancel := mainContext(context.Background())
defer cancel()
rootCmd.SetVersionTemplate(`{{println .Version}}`)
if err := rootCmd.ExecuteContext(ctx); err != nil {
log.Fatal(err)
}
}
func preRun() {
if !noBanner {
println(resources.Banner())
}
conf.Load(noBanner)
}
func postRun() {
log.Info("Navidrome stopped, bye.")
}
// runNavidrome is the main entry point for the Navidrome server. It starts all the services and blocks.
// If any of the services returns an error, it will log it and exit. If the process receives a signal to exit,
// it will cancel the context and exit gracefully.
func runNavidrome(ctx context.Context) {
defer db.Init(ctx)()
g, ctx := errgroup.WithContext(ctx)
g.Go(startServer(ctx))
g.Go(startSignaller(ctx))
g.Go(startScheduler(ctx))
g.Go(startPlaybackServer(ctx))
g.Go(schedulePeriodicBackup(ctx))
g.Go(startInsightsCollector(ctx))
g.Go(scheduleDBAnalyzer(ctx))
g.Go(startPluginManager(ctx))
g.Go(runInitialScan(ctx))
if conf.Server.Scanner.Enabled {
g.Go(startScanWatcher(ctx))
g.Go(schedulePeriodicScan(ctx))
} else {
log.Warn(ctx, "Automatic Scanning is DISABLED")
}
if err := g.Wait(); err != nil {
log.Error("Fatal error in Navidrome. Aborting", err)
}
}
// mainContext returns a context that is cancelled when the process receives a signal to exit.
func mainContext(ctx context.Context) (context.Context, context.CancelFunc) {
return signal.NotifyContext(ctx,
os.Interrupt,
syscall.SIGHUP,
syscall.SIGTERM,
syscall.SIGABRT,
)
}
// startServer starts the Navidrome web server, adding all the necessary routers.
func startServer(ctx context.Context) func() error {
return func() error {
a := CreateServer()
a.MountRouter("Native API", consts.URLPathNativeAPI, CreateNativeAPIRouter(ctx))
a.MountRouter("Subsonic API", consts.URLPathSubsonicAPI, CreateSubsonicAPIRouter(ctx))
a.MountRouter("Public Endpoints", consts.URLPathPublic, CreatePublicRouter())
if conf.Server.LastFM.Enabled {
a.MountRouter("LastFM Auth", consts.URLPathNativeAPI+"/lastfm", CreateLastFMRouter())
}
if conf.Server.ListenBrainz.Enabled {
a.MountRouter("ListenBrainz Auth", consts.URLPathNativeAPI+"/listenbrainz", CreateListenBrainzRouter())
}
if conf.Server.Prometheus.Enabled {
p := CreatePrometheus()
// blocking call because takes <100ms but useful if fails
p.WriteInitialMetrics(ctx)
a.MountRouter("Prometheus metrics", conf.Server.Prometheus.MetricsPath, p.GetHandler())
}
if conf.Server.DevEnableProfiler {
a.MountRouter("Profiling", "/debug", middleware.Profiler())
}
if strings.HasPrefix(conf.Server.UILoginBackgroundURL, "/") {
a.MountRouter("Background images", conf.Server.UILoginBackgroundURL, backgrounds.NewHandler())
}
return a.Run(ctx, conf.Server.Address, conf.Server.Port, conf.Server.TLSCert, conf.Server.TLSKey)
}
}
// schedulePeriodicScan schedules a periodic scan of the music library, if configured.
func schedulePeriodicScan(ctx context.Context) func() error {
return func() error {
schedule := conf.Server.Scanner.Schedule
if schedule == "" {
log.Info(ctx, "Periodic scan is DISABLED")
return nil
}
s := CreateScanner(ctx)
schedulerInstance := scheduler.GetInstance()
log.Info("Scheduling periodic scan", "schedule", schedule)
_, err := schedulerInstance.Add(schedule, func() {
_, err := s.ScanAll(ctx, false)
if err != nil {
log.Error(ctx, "Error executing periodic scan", err)
}
})
if err != nil {
log.Error(ctx, "Error scheduling periodic scan", err)
}
return nil
}
}
func pidHashChanged(ds model.DataStore) (bool, error) {
pidAlbum, err := ds.Property(context.Background()).DefaultGet(consts.PIDAlbumKey, "")
if err != nil {
return false, err
}
pidTrack, err := ds.Property(context.Background()).DefaultGet(consts.PIDTrackKey, "")
if err != nil {
return false, err
}
return !strings.EqualFold(pidAlbum, conf.Server.PID.Album) || !strings.EqualFold(pidTrack, conf.Server.PID.Track), nil
}
// runInitialScan runs an initial scan of the music library if needed.
func runInitialScan(ctx context.Context) func() error {
return func() error {
ds := CreateDataStore()
fullScanRequired, err := ds.Property(ctx).DefaultGet(consts.FullScanAfterMigrationFlagKey, "0")
if err != nil {
return err
}
inProgress, err := ds.Library(ctx).ScanInProgress()
if err != nil {
return err
}
pidHasChanged, err := pidHashChanged(ds)
if err != nil {
return err
}
scanOnStartup := conf.Server.Scanner.Enabled && conf.Server.Scanner.ScanOnStartup
scanNeeded := scanOnStartup || inProgress || fullScanRequired == "1" || pidHasChanged
time.Sleep(2 * time.Second) // Wait 2 seconds before the initial scan
if scanNeeded {
s := CreateScanner(ctx)
switch {
case fullScanRequired == "1":
log.Warn(ctx, "Full scan required after migration")
_ = ds.Property(ctx).Delete(consts.FullScanAfterMigrationFlagKey)
case pidHasChanged:
log.Warn(ctx, "PID config changed, performing full scan")
fullScanRequired = "1"
case inProgress:
log.Warn(ctx, "Resuming interrupted scan")
default:
log.Info("Executing initial scan")
}
_, err = s.ScanAll(ctx, fullScanRequired == "1")
if err != nil {
log.Error(ctx, "Scan failed", err)
} else {
log.Info(ctx, "Scan completed")
}
} else {
log.Debug(ctx, "Initial scan not needed")
}
return nil
}
}
func startScanWatcher(ctx context.Context) func() error {
return func() error {
if conf.Server.Scanner.WatcherWait == 0 {
log.Debug("Folder watcher is DISABLED")
return nil
}
w := CreateScanWatcher(ctx)
err := w.Run(ctx)
if err != nil {
log.Error("Error starting watcher", err)
}
return nil
}
}
func schedulePeriodicBackup(ctx context.Context) func() error {
return func() error {
schedule := conf.Server.Backup.Schedule
if schedule == "" {
log.Info(ctx, "Periodic backup is DISABLED")
return nil
}
schedulerInstance := scheduler.GetInstance()
log.Info("Scheduling periodic backup", "schedule", schedule)
_, err := schedulerInstance.Add(schedule, func() {
start := time.Now()
path, err := db.Backup(ctx)
elapsed := time.Since(start)
if err != nil {
log.Error(ctx, "Error backing up database", "elapsed", elapsed, err)
return
}
log.Info(ctx, "Backup complete", "elapsed", elapsed, "path", path)
count, err := db.Prune(ctx)
if err != nil {
log.Error(ctx, "Error pruning database", "error", err)
} else if count > 0 {
log.Info(ctx, "Successfully pruned old files", "count", count)
} else {
log.Info(ctx, "No backups pruned")
}
})
return err
}
}
func scheduleDBAnalyzer(ctx context.Context) func() error {
return func() error {
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.DBAnalyzeCheckSchedule, func() {
release, ok := scanner.LockForMaintenance()
if !ok {
log.Debug(ctx, "Skipping DB analysis check because a scan is in progress")
return
}
defer release()
if _, err := db.OptimizeIfNeeded(ctx); err != nil {
log.Error(ctx, "Error analyzing DB", err)
}
})
return err
}
}
// startScheduler starts the Navidrome scheduler, which is used to run periodic tasks.
func startScheduler(ctx context.Context) func() error {
return func() error {
log.Info(ctx, "Starting scheduler")
schedulerInstance := scheduler.GetInstance()
schedulerInstance.Run(ctx)
return nil
}
}
// startInsightsCollector starts the Navidrome Insight Collector, if configured.
func startInsightsCollector(ctx context.Context) func() error {
return func() error {
if !conf.Server.EnableInsightsCollector {
log.Info(ctx, "Insight Collector is DISABLED")
return nil
}
log.Info(ctx, "Starting Insight Collector")
select {
case <-time.After(conf.Server.DevInsightsInitialDelay):
case <-ctx.Done():
return nil
}
ic := CreateInsights()
ic.Run(ctx)
return nil
}
}
// startPlaybackServer starts the Navidrome playback server, if configured.
// It is responsible for the Jukebox functionality
func startPlaybackServer(ctx context.Context) func() error {
return func() error {
if !conf.Server.Jukebox.Enabled {
log.Debug("Jukebox is DISABLED")
return nil
}
log.Info(ctx, "Starting Jukebox service")
playbackInstance := GetPlaybackServer()
return playbackInstance.Run(ctx)
}
}
// startPluginManager starts the plugin manager, if configured.
func startPluginManager(ctx context.Context) func() error {
return func() error {
manager := GetPluginManager(ctx)
if !conf.Server.Plugins.Enabled {
log.Debug("Plugin system is DISABLED")
return nil
}
log.Info(ctx, "Starting plugin manager")
return manager.Start(ctx)
}
}
// TODO: Implement some struct tags to map flags to viper
func init() {
cobra.OnInitialize(func() {
conf.InitConfig(cfgFile, true)
})
rootCmd.PersistentFlags().StringVarP(&cfgFile, "configfile", "c", "", `config file (default "./navidrome.toml")`)
rootCmd.PersistentFlags().BoolVarP(&noBanner, "nobanner", "n", false, `don't show banner`)
rootCmd.PersistentFlags().String("musicfolder", viper.GetString("musicfolder"), "folder where your music is stored")
rootCmd.PersistentFlags().String("datafolder", viper.GetString("datafolder"), "folder to store application data (DB), needs write access")
rootCmd.PersistentFlags().String("cachefolder", viper.GetString("cachefolder"), "folder to store cache data (transcoding, images...), needs write access")
rootCmd.PersistentFlags().StringP("loglevel", "l", viper.GetString("loglevel"), "log level, possible values: error, info, debug, trace")
rootCmd.PersistentFlags().String("logfile", viper.GetString("logfile"), "log file path, if not set logs will be printed to stderr")
_ = viper.BindPFlag("musicfolder", rootCmd.PersistentFlags().Lookup("musicfolder"))
_ = viper.BindPFlag("datafolder", rootCmd.PersistentFlags().Lookup("datafolder"))
_ = viper.BindPFlag("cachefolder", rootCmd.PersistentFlags().Lookup("cachefolder"))
_ = viper.BindPFlag("loglevel", rootCmd.PersistentFlags().Lookup("loglevel"))
_ = viper.BindPFlag("logfile", rootCmd.PersistentFlags().Lookup("logfile"))
rootCmd.Flags().StringP("address", "a", viper.GetString("address"), "IP address to bind to")
rootCmd.Flags().IntP("port", "p", viper.GetInt("port"), "HTTP port Navidrome will listen to")
rootCmd.Flags().String("baseurl", viper.GetString("baseurl"), "base URL to configure Navidrome behind a proxy (ex: /music or http://my.server.com)")
rootCmd.Flags().String("tlscert", viper.GetString("tlscert"), "optional path to a TLS cert file (enables HTTPS listening)")
rootCmd.Flags().String("unixsocketperm", viper.GetString("unixsocketperm"), "optional file permission for the unix socket")
rootCmd.Flags().String("tlskey", viper.GetString("tlskey"), "optional path to a TLS key file (enables HTTPS listening)")
rootCmd.Flags().Duration("sessiontimeout", viper.GetDuration("sessiontimeout"), "how long Navidrome will wait before closing web ui idle sessions")
rootCmd.Flags().Duration("scaninterval", viper.GetDuration("scaninterval"), "how frequently to scan for changes in your music library")
rootCmd.Flags().String("uiloginbackgroundurl", viper.GetString("uiloginbackgroundurl"), "URL to a backaground image used in the Login page")
rootCmd.Flags().Bool("enabletranscodingconfig", viper.GetBool("enabletranscodingconfig"), "enables transcoding configuration in the UI")
rootCmd.Flags().Bool("enabletranscodingcancellation", viper.GetBool("enabletranscodingcancellation"), "enables transcoding context cancellation")
rootCmd.Flags().String("transcodingcachesize", viper.GetString("transcodingcachesize"), "size of transcoding cache")
rootCmd.Flags().String("imagecachesize", viper.GetString("imagecachesize"), "size of image (art work) cache. set to 0 to disable cache")
rootCmd.Flags().String("albumplaycountmode", viper.GetString("albumplaycountmode"), "how to compute playcount for albums. absolute (default) or normalized")
rootCmd.Flags().Bool("autoimportplaylists", viper.GetBool("autoimportplaylists"), "enable/disable .m3u playlist auto-import`")
rootCmd.Flags().Bool("prometheus.enabled", viper.GetBool("prometheus.enabled"), "enable/disable prometheus metrics endpoint`")
rootCmd.Flags().String("prometheus.metricspath", viper.GetString("prometheus.metricspath"), "http endpoint for prometheus metrics")
_ = viper.BindPFlag("address", rootCmd.Flags().Lookup("address"))
_ = viper.BindPFlag("port", rootCmd.Flags().Lookup("port"))
_ = viper.BindPFlag("tlscert", rootCmd.Flags().Lookup("tlscert"))
_ = viper.BindPFlag("unixsocketperm", rootCmd.Flags().Lookup("unixsocketperm"))
_ = viper.BindPFlag("tlskey", rootCmd.Flags().Lookup("tlskey"))
_ = viper.BindPFlag("baseurl", rootCmd.Flags().Lookup("baseurl"))
_ = viper.BindPFlag("sessiontimeout", rootCmd.Flags().Lookup("sessiontimeout"))
_ = viper.BindPFlag("scaninterval", rootCmd.Flags().Lookup("scaninterval"))
_ = viper.BindPFlag("uiloginbackgroundurl", rootCmd.Flags().Lookup("uiloginbackgroundurl"))
_ = viper.BindPFlag("prometheus.enabled", rootCmd.Flags().Lookup("prometheus.enabled"))
_ = viper.BindPFlag("prometheus.metricspath", rootCmd.Flags().Lookup("prometheus.metricspath"))
_ = viper.BindPFlag("enabletranscodingconfig", rootCmd.Flags().Lookup("enabletranscodingconfig"))
_ = viper.BindPFlag("enabletranscodingcancellation", rootCmd.Flags().Lookup("enabletranscodingcancellation"))
_ = viper.BindPFlag("transcodingcachesize", rootCmd.Flags().Lookup("transcodingcachesize"))
_ = viper.BindPFlag("imagecachesize", rootCmd.Flags().Lookup("imagecachesize"))
}