diff --git a/Content.IntegrationTests/Tests/Preferences/ServerDbSqliteTests.cs b/Content.IntegrationTests/Tests/Preferences/ServerDbSqliteTests.cs index 35aedf43f26996..1bc2885e97be42 100644 --- a/Content.IntegrationTests/Tests/Preferences/ServerDbSqliteTests.cs +++ b/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(); + var opsLog = server.ResolveDependency().GetSawmill("db.ops"); var builder = new DbContextOptionsBuilder(); 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()); + 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()); + 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()); + 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); diff --git a/Content.Server/Database/ServerDbBase.cs b/Content.Server/Database/ServerDbBase.cs index a4dbec5f19f6d0..1edf9293211ec9 100644 --- a/Content.Server/Database/ServerDbBase.cs +++ b/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; + + /// Sawmill to trace log database operations to. + public ServerDbBase(ISawmill opsLog) + { + _opsLog = opsLog; + } + #region Preferences public async Task GetPlayerPreferencesAsync(NetUserId userId) { @@ -1375,7 +1384,12 @@ protected async Task> GetGroupedServerRoleBansAsNotesFor #endregion - protected abstract Task GetDb(); + protected abstract Task GetDb([CallerMemberName] string? name = null); + + protected void LogDbOp(string? name) + { + _opsLog.Verbose($"Running DB operation: {name ?? "unknown"}"); + } protected abstract class DbGuard : IAsyncDisposable { diff --git a/Content.Server/Database/ServerDbManager.cs b/Content.Server/Database/ServerDbManager.cs index 5928475a4ba374..7deeeb8e95acb2 100644 --- a/Content.Server/Database/ServerDbManager.cs +++ b/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 RunDbCommand(Func> command) + private async Task RunDbCommand(Func> 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 command) + private async Task RunDbCommand(Func 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(Func command) where T : IAsyncResult diff --git a/Content.Server/Database/ServerDbPostgres.cs b/Content.Server/Database/ServerDbPostgres.cs index 555226092d8b65..4af3c6e2ede916 100644 --- a/Content.Server/Database/ServerDbPostgres.cs +++ b/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 options, IConfigurationManager cfg) + private int _msLag; + + public ServerDbPostgres( + DbContextOptions options, + IConfigurationManager cfg, + ISawmill opsLog) + : base(opsLog) { var concurrency = cfg.GetCVar(CCVars.DatabasePgConcurrency); @@ -39,6 +46,8 @@ public ServerDbPostgres(DbContextOptions 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 GetDbImpl() + private async Task 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 GetDb() + protected override async Task GetDb([CallerMemberName] string? name = null) { - return await GetDbImpl(); + return await GetDbImpl(name); } private sealed class DbGuardImpl : DbGuard diff --git a/Content.Server/Database/ServerDbSqlite.cs b/Content.Server/Database/ServerDbSqlite.cs index 594ed2e37c962d..1bcea6b1703cbf 100644 --- a/Content.Server/Database/ServerDbSqlite.cs +++ b/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> options, + public ServerDbSqlite( + Func> 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 AddAdminMessage(AdminMessage message) return await base.AddAdminMessage(message); } - private async Task GetDbImpl() + private async Task GetDbImpl([CallerMemberName] string? name = null) { + LogDbOp(name); await _dbReadyTask; if (_msDelay > 0) await Task.Delay(_msDelay); @@ -554,9 +560,9 @@ private async Task GetDbImpl() return new DbGuardImpl(this, dbContext); } - protected override async Task GetDb() + protected override async Task GetDb([CallerMemberName] string? name = null) { - return await GetDbImpl().ConfigureAwait(false); + return await GetDbImpl(name).ConfigureAwait(false); } private sealed class DbGuardImpl : DbGuard diff --git a/Content.Shared/CCVar/CCVars.cs b/Content.Shared/CCVar/CCVars.cs index f2ee22e0ead484..32855652c99c11 100644 --- a/Content.Shared/CCVar/CCVars.cs +++ b/Content.Shared/CCVar/CCVars.cs @@ -540,6 +540,16 @@ public static readonly CVarDef public static readonly CVarDef DatabasePgConcurrency = CVarDef.Create("database.pg_concurrency", 8, CVar.SERVERONLY); + /// + /// Milliseconds to asynchronously delay all PostgreSQL database operations with. + /// + /// + /// This is intended for performance testing. It works different from , + /// as the lag is applied after acquiring the database lock. + /// + public static readonly CVarDef DatabasePgFakeLag = + CVarDef.Create("database.pg_fake_lag", 0, CVar.SERVERONLY); + // Basically only exists for integration tests to avoid race conditions. public static readonly CVarDef DatabaseSynchronous = CVarDef.Create("database.sync", false, CVar.SERVERONLY);