Library.db migration impovements (#13809)

* Fixes cleanup of wrong table in migration

* use dedicated context for each step

* Use prepared Context

* Fix measurement of UserData migration time

* Update logging and combine cleanup to its own stage

* fix people map not logging
migrate only readonly database

* Add id blacklisting in migration to avoid duplicated log entires

Jellyfin.Server/Migrations/Routines/MigrateLibraryDb.cs

@@ -73,21 +73,31 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
 
         var dataPath = _paths.DataPath;
         var libraryDbPath = Path.Combine(dataPath, DbFilename);
-        using var connection = new SqliteConnection($"Filename={libraryDbPath}");
+        using var connection = new SqliteConnection($"Filename={libraryDbPath};Mode=ReadOnly");
-        var migrationTotalTime = TimeSpan.Zero;
 
-        var stopwatch = new Stopwatch();
+        var fullOperationTimer = new Stopwatch();
-        stopwatch.Start();
+        fullOperationTimer.Start();
 
+        using (var operation = GetPreparedDbContext("Cleanup database"))
+        {
+            operation.JellyfinDbContext.BaseItems.ExecuteDelete();
+            operation.JellyfinDbContext.ItemValues.ExecuteDelete();
+            operation.JellyfinDbContext.UserData.ExecuteDelete();
+            operation.JellyfinDbContext.MediaStreamInfos.ExecuteDelete();
+            operation.JellyfinDbContext.Peoples.ExecuteDelete();
+            operation.JellyfinDbContext.PeopleBaseItemMap.ExecuteDelete();
+            operation.JellyfinDbContext.Chapters.ExecuteDelete();
+            operation.JellyfinDbContext.AncestorIds.ExecuteDelete();
+        }
+
+        var legacyBaseItemWithUserKeys = new Dictionary<string, BaseItemEntity>();
         connection.Open();
-        using var dbContext = _provider.CreateDbContext();
 
-        migrationTotalTime += stopwatch.Elapsed;
+        var baseItemIds = new HashSet<Guid>();
-        _logger.LogInformation("Saving UserData entries took {0}.", stopwatch.Elapsed);
+        using (var operation = GetPreparedDbContext("moving TypedBaseItem"))
-        stopwatch.Restart();
+        {
-
+            const string typedBaseItemsQuery =
-        _logger.LogInformation("Start moving TypedBaseItem.");
+            """
-        const string typedBaseItemsQuery = """
             SELECT guid, type, data, StartDate, EndDate, ChannelId, IsMovie,
             IsSeries, EpisodeTitle, IsRepeat, CommunityRating, CustomRating, IndexNumber, IsLocked, PreferredMetadataLanguage,
             PreferredMetadataCountryCode, Width, Height, DateLastRefreshed, Name, Path, PremiereDate, Overview, ParentIndexNumber,
@@ -97,37 +107,39 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
             PresentationUniqueKey, InheritedParentalRatingValue, ExternalSeriesId, Tagline, ProviderIds, Images, ProductionLocations, ExtraIds, TotalBitrate,
             ExtraType, Artists, AlbumArtists, ExternalId, SeriesPresentationUniqueKey, ShowId, OwnerId, MediaType, SortName, CleanName, UnratedType FROM TypedBaseItems
             """;
-        dbContext.BaseItems.ExecuteDelete();
+            using (new TrackedMigrationStep("Loading TypedBaseItems", _logger))
-
+            {
-        var legacyBaseItemWithUserKeys = new Dictionary<string, BaseItemEntity>();
                 foreach (SqliteDataReader dto in connection.Query(typedBaseItemsQuery))
                 {
                     var baseItem = GetItem(dto);
-            dbContext.BaseItems.Add(baseItem.BaseItem);
+                    operation.JellyfinDbContext.BaseItems.Add(baseItem.BaseItem);
+                    baseItemIds.Add(baseItem.BaseItem.Id);
                     foreach (var dataKey in baseItem.LegacyUserDataKey)
                     {
                         legacyBaseItemWithUserKeys[dataKey] = baseItem.BaseItem;
                     }
                 }
+            }
 
-        _logger.LogInformation("Try saving {0} BaseItem entries.", dbContext.BaseItems.Local.Count);
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.BaseItems.Local.Count} BaseItem entries", _logger))
-        dbContext.SaveChanges();
+            {
-        migrationTotalTime += stopwatch.Elapsed;
+                operation.JellyfinDbContext.SaveChanges();
-        _logger.LogInformation("Saving BaseItems entries took {0}.", stopwatch.Elapsed);
+            }
-        stopwatch.Restart();
+        }
 
-        _logger.LogInformation("Start moving ItemValues.");
+        using (var operation = GetPreparedDbContext("moving ItemValues"))
+        {
             // do not migrate inherited types as they are now properly mapped in search and lookup.
             const string itemValueQuery =
             """
             SELECT ItemId, Type, Value, CleanValue FROM ItemValues
                         WHERE Type <> 6 AND EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.guid = ItemValues.ItemId)
             """;
-        dbContext.ItemValues.ExecuteDelete();
 
             // EFCores local lookup sucks. We cannot use context.ItemValues.Local here because its just super slow.
             var localItems = new Dictionary<(int Type, string CleanValue), (Database.Implementations.Entities.ItemValue ItemValue, List<Guid> ItemIds)>();
-
+            using (new TrackedMigrationStep("loading ItemValues", _logger))
+            {
                 foreach (SqliteDataReader dto in connection.Query(itemValueQuery))
                 {
                     var itemId = dto.GetGuid(0);
@@ -143,8 +155,8 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
 
                 foreach (var item in localItems)
                 {
-            dbContext.ItemValues.Add(item.Value.ItemValue);
+                    operation.JellyfinDbContext.ItemValues.Add(item.Value.ItemValue);
-            dbContext.ItemValuesMap.AddRange(item.Value.ItemIds.Distinct().Select(f => new ItemValueMap()
+                    operation.JellyfinDbContext.ItemValuesMap.AddRange(item.Value.ItemIds.Distinct().Select(f => new ItemValueMap()
                     {
                         Item = null!,
                         ItemValue = null!,
@@ -152,30 +164,42 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
                         ItemValueId = item.Value.ItemValue.ItemValueId
                     }));
                 }
+            }
 
-        _logger.LogInformation("Try saving {0} ItemValues entries.", dbContext.ItemValues.Local.Count);
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.ItemValues.Local.Count} ItemValues entries", _logger))
-        dbContext.SaveChanges();
+            {
-        migrationTotalTime += stopwatch.Elapsed;
+                operation.JellyfinDbContext.SaveChanges();
-        _logger.LogInformation("Saving People ItemValues took {0}.", stopwatch.Elapsed);
+            }
-        stopwatch.Restart();
+        }
 
-        _logger.LogInformation("Start moving UserData.");
+        using (var operation = GetPreparedDbContext("moving UserData"))
-        var queryResult = connection.Query("""
+        {
+            var queryResult = connection.Query(
+            """
             SELECT key, userId, rating, played, playCount, isFavorite, playbackPositionTicks, lastPlayedDate, AudioStreamIndex, SubtitleStreamIndex FROM UserDatas
 
             WHERE EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.UserDataKey = UserDatas.key)
             """);
 
-        dbContext.UserData.ExecuteDelete();
+            using (new TrackedMigrationStep("loading UserData", _logger))
-
+            {
-        var users = dbContext.Users.AsNoTracking().ToImmutableArray();
+                var users = operation.JellyfinDbContext.Users.AsNoTracking().ToImmutableArray();
+                var userIdBlacklist = new HashSet<int>();
 
                 foreach (var entity in queryResult)
                 {
-            var userData = GetUserData(users, entity);
+                    var userData = GetUserData(users, entity, userIdBlacklist);
                     if (userData is null)
                     {
-                _logger.LogError("Was not able to migrate user data with key {0}", entity.GetString(0));
+                        var userDataId = entity.GetString(0);
+                        var internalUserId = entity.GetInt32(1);
+
+                        if (!userIdBlacklist.Contains(internalUserId))
+                        {
+                            _logger.LogError("Was not able to migrate user data with key {0} because its id {InternalId} does not match any existing user.", userDataId, internalUserId);
+                            userIdBlacklist.Add(internalUserId);
+                        }
+
                         continue;
                     }
 
@@ -186,16 +210,24 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
                     }
 
                     userData.ItemId = refItem.Id;
-            dbContext.UserData.Add(userData);
+                    operation.JellyfinDbContext.UserData.Add(userData);
                 }
 
                 users.Clear();
-        legacyBaseItemWithUserKeys.Clear();
+            }
-        _logger.LogInformation("Try saving {0} UserData entries.", dbContext.UserData.Local.Count);
-        dbContext.SaveChanges();
 
-        _logger.LogInformation("Start moving MediaStreamInfos.");
+            legacyBaseItemWithUserKeys.Clear();
-        const string mediaStreamQuery = """
+
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.UserData.Local.Count} UserData entries", _logger))
+            {
+                operation.JellyfinDbContext.SaveChanges();
+            }
+        }
+
+        using (var operation = GetPreparedDbContext("moving MediaStreamInfos"))
+        {
+            const string mediaStreamQuery =
+            """
             SELECT ItemId, StreamIndex, StreamType, Codec, Language, ChannelLayout, Profile, AspectRatio, Path,
             IsInterlaced, BitRate, Channels, SampleRate, IsDefault, IsForced, IsExternal, Height, Width,
             AverageFrameRate, RealFrameRate, Level, PixelFormat, BitDepth, IsAnamorphic, RefFrames, CodecTag,
@@ -204,31 +236,33 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
             FROM MediaStreams
             WHERE EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.guid = MediaStreams.ItemId)
             """;
-        dbContext.MediaStreamInfos.ExecuteDelete();
 
+            using (new TrackedMigrationStep("loading MediaStreamInfos", _logger))
+            {
                 foreach (SqliteDataReader dto in connection.Query(mediaStreamQuery))
                 {
-            dbContext.MediaStreamInfos.Add(GetMediaStream(dto));
+                    operation.JellyfinDbContext.MediaStreamInfos.Add(GetMediaStream(dto));
+                }
             }
 
-        _logger.LogInformation("Try saving {0} MediaStreamInfos entries.", dbContext.MediaStreamInfos.Local.Count);
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.MediaStreamInfos.Local.Count} MediaStreamInfos entries", _logger))
-        dbContext.SaveChanges();
+            {
+                operation.JellyfinDbContext.SaveChanges();
+            }
+        }
 
-        migrationTotalTime += stopwatch.Elapsed;
+        using (var operation = GetPreparedDbContext("moving People"))
-        _logger.LogInformation("Saving MediaStreamInfos entries took {0}.", stopwatch.Elapsed);
+        {
-        stopwatch.Restart();
+            const string personsQuery =
-
+            """
-        _logger.LogInformation("Start moving People.");
-        const string personsQuery = """
             SELECT ItemId, Name, Role, PersonType, SortOrder FROM People
             WHERE EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.guid = People.ItemId)
             """;
-        dbContext.Peoples.ExecuteDelete();
-        dbContext.PeopleBaseItemMap.ExecuteDelete();
 
             var peopleCache = new Dictionary<string, (People Person, List<PeopleBaseItemMap> Items)>();
-        var baseItemIds = dbContext.BaseItems.Select(b => b.Id).ToHashSet();
 
+            using (new TrackedMigrationStep("loading People", _logger))
+            {
                 foreach (SqliteDataReader reader in connection.Query(personsQuery))
                 {
                     var itemId = reader.GetGuid(0);
@@ -266,80 +300,101 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
 
                 foreach (var item in peopleCache)
                 {
-            dbContext.Peoples.Add(item.Value.Person);
+                    operation.JellyfinDbContext.Peoples.Add(item.Value.Person);
-            dbContext.PeopleBaseItemMap.AddRange(item.Value.Items.DistinctBy(e => (e.ItemId, e.PeopleId)));
+                    operation.JellyfinDbContext.PeopleBaseItemMap.AddRange(item.Value.Items.DistinctBy(e => (e.ItemId, e.PeopleId)));
                 }
 
                 peopleCache.Clear();
+            }
 
-        _logger.LogInformation("Try saving {0} People entries.", dbContext.Peoples.Local.Count);
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.Peoples.Local.Count} People entries and {operation.JellyfinDbContext.PeopleBaseItemMap.Local.Count} maps", _logger))
-        dbContext.SaveChanges();
+            {
-        migrationTotalTime += stopwatch.Elapsed;
+                operation.JellyfinDbContext.SaveChanges();
-        _logger.LogInformation("Saving People entries took {0}.", stopwatch.Elapsed);
+            }
-        stopwatch.Restart();
+        }
 
-        _logger.LogInformation("Start moving Chapters.");
+        using (var operation = GetPreparedDbContext("moving Chapters"))
-        const string chapterQuery = """
+        {
+            const string chapterQuery =
+            """
             SELECT ItemId,StartPositionTicks,Name,ImagePath,ImageDateModified,ChapterIndex from Chapters2
             WHERE EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.guid = Chapters2.ItemId)
             """;
-        dbContext.Chapters.ExecuteDelete();
 
+            using (new TrackedMigrationStep("loading Chapters", _logger))
+            {
                 foreach (SqliteDataReader dto in connection.Query(chapterQuery))
                 {
                     var chapter = GetChapter(dto);
-            dbContext.Chapters.Add(chapter);
+                    operation.JellyfinDbContext.Chapters.Add(chapter);
+                }
             }
 
-        _logger.LogInformation("Try saving {0} Chapters entries.", dbContext.Chapters.Local.Count);
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.Chapters.Local.Count} Chapters entries", _logger))
-        dbContext.SaveChanges();
+            {
-        migrationTotalTime += stopwatch.Elapsed;
+                operation.JellyfinDbContext.SaveChanges();
-        _logger.LogInformation("Saving Chapters took {0}.", stopwatch.Elapsed);
+            }
-        stopwatch.Restart();
+        }
 
-        _logger.LogInformation("Start moving AncestorIds.");
+        using (var operation = GetPreparedDbContext("moving AncestorIds"))
-        const string ancestorIdsQuery = """
+        {
+            const string ancestorIdsQuery =
+            """
             SELECT ItemId, AncestorId, AncestorIdText FROM AncestorIds
             WHERE
             EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.guid = AncestorIds.ItemId)
             AND
             EXISTS(SELECT 1 FROM TypedBaseItems WHERE TypedBaseItems.guid = AncestorIds.AncestorId)
             """;
-        dbContext.AncestorIds.ExecuteDelete();
 
+            using (new TrackedMigrationStep("loading AncestorIds", _logger))
+            {
                 foreach (SqliteDataReader dto in connection.Query(ancestorIdsQuery))
                 {
                     var ancestorId = GetAncestorId(dto);
-            dbContext.AncestorIds.Add(ancestorId);
+                    operation.JellyfinDbContext.AncestorIds.Add(ancestorId);
+                }
             }
 
-        _logger.LogInformation("Try saving {0} AncestorIds entries.", dbContext.AncestorIds.Local.Count);
+            using (new TrackedMigrationStep($"saving {operation.JellyfinDbContext.AncestorIds.Local.Count} AncestorId entries", _logger))
-
+            {
-        dbContext.SaveChanges();
+                operation.JellyfinDbContext.SaveChanges();
-        migrationTotalTime += stopwatch.Elapsed;
+            }
-        _logger.LogInformation("Saving AncestorIds took {0}.", stopwatch.Elapsed);
+        }
-        stopwatch.Restart();
 
         connection.Close();
+
         _logger.LogInformation("Migration of the Library.db done.");
-        _logger.LogInformation("Move {0} to {1}.", libraryDbPath, libraryDbPath + ".old");
+        _logger.LogInformation("Migrating Library db took {0}.", fullOperationTimer.Elapsed);
 
         SqliteConnection.ClearAllPools();
 
+        _logger.LogInformation("Move {0} to {1}.", libraryDbPath, libraryDbPath + ".old");
         File.Move(libraryDbPath, libraryDbPath + ".old", true);
 
-        _logger.LogInformation("Migrating Library db took {0}.", migrationTotalTime);
-
         _jellyfinDatabaseProvider.RunScheduledOptimisation(CancellationToken.None).ConfigureAwait(false).GetAwaiter().GetResult();
     }
 
-    private UserData? GetUserData(ImmutableArray<User> users, SqliteDataReader dto)
+    private DatabaseMigrationStep GetPreparedDbContext(string operationName)
+    {
+        var dbContext = _provider.CreateDbContext();
+        dbContext.ChangeTracker.AutoDetectChangesEnabled = false;
+        dbContext.ChangeTracker.QueryTrackingBehavior = QueryTrackingBehavior.NoTracking;
+        return new DatabaseMigrationStep(dbContext, operationName, _logger);
+    }
+
+    private UserData? GetUserData(ImmutableArray<User> users, SqliteDataReader dto, HashSet<int> userIdBlacklist)
     {
         var internalUserId = dto.GetInt32(1);
         var user = users.FirstOrDefault(e => e.InternalId == internalUserId);
 
         if (user is null)
         {
+            if (userIdBlacklist.Contains(internalUserId))
+            {
+                return null;
+            }
+
             _logger.LogError("Tried to find user with index '{Idx}' but there are only '{MaxIdx}' users.", internalUserId, users.Length);
             return null;
         }
@@ -1214,4 +1269,58 @@ internal class MigrateLibraryDb : IDatabaseMigrationRoutine
 
         return image;
     }
+
+    private class TrackedMigrationStep : IDisposable
+    {
+        private readonly string _operationName;
+        private readonly ILogger _logger;
+        private readonly Stopwatch _operationTimer;
+        private bool _disposed;
+
+        public TrackedMigrationStep(string operationName, ILogger logger)
+        {
+            _operationName = operationName;
+            _logger = logger;
+            _operationTimer = Stopwatch.StartNew();
+            logger.LogInformation("Start {OperationName}", operationName);
+        }
+
+        public bool Disposed
+        {
+            get => _disposed;
+            set => _disposed = value;
+        }
+
+        public virtual void Dispose()
+        {
+            if (Disposed)
+            {
+                return;
+            }
+
+            Disposed = true;
+            _logger.LogInformation("{OperationName} took '{Time}'", _operationName, _operationTimer.Elapsed);
+        }
+    }
+
+    private sealed class DatabaseMigrationStep : TrackedMigrationStep
+    {
+        public DatabaseMigrationStep(JellyfinDbContext jellyfinDbContext, string operationName, ILogger logger) : base(operationName, logger)
+        {
+            JellyfinDbContext = jellyfinDbContext;
+        }
+
+        public JellyfinDbContext JellyfinDbContext { get; }
+
+        public override void Dispose()
+        {
+            if (Disposed)
+            {
+                return;
+            }
+
+            JellyfinDbContext.Dispose();
+            base.Dispose();
+        }
+    }
 }