From 4fd47b5fa0fffdc882779ac11a78b7bbc0f492b8 Mon Sep 17 00:00:00 2001 From: Dean Herbert Date: Sat, 2 Jul 2022 12:35:29 +0900 Subject: [PATCH] Add more verbose logging to realm blocking process --- osu.Game.Tests/Database/GeneralUsageTests.cs | 8 ++++---- osu.Game.Tests/Database/RealmLiveTests.cs | 2 +- .../Database/RealmSubscriptionRegistrationTests.cs | 12 ++++++------ osu.Game/Database/EFToRealmMigrator.cs | 2 +- osu.Game/Database/RealmAccess.cs | 11 ++++++++--- osu.Game/OsuGameBase.cs | 2 +- .../Sections/DebugSettings/MemorySettings.cs | 4 ++-- 7 files changed, 23 insertions(+), 18 deletions(-) diff --git a/osu.Game.Tests/Database/GeneralUsageTests.cs b/osu.Game.Tests/Database/GeneralUsageTests.cs index 5b6f7a0a53..fd0b391d0d 100644 --- a/osu.Game.Tests/Database/GeneralUsageTests.cs +++ b/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(() => { - 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")) { } }); diff --git a/osu.Game.Tests/Database/RealmLiveTests.cs b/osu.Game.Tests/Database/RealmLiveTests.cs index fd1f564f59..a50eb22c67 100644 --- a/osu.Game.Tests/Database/RealmLiveTests.cs +++ b/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); } diff --git a/osu.Game.Tests/Database/RealmSubscriptionRegistrationTests.cs b/osu.Game.Tests/Database/RealmSubscriptionRegistrationTests.cs index c74341b5c9..4ee302bbd0 100644 --- a/osu.Game.Tests/Database/RealmSubscriptionRegistrationTests.cs +++ b/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()); diff --git a/osu.Game/Database/EFToRealmMigrator.cs b/osu.Game/Database/EFToRealmMigrator.cs index 896d111989..8f2ff600d8 100644 --- a/osu.Game/Database/EFToRealmMigrator.cs +++ b/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(() => { diff --git a/osu.Game/Database/RealmAccess.cs b/osu.Game/Database/RealmAccess.cs index 8cf9bb4a47..9c7ecd8a03 100644 --- a/osu.Game/Database/RealmAccess.cs +++ b/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. /// + /// The reason for blocking. Used for logging purposes. /// An which should be disposed to end the blocking section. - 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,7 +846,7 @@ 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; @@ -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` diff --git a/osu.Game/OsuGameBase.cs b/osu.Game/OsuGameBase.cs index 9a001c92cd..ead3eeb0dc 100644 --- a/osu.Game/OsuGameBase.cs +++ b/osu.Game/OsuGameBase.cs @@ -446,7 +446,7 @@ namespace osu.Game Scheduler.Add(() => { - realmBlocker = realm.BlockAllOperations(); + realmBlocker = realm.BlockAllOperations("migration"); readyToRun.Set(); }, false); diff --git a/osu.Game/Overlays/Settings/Sections/DebugSettings/MemorySettings.cs b/osu.Game/Overlays/Settings/Sections/DebugSettings/MemorySettings.cs index 77eede0e46..42ac4adb34 100644 --- a/osu.Game/Overlays/Settings/Sections/DebugSettings/MemorySettings.cs +++ b/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;