High-latency DB testing stuff (space-wizards#22282)

Content.IntegrationTests/Tests/Preferences/ServerDbSqliteTests.cs

@@ -8,9 +8,11 @@
 using Microsoft.EntityFrameworkCore;
 using Robust.Shared.Configuration;
 using Robust.Shared.Enums;
+using Robust.Shared.Log;
 using Robust.Shared.Maths;
 using Robust.Shared.Network;
 using Robust.Shared.Prototypes;
+using Robust.UnitTesting;
 
 namespace Content.IntegrationTests.Tests.Preferences
 {
@@ -64,20 +66,22 @@ private static HumanoidCharacterProfile CharlieCharlieson()
             );
         }
 
-        private static ServerDbSqlite GetDb(IConfigurationManager cfgManager)
+        private static ServerDbSqlite GetDb(RobustIntegrationTest.ServerIntegrationInstance server)
         {
+            var cfg = server.ResolveDependency<IConfigurationManager>();
+            var opsLog = server.ResolveDependency<ILogManager>().GetSawmill("db.ops");
             var builder = new DbContextOptionsBuilder<SqliteServerDbContext>();
             var conn = new SqliteConnection("Data Source=:memory:");
             conn.Open();
             builder.UseSqlite(conn);
-            return new ServerDbSqlite(() => builder.Options, true, cfgManager, true);
+            return new ServerDbSqlite(() => builder.Options, true, cfg, true, opsLog);
         }
 
         [Test]
         public async Task TestUserDoesNotExist()
         {
             var pair = await PoolManager.GetServerClient();
-            var db = GetDb(pair.Server.ResolveDependency<IConfigurationManager>());
+            var db = GetDb(pair.Server);
             // Database should be empty so a new GUID should do it.
             Assert.Null(await db.GetPlayerPreferencesAsync(NewUserId()));
 
@@ -88,7 +92,7 @@ public async Task TestUserDoesNotExist()
         public async Task TestInitPrefs()
         {
             var pair = await PoolManager.GetServerClient();
-            var db = GetDb(pair.Server.ResolveDependency<IConfigurationManager>());
+            var db = GetDb(pair.Server);
             var username = new NetUserId(new Guid("640bd619-fc8d-4fe2-bf3c-4a5fb17d6ddd"));
             const int slot = 0;
             var originalProfile = CharlieCharlieson();
@@ -103,7 +107,7 @@ public async Task TestDeleteCharacter()
         {
             var pair = await PoolManager.GetServerClient();
             var server = pair.Server;
-            var db = GetDb(server.ResolveDependency<IConfigurationManager>());
+            var db = GetDb(server);
             var username = new NetUserId(new Guid("640bd619-fc8d-4fe2-bf3c-4a5fb17d6ddd"));
             await db.InitPrefsAsync(username, new HumanoidCharacterProfile());
             await db.SaveCharacterSlotAsync(username, CharlieCharlieson(), 1);

Content.Server/Database/ServerDbBase.cs

@@ -1,6 +1,7 @@
 using System.Collections.Immutable;
 using System.Linq;
 using System.Net;
+using System.Runtime.CompilerServices;
 using System.Text.Json;
 using System.Threading;
 using System.Threading.Tasks;
@@ -20,6 +21,14 @@ namespace Content.Server.Database
 {
     public abstract class ServerDbBase
     {
+        private readonly ISawmill _opsLog;
+
+        /// <param name="opsLog">Sawmill to trace log database operations to.</param>
+        public ServerDbBase(ISawmill opsLog)
+        {
+            _opsLog = opsLog;
+        }
+
         #region Preferences
         public async Task<PlayerPreferences?> GetPlayerPreferencesAsync(NetUserId userId)
         {
@@ -1375,7 +1384,12 @@ protected async Task<List<ServerRoleBanNote>> GetGroupedServerRoleBansAsNotesFor
 
         #endregion
 
-        protected abstract Task<DbGuard> GetDb();
+        protected abstract Task<DbGuard> GetDb([CallerMemberName] string? name = null);
+
+        protected void LogDbOp(string? name)
+        {
+            _opsLog.Verbose($"Running DB operation: {name ?? "unknown"}");
+        }
 
         protected abstract class DbGuard : IAsyncDisposable
         {

Content.Server/Database/ServerDbManager.cs

@@ -289,6 +289,10 @@ public sealed class ServerDbManager : IServerDbManager
             "db_write_ops",
             "Amount of write operations processed by the database manager.");
 
+        public static readonly Gauge DbActiveOps = Metrics.CreateGauge(
+            "db_executing_ops",
+            "Amount of active database operations. Note that some operations may be waiting for a database connection.");
+
         [Dependency] private readonly IConfigurationManager _cfg = default!;
         [Dependency] private readonly IResourceManager _res = default!;
         [Dependency] private readonly ILogManager _logMgr = default!;
@@ -313,15 +317,16 @@ public void Init()
             _synchronous = _cfg.GetCVar(CCVars.DatabaseSynchronous);
 
             var engine = _cfg.GetCVar(CCVars.DatabaseEngine).ToLower();
+            var opsLog = _logMgr.GetSawmill("db.op");
             switch (engine)
             {
                 case "sqlite":
                     SetupSqlite(out var contextFunc, out var inMemory);
-                    _db = new ServerDbSqlite(contextFunc, inMemory, _cfg, _synchronous);
+                    _db = new ServerDbSqlite(contextFunc, inMemory, _cfg, _synchronous, opsLog);
                     break;
                 case "postgres":
                     var pgOptions = CreatePostgresOptions();
-                    _db = new ServerDbPostgres(pgOptions, _cfg);
+                    _db = new ServerDbPostgres(pgOptions, _cfg, opsLog);
                     break;
                 default:
                     throw new InvalidDataException($"Unknown database engine {engine}.");
@@ -856,20 +861,27 @@ public Task MarkMessageAsSeen(int id)
         // as that would make things very random and undeterministic.
         // That only works on SQLite though, since SQLite is internally synchronous anyways.
 
-        private Task<T> RunDbCommand<T>(Func<Task<T>> command)
+        private async Task<T> RunDbCommand<T>(Func<Task<T>> command)
         {
+            using var _ = DbActiveOps.TrackInProgress();
+
             if (_synchronous)
-                return RunDbCommandCoreSync(command);
+                return await RunDbCommandCoreSync(command);
 
-            return Task.Run(command);
+            return await Task.Run(command);
         }
 
-        private Task RunDbCommand(Func<Task> command)
+        private async Task RunDbCommand(Func<Task> command)
         {
+            using var _ = DbActiveOps.TrackInProgress();
+
             if (_synchronous)
-                return RunDbCommandCoreSync(command);
+            {
+                await RunDbCommandCoreSync(command);
+                return;
+            }
 
-            return Task.Run(command);
+            await Task.Run(command);
         }
 
         private static T RunDbCommandCoreSync<T>(Func<T> command) where T : IAsyncResult

Content.Server/Database/ServerDbPostgres.cs

@@ -3,6 +3,7 @@
 using System.Diagnostics.CodeAnalysis;
 using System.Linq;
 using System.Net;
+using System.Runtime.CompilerServices;
 using System.Threading;
 using System.Threading.Tasks;
 using Content.Server.Administration.Logs;
@@ -20,7 +21,13 @@ public sealed class ServerDbPostgres : ServerDbBase
         private readonly SemaphoreSlim _prefsSemaphore;
         private readonly Task _dbReadyTask;
 
-        public ServerDbPostgres(DbContextOptions<PostgresServerDbContext> options, IConfigurationManager cfg)
+        private int _msLag;
+
+        public ServerDbPostgres(
+            DbContextOptions<PostgresServerDbContext> options,
+            IConfigurationManager cfg,
+            ISawmill opsLog)
+            : base(opsLog)
         {
             var concurrency = cfg.GetCVar(CCVars.DatabasePgConcurrency);
 
@@ -39,6 +46,8 @@ public ServerDbPostgres(DbContextOptions<PostgresServerDbContext> options, IConf
                     await ctx.DisposeAsync();
                 }
             });
+
+            cfg.OnValueChanged(CCVars.DatabasePgFakeLag, v => _msLag = v, true);
         }
 
         #region Ban
@@ -522,17 +531,22 @@ WHERE to_tsvector('english'::regconfig, a.message) @@ websearch_to_tsquery('engl
             return db.AdminLog;
         }
 
-        private async Task<DbGuardImpl> GetDbImpl()
+        private async Task<DbGuardImpl> GetDbImpl([CallerMemberName] string? name = null)
         {
+            LogDbOp(name);
+
             await _dbReadyTask;
             await _prefsSemaphore.WaitAsync();
 
+            if (_msLag > 0)
+                await Task.Delay(_msLag);
+
             return new DbGuardImpl(this, new PostgresServerDbContext(_options));
         }
 
-        protected override async Task<DbGuard> GetDb()
+        protected override async Task<DbGuard> GetDb([CallerMemberName] string? name = null)
         {
-            return await GetDbImpl();
+            return await GetDbImpl(name);
         }
 
         private sealed class DbGuardImpl : DbGuard

Content.Server/Database/ServerDbSqlite.cs

@@ -2,6 +2,7 @@
 using System.Diagnostics.CodeAnalysis;
 using System.Linq;
 using System.Net;
+using System.Runtime.CompilerServices;
 using System.Threading;
 using System.Threading.Tasks;
 using Content.Server.Administration.Logs;
@@ -28,9 +29,13 @@ public sealed class ServerDbSqlite : ServerDbBase
 
         private int _msDelay;
 
-        public ServerDbSqlite(Func<DbContextOptions<SqliteServerDbContext>> options,
+        public ServerDbSqlite(
+            Func<DbContextOptions<SqliteServerDbContext>> options,
             bool inMemory,
-            IConfigurationManager cfg, bool synchronous)
+            IConfigurationManager cfg,
+            bool synchronous,
+            ISawmill opsLog)
+            : base(opsLog)
         {
             _options = options;
 
@@ -541,8 +546,9 @@ public override async Task<int> AddAdminMessage(AdminMessage message)
             return await base.AddAdminMessage(message);
         }
 
-        private async Task<DbGuardImpl> GetDbImpl()
+        private async Task<DbGuardImpl> GetDbImpl([CallerMemberName] string? name = null)
         {
+            LogDbOp(name);
             await _dbReadyTask;
             if (_msDelay > 0)
                 await Task.Delay(_msDelay);
@@ -554,9 +560,9 @@ private async Task<DbGuardImpl> GetDbImpl()
             return new DbGuardImpl(this, dbContext);
         }
 
-        protected override async Task<DbGuard> GetDb()
+        protected override async Task<DbGuard> GetDb([CallerMemberName] string? name = null)
         {
-            return await GetDbImpl().ConfigureAwait(false);
+            return await GetDbImpl(name).ConfigureAwait(false);
         }
 
         private sealed class DbGuardImpl : DbGuard

Content.Shared/CCVar/CCVars.cs

@@ -540,6 +540,16 @@ public static readonly CVarDef<bool>
         public static readonly CVarDef<int> DatabasePgConcurrency =
             CVarDef.Create("database.pg_concurrency", 8, CVar.SERVERONLY);
 
+        /// <summary>
+        /// Milliseconds to asynchronously delay all PostgreSQL database operations with.
+        /// </summary>
+        /// <remarks>
+        /// This is intended for performance testing. It works different from <see cref="DatabaseSqliteDelay"/>,
+        /// as the lag is applied after acquiring the database lock.
+        /// </remarks>
+        public static readonly CVarDef<int> DatabasePgFakeLag =
+            CVarDef.Create("database.pg_fake_lag", 0, CVar.SERVERONLY);
+
         // Basically only exists for integration tests to avoid race conditions.
         public static readonly CVarDef<bool> DatabaseSynchronous =
             CVarDef.Create("database.sync", false, CVar.SERVERONLY);