Merge pull request #18979 from peppy/add-realm-blocking-logging

Add more verbose logging to realm blocking process

osu.Game.Tests/Database/GeneralUsageTests.cs

@@ -30,7 +30,7 @@ namespace osu.Game.Tests.Database
         {
             RunTestWithRealm((realm, _) =>
             {
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                 {
                 }
             });
@@ -56,7 +56,7 @@ namespace osu.Game.Tests.Database
             {
                 Task writeTask;
 
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                 {
                     writeTask = realm.WriteAsync(r => r.Add(TestResources.CreateTestBeatmapSetInfo()));
                     Thread.Sleep(100);
@@ -169,7 +169,7 @@ namespace osu.Game.Tests.Database
 
                 Assert.Throws<TimeoutException>(() =>
                 {
-                    using (realm.BlockAllOperations())
+                    using (realm.BlockAllOperations("testing"))
                     {
                     }
                 });
@@ -177,7 +177,7 @@ namespace osu.Game.Tests.Database
                 stopThreadedUsage.Set();
 
                 // Ensure we can block a second time after the usage has ended.
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                 {
                 }
             });

osu.Game.Tests/Database/RealmLiveTests.cs

@@ -49,7 +49,7 @@ namespace osu.Game.Tests.Database
                 {
                     migratedStorage.DeleteDirectory(string.Empty);
 
-                    using (realm.BlockAllOperations())
+                    using (realm.BlockAllOperations("testing"))
                     {
                         storage.Migrate(migratedStorage);
                     }

osu.Game.Tests/Database/RealmSubscriptionRegistrationTests.cs

@@ -136,7 +136,7 @@ namespace osu.Game.Tests.Database
                 resolvedItems = null;
                 lastChanges = null;
 
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                     Assert.That(resolvedItems, Is.Empty);
 
                 realm.Write(r => r.Add(TestResources.CreateTestBeatmapSetInfo()));
@@ -154,7 +154,7 @@ namespace osu.Game.Tests.Database
                 testEventsArriving(false);
 
                 // And make sure even after another context loss we don't get firings.
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                     Assert.That(resolvedItems, Is.Null);
 
                 realm.Write(r => r.Add(TestResources.CreateTestBeatmapSetInfo()));
@@ -212,7 +212,7 @@ namespace osu.Game.Tests.Database
 
                 Assert.That(beatmapSetInfo, Is.Not.Null);
 
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                 {
                     // custom disposal action fired when context lost.
                     Assert.That(beatmapSetInfo, Is.Null);
@@ -226,7 +226,7 @@ namespace osu.Game.Tests.Database
 
                 Assert.That(beatmapSetInfo, Is.Null);
 
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                     Assert.That(beatmapSetInfo, Is.Null);
 
                 realm.Run(r => r.Refresh());
@@ -251,7 +251,7 @@ namespace osu.Game.Tests.Database
                 Assert.That(receivedValue, Is.Not.Null);
                 receivedValue = null;
 
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                 {
                 }
 
@@ -262,7 +262,7 @@ namespace osu.Game.Tests.Database
                 subscription.Dispose();
                 receivedValue = null;
 
-                using (realm.BlockAllOperations())
+                using (realm.BlockAllOperations("testing"))
                     Assert.That(receivedValue, Is.Null);
 
                 realm.Run(r => r.Refresh());

osu.Game/Database/EFToRealmMigrator.cs

@@ -126,7 +126,7 @@ namespace osu.Game.Database
             string backupSuffix = $"before_final_migration_{DateTimeOffset.UtcNow.ToUnixTimeSeconds()}";
 
             // required for initial backup.
-            var realmBlockOperations = realm.BlockAllOperations();
+            var realmBlockOperations = realm.BlockAllOperations("EF migration");
 
             Task.Factory.StartNew(() =>
             {

osu.Game/Database/RealmAccess.cs

@@ -780,7 +780,7 @@ namespace osu.Game.Database
 
         public void CreateBackup(string backupFilename, IDisposable? blockAllOperations = null)
         {
-            using (blockAllOperations ?? BlockAllOperations())
+            using (blockAllOperations ?? BlockAllOperations("creating backup"))
             {
                 Logger.Log($"Creating full realm database backup at {backupFilename}", LoggingTarget.Database);
 
@@ -811,9 +811,12 @@ namespace osu.Game.Database
         /// This should be used in places we need to ensure no ongoing reads/writes are occurring with realm.
         /// ie. to move the realm backing file to a new location.
         /// </remarks>
+        /// <param name="reason">The reason for blocking. Used for logging purposes.</param>
         /// <returns>An <see cref="IDisposable"/> which should be disposed to end the blocking section.</returns>
-        public IDisposable BlockAllOperations()
+        public IDisposable BlockAllOperations(string reason)
         {
+            Logger.Log($@"Attempting to block all realm operations for {reason}.", LoggingTarget.Database);
+
             if (!ThreadSafety.IsUpdateThread)
                 throw new InvalidOperationException(@$"{nameof(BlockAllOperations)} must be called from the update thread.");
 
@@ -843,10 +846,10 @@ namespace osu.Game.Database
                     updateRealm = null;
                 }
 
-                Logger.Log(@"Blocking realm operations.", LoggingTarget.Database);
+                Logger.Log(@"Lock acquired for blocking operations", LoggingTarget.Database);
 
                 const int sleep_length = 200;
-                int timeout = 5000;
+                int timeSpent = 0;
 
                 try
                 {
@@ -854,10 +857,10 @@ namespace osu.Game.Database
                     while (!Compact())
                     {
                         Thread.Sleep(sleep_length);
-                        timeout -= sleep_length;
+                        timeSpent += sleep_length;
 
-                        if (timeout < 0)
-                            throw new TimeoutException(@"Took too long to acquire lock");
+                        if (timeSpent > 5000)
+                            throw new TimeoutException($@"Realm compact failed after {timeSpent / sleep_length} attempts over {timeSpent / 1000} seconds");
                     }
                 }
                 catch (RealmException e)
@@ -867,6 +870,8 @@ namespace osu.Game.Database
                     Logger.Log($"Realm compact failed with error {e}", LoggingTarget.Database);
                 }
 
+                Logger.Log(@"Realm usage isolated via compact", LoggingTarget.Database);
+
                 // In order to ensure events arrive in the correct order, these *must* be fired post disposal of the update realm,
                 // and must be posted to the synchronization context.
                 // This is because realm may fire event callbacks between the `unregisterAllSubscriptions` and `updateRealm.Dispose`

osu.Game/OsuGameBase.cs

@@ -446,7 +446,7 @@ namespace osu.Game
 
                 Scheduler.Add(() =>
                 {
-                    realmBlocker = realm.BlockAllOperations();
+                    realmBlocker = realm.BlockAllOperations("migration");
 
                     readyToRun.Set();
                 }, false);

osu.Game/Overlays/Settings/Sections/DebugSettings/MemorySettings.cs

@@ -39,7 +39,7 @@ namespace osu.Game.Overlays.Settings.Sections.DebugSettings
                     Action = () =>
                     {
                         // Blocking operations implicitly causes a Compact().
-                        using (realm.BlockAllOperations())
+                        using (realm.BlockAllOperations("compact"))
                         {
                         }
                     }
@@ -58,7 +58,7 @@ namespace osu.Game.Overlays.Settings.Sections.DebugSettings
             {
                 try
                 {
-                    var token = realm.BlockAllOperations();
+                    var token = realm.BlockAllOperations("maintenance");
 
                     blockAction.Enabled.Value = false;