From 1468a56808dcadfce9aee8fc24c4f55a95aeb457 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Deluan=20Quint=C3=A3o?= Date: Wed, 26 Feb 2025 19:01:49 -0800 Subject: [PATCH] fix(server): reduce SQLite "database busy" errors (#3760) * fix(scanner): remove transactions where they are not strictly needed Signed-off-by: Deluan * fix(server): force setStar transaction to start as IMMEDIATE Signed-off-by: Deluan * fix(server): encapsulated way to upgrade tx to write mode Signed-off-by: Deluan * fix(server): use tx immediate for some playlist endpoints Signed-off-by: Deluan * make more transactions immediate (#3759) --------- Signed-off-by: Deluan Co-authored-by: Kendall Garner <17521368+kgarner7@users.noreply.github.com> --- core/playlists.go | 2 +- model/datastore.go | 1 + persistence/persistence.go | 14 ++++ scanner/phase_2_missing_tracks.go | 126 ++++++++++++++-------------- scanner/phase_3_refresh_albums.go | 50 +++++------ scanner/scanner.go | 32 ++++--- server/nativeapi/playlists.go | 2 +- server/subsonic/media_annotation.go | 2 +- server/subsonic/playlists.go | 2 +- tests/mock_data_store.go | 4 + 10 files changed, 120 insertions(+), 115 deletions(-) diff --git a/core/playlists.go b/core/playlists.go index 2aa538b69..885cd8c7d 100644 --- a/core/playlists.go +++ b/core/playlists.go @@ -262,7 +262,7 @@ func (s *playlists) Update(ctx context.Context, playlistID string, needsInfoUpdate := name != nil || comment != nil || public != nil needsTrackRefresh := len(idxToRemove) > 0 - return s.ds.WithTx(func(tx model.DataStore) error { + return s.ds.WithTxImmediate(func(tx model.DataStore) error { var pls *model.Playlist var err error repo := tx.Playlist(ctx) diff --git a/model/datastore.go b/model/datastore.go index 3babb9f1b..4290e2134 100644 --- a/model/datastore.go +++ b/model/datastore.go @@ -42,5 +42,6 @@ type DataStore interface { Resource(ctx context.Context, model interface{}) ResourceRepository WithTx(block func(tx DataStore) error, scope ...string) error + WithTxImmediate(block func(tx DataStore) error, scope ...string) error GC(ctx context.Context) error } diff --git a/persistence/persistence.go b/persistence/persistence.go index d9569c4d0..579f13707 100644 --- a/persistence/persistence.go +++ b/persistence/persistence.go @@ -143,6 +143,20 @@ func (s *SQLStore) WithTx(block func(tx model.DataStore) error, scope ...string) }) } +func (s *SQLStore) WithTxImmediate(block func(tx model.DataStore) error, scope ...string) error { + ctx := context.Background() + return s.WithTx(func(tx model.DataStore) error { + // Workaround to force the transaction to be upgraded to immediate mode to avoid deadlocks + // See https://berthub.eu/articles/posts/a-brief-post-on-sqlite3-database-locked-despite-timeout/ + _ = tx.Property(ctx).Put("tmp_lock_flag", "") + defer func() { + _ = tx.Property(ctx).Delete("tmp_lock_flag") + }() + + return block(tx) + }, scope...) +} + func (s *SQLStore) GC(ctx context.Context) error { trace := func(ctx context.Context, msg string, f func() error) func() error { return func() error { diff --git a/scanner/phase_2_missing_tracks.go b/scanner/phase_2_missing_tracks.go index c0a1287f1..352f92c34 100644 --- a/scanner/phase_2_missing_tracks.go +++ b/scanner/phase_2_missing_tracks.go @@ -106,79 +106,75 @@ func (p *phaseMissingTracks) stages() []ppl.Stage[*missingTracks] { } func (p *phaseMissingTracks) processMissingTracks(in *missingTracks) (*missingTracks, error) { - err := p.ds.WithTx(func(tx model.DataStore) error { - for _, ms := range in.missing { - var exactMatch model.MediaFile - var equivalentMatch model.MediaFile + for _, ms := range in.missing { + var exactMatch model.MediaFile + var equivalentMatch model.MediaFile - // Identify exact and equivalent matches - for _, mt := range in.matched { - if ms.Equals(mt) { - exactMatch = mt - break // Prioritize exact match - } - if ms.IsEquivalent(mt) { - equivalentMatch = mt - } + // Identify exact and equivalent matches + for _, mt := range in.matched { + if ms.Equals(mt) { + exactMatch = mt + break // Prioritize exact match } - - // Use the exact match if found - if exactMatch.ID != "" { - log.Debug(p.ctx, "Scanner: Found missing track in a new place", "missing", ms.Path, "movedTo", exactMatch.Path, "lib", in.lib.Name) - err := p.moveMatched(tx, exactMatch, ms) - if err != nil { - log.Error(p.ctx, "Scanner: Error moving matched track", "missing", ms.Path, "movedTo", exactMatch.Path, "lib", in.lib.Name, err) - return err - } - p.totalMatched.Add(1) - continue - } - - // If there is only one missing and one matched track, consider them equivalent (same PID) - if len(in.missing) == 1 && len(in.matched) == 1 { - singleMatch := in.matched[0] - log.Debug(p.ctx, "Scanner: Found track with same persistent ID in a new place", "missing", ms.Path, "movedTo", singleMatch.Path, "lib", in.lib.Name) - err := p.moveMatched(tx, singleMatch, ms) - if err != nil { - log.Error(p.ctx, "Scanner: Error updating matched track", "missing", ms.Path, "movedTo", singleMatch.Path, "lib", in.lib.Name, err) - return err - } - p.totalMatched.Add(1) - continue - } - - // Use the equivalent match if no other better match was found - if equivalentMatch.ID != "" { - log.Debug(p.ctx, "Scanner: Found missing track with same base path", "missing", ms.Path, "movedTo", equivalentMatch.Path, "lib", in.lib.Name) - err := p.moveMatched(tx, equivalentMatch, ms) - if err != nil { - log.Error(p.ctx, "Scanner: Error updating matched track", "missing", ms.Path, "movedTo", equivalentMatch.Path, "lib", in.lib.Name, err) - return err - } - p.totalMatched.Add(1) + if ms.IsEquivalent(mt) { + equivalentMatch = mt } } - return nil - }, "scanner: process missing tracks") - if err != nil { - return nil, err + + // Use the exact match if found + if exactMatch.ID != "" { + log.Debug(p.ctx, "Scanner: Found missing track in a new place", "missing", ms.Path, "movedTo", exactMatch.Path, "lib", in.lib.Name) + err := p.moveMatched(exactMatch, ms) + if err != nil { + log.Error(p.ctx, "Scanner: Error moving matched track", "missing", ms.Path, "movedTo", exactMatch.Path, "lib", in.lib.Name, err) + return nil, err + } + p.totalMatched.Add(1) + continue + } + + // If there is only one missing and one matched track, consider them equivalent (same PID) + if len(in.missing) == 1 && len(in.matched) == 1 { + singleMatch := in.matched[0] + log.Debug(p.ctx, "Scanner: Found track with same persistent ID in a new place", "missing", ms.Path, "movedTo", singleMatch.Path, "lib", in.lib.Name) + err := p.moveMatched(singleMatch, ms) + if err != nil { + log.Error(p.ctx, "Scanner: Error updating matched track", "missing", ms.Path, "movedTo", singleMatch.Path, "lib", in.lib.Name, err) + return nil, err + } + p.totalMatched.Add(1) + continue + } + + // Use the equivalent match if no other better match was found + if equivalentMatch.ID != "" { + log.Debug(p.ctx, "Scanner: Found missing track with same base path", "missing", ms.Path, "movedTo", equivalentMatch.Path, "lib", in.lib.Name) + err := p.moveMatched(equivalentMatch, ms) + if err != nil { + log.Error(p.ctx, "Scanner: Error updating matched track", "missing", ms.Path, "movedTo", equivalentMatch.Path, "lib", in.lib.Name, err) + return nil, err + } + p.totalMatched.Add(1) + } } return in, nil } -func (p *phaseMissingTracks) moveMatched(tx model.DataStore, mt, ms model.MediaFile) error { - discardedID := mt.ID - mt.ID = ms.ID - err := tx.MediaFile(p.ctx).Put(&mt) - if err != nil { - return fmt.Errorf("update matched track: %w", err) - } - err = tx.MediaFile(p.ctx).Delete(discardedID) - if err != nil { - return fmt.Errorf("delete discarded track: %w", err) - } - p.state.changesDetected.Store(true) - return nil +func (p *phaseMissingTracks) moveMatched(mt, ms model.MediaFile) error { + return p.ds.WithTx(func(tx model.DataStore) error { + discardedID := mt.ID + mt.ID = ms.ID + err := tx.MediaFile(p.ctx).Put(&mt) + if err != nil { + return fmt.Errorf("update matched track: %w", err) + } + err = tx.MediaFile(p.ctx).Delete(discardedID) + if err != nil { + return fmt.Errorf("delete discarded track: %w", err) + } + p.state.changesDetected.Store(true) + return nil + }) } func (p *phaseMissingTracks) finalize(err error) error { diff --git a/scanner/phase_3_refresh_albums.go b/scanner/phase_3_refresh_albums.go index ad7a68a47..f51aa8f4b 100644 --- a/scanner/phase_3_refresh_albums.go +++ b/scanner/phase_3_refresh_albums.go @@ -104,19 +104,13 @@ func (p *phaseRefreshAlbums) refreshAlbum(album *model.Album) (*model.Album, err return nil, nil } start := time.Now() - err := p.ds.WithTx(func(tx model.DataStore) error { - err := tx.Album(p.ctx).Put(album) - log.Debug(p.ctx, "Scanner: refreshing album", "album_id", album.ID, "name", album.Name, "songCount", album.SongCount, "elapsed", time.Since(start)) - if err != nil { - return fmt.Errorf("refreshing album %s: %w", album.ID, err) - } - p.refreshed.Add(1) - p.state.changesDetected.Store(true) - return nil - }, "scanner: refresh album") + err := p.ds.Album(p.ctx).Put(album) + log.Debug(p.ctx, "Scanner: refreshing album", "album_id", album.ID, "name", album.Name, "songCount", album.SongCount, "elapsed", time.Since(start), err) if err != nil { - return nil, err + return nil, fmt.Errorf("refreshing album %s: %w", album.ID, err) } + p.refreshed.Add(1) + p.state.changesDetected.Store(true) return album, nil } @@ -135,23 +129,21 @@ func (p *phaseRefreshAlbums) finalize(err error) error { log.Debug(p.ctx, "Scanner: No changes detected, skipping refreshing annotations") return nil } - return p.ds.WithTx(func(tx model.DataStore) error { - // Refresh album annotations - start := time.Now() - cnt, err := tx.Album(p.ctx).RefreshPlayCounts() - if err != nil { - return fmt.Errorf("refreshing album annotations: %w", err) - } - log.Debug(p.ctx, "Scanner: Refreshed album annotations", "albums", cnt, "elapsed", time.Since(start)) + // Refresh album annotations + start := time.Now() + cnt, err := p.ds.Album(p.ctx).RefreshPlayCounts() + if err != nil { + return fmt.Errorf("refreshing album annotations: %w", err) + } + log.Debug(p.ctx, "Scanner: Refreshed album annotations", "albums", cnt, "elapsed", time.Since(start)) - // Refresh artist annotations - start = time.Now() - cnt, err = tx.Artist(p.ctx).RefreshPlayCounts() - if err != nil { - return fmt.Errorf("refreshing artist annotations: %w", err) - } - log.Debug(p.ctx, "Scanner: Refreshed artist annotations", "artists", cnt, "elapsed", time.Since(start)) - p.state.changesDetected.Store(true) - return nil - }, "scanner: finalize phaseRefreshAlbums") + // Refresh artist annotations + start = time.Now() + cnt, err = p.ds.Artist(p.ctx).RefreshPlayCounts() + if err != nil { + return fmt.Errorf("refreshing artist annotations: %w", err) + } + log.Debug(p.ctx, "Scanner: Refreshed artist annotations", "artists", cnt, "elapsed", time.Since(start)) + p.state.changesDetected.Store(true) + return nil } diff --git a/scanner/scanner.go b/scanner/scanner.go index d698a32b4..1c08e3fb3 100644 --- a/scanner/scanner.go +++ b/scanner/scanner.go @@ -138,24 +138,22 @@ func (s *scannerImpl) runRefreshStats(ctx context.Context, state *scanState) fun log.Debug(ctx, "Scanner: No changes detected, skipping refreshing stats") return nil } - return s.ds.WithTx(func(tx model.DataStore) error { - start := time.Now() - stats, err := tx.Artist(ctx).RefreshStats() - if err != nil { - log.Error(ctx, "Scanner: Error refreshing artists stats", err) - return fmt.Errorf("refreshing artists stats: %w", err) - } - log.Debug(ctx, "Scanner: Refreshed artist stats", "stats", stats, "elapsed", time.Since(start)) + start := time.Now() + stats, err := s.ds.Artist(ctx).RefreshStats() + if err != nil { + log.Error(ctx, "Scanner: Error refreshing artists stats", err) + return fmt.Errorf("refreshing artists stats: %w", err) + } + log.Debug(ctx, "Scanner: Refreshed artist stats", "stats", stats, "elapsed", time.Since(start)) - start = time.Now() - err = tx.Tag(ctx).UpdateCounts() - if err != nil { - log.Error(ctx, "Scanner: Error updating tag counts", err) - return fmt.Errorf("updating tag counts: %w", err) - } - log.Debug(ctx, "Scanner: Updated tag counts", "elapsed", time.Since(start)) - return nil - }, "scanner: refresh stats") + start = time.Now() + err = s.ds.Tag(ctx).UpdateCounts() + if err != nil { + log.Error(ctx, "Scanner: Error updating tag counts", err) + return fmt.Errorf("updating tag counts: %w", err) + } + log.Debug(ctx, "Scanner: Updated tag counts", "elapsed", time.Since(start)) + return nil } } diff --git a/server/nativeapi/playlists.go b/server/nativeapi/playlists.go index 8921df70c..1e8e961ca 100644 --- a/server/nativeapi/playlists.go +++ b/server/nativeapi/playlists.go @@ -100,7 +100,7 @@ func deleteFromPlaylist(ds model.DataStore) http.HandlerFunc { p := req.Params(r) playlistId, _ := p.String(":playlistId") ids, _ := p.Strings("id") - err := ds.WithTx(func(tx model.DataStore) error { + err := ds.WithTxImmediate(func(tx model.DataStore) error { tracksRepo := tx.Playlist(r.Context()).Tracks(playlistId, true) return tracksRepo.Delete(ids...) }) diff --git a/server/subsonic/media_annotation.go b/server/subsonic/media_annotation.go index c9656d065..74000856f 100644 --- a/server/subsonic/media_annotation.go +++ b/server/subsonic/media_annotation.go @@ -112,7 +112,7 @@ func (api *Router) setStar(ctx context.Context, star bool, ids ...string) error return nil } event := &events.RefreshResource{} - err := api.ds.WithTx(func(tx model.DataStore) error { + err := api.ds.WithTxImmediate(func(tx model.DataStore) error { for _, id := range ids { exist, err := tx.Album(ctx).Exists(id) if err != nil { diff --git a/server/subsonic/playlists.go b/server/subsonic/playlists.go index 06b0ff58a..555c9eb48 100644 --- a/server/subsonic/playlists.go +++ b/server/subsonic/playlists.go @@ -58,7 +58,7 @@ func (api *Router) getPlaylist(ctx context.Context, id string) (*responses.Subso } func (api *Router) create(ctx context.Context, playlistId, name string, ids []string) (string, error) { - err := api.ds.WithTx(func(tx model.DataStore) error { + err := api.ds.WithTxImmediate(func(tx model.DataStore) error { owner := getUser(ctx) var pls *model.Playlist var err error diff --git a/tests/mock_data_store.go b/tests/mock_data_store.go index e5f7cd8b6..f380755e0 100644 --- a/tests/mock_data_store.go +++ b/tests/mock_data_store.go @@ -213,6 +213,10 @@ func (db *MockDataStore) WithTx(block func(tx model.DataStore) error, label ...s return block(db) } +func (db *MockDataStore) WithTxImmediate(block func(tx model.DataStore) error, label ...string) error { + return block(db) +} + func (db *MockDataStore) Resource(context.Context, any) model.ResourceRepository { return struct{ model.ResourceRepository }{} }