High-latency DB testing stuff (#22282)

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 @@ INSERT INTO player_round (players_id, rounds_id) VALUES ({players[player]}, {id}
 
         #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 @@ namespace Content.Server.Database
             "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 @@ namespace Content.Server.Database
             _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 @@ namespace Content.Server.Database
         // 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)
         {
-            if (_synchronous)
-                return RunDbCommandCoreSync(command);
+            using var _ = DbActiveOps.TrackInProgress();
 
-            return Task.Run(command);
+            if (_synchronous)
+                return await RunDbCommandCoreSync(command);
+
+            return await Task.Run(command);
         }
 
-        private Task RunDbCommand(Func<Task> command)
+        private async Task RunDbCommand(Func<Task> command)
         {
-            if (_synchronous)
-                return RunDbCommandCoreSync(command);
+            using var _ = DbActiveOps.TrackInProgress();
 
-            return Task.Run(command);
+            if (_synchronous)
+            {
+                await RunDbCommandCoreSync(command);
+                return;
+            }
+
+            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.Data;
 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 @@ namespace Content.Server.Database
         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 @@ namespace Content.Server.Database
                     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.Collections.Immutable;
 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 @@ namespace Content.Server.Database
 
         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 @@ namespace Content.Server.Database
             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 @@ namespace Content.Server.Database
             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