Add more performance logging to the app

app/Server/Database/Export/ViewerJsonExport.cs

@@ -31,18 +31,21 @@ namespace DHT.Server.Database.Export {
 				}
 			}
 
-			var opts = new JsonSerializerOptions();
-			opts.Converters.Add(new ViewerJsonSnowflakeSerializer());
-
 			var users = GenerateUserList(db, includedUserIds, out var userindex, out var userIndices);
 			var servers = GenerateServerList(db, includedServerIds, out var serverindex);
 			var channels = GenerateChannelList(includedChannels, serverindex);
 
+			perf.Step("Collect database data");
+
+			var opts = new JsonSerializerOptions();
+			opts.Converters.Add(new ViewerJsonSnowflakeSerializer());
+
 			var json = JsonSerializer.Serialize(new {
 				meta = new { users, userindex, servers, channels },
 				data = GenerateMessageList(includedMessages, userIndices)
 			}, opts);
 
+			perf.Step("Serialize to JSON");
 			perf.End();
 			return json;
 		}

app/Server/Database/Sqlite/Schema.cs

@@ -1,12 +1,15 @@
 using System;
 using System.Threading.Tasks;
 using DHT.Server.Database.Exceptions;
+using DHT.Utils.Logging;
 using Microsoft.Data.Sqlite;
 
 namespace DHT.Server.Database.Sqlite {
 	sealed class Schema {
 		internal const int Version = 3;
 
+		private static readonly Log Log = Log.ForType<Schema>();
+
 		private readonly SqliteConnection conn;
 
 		public Schema(SqliteConnection conn) {
@@ -120,10 +123,13 @@ namespace DHT.Server.Database.Sqlite {
 		}
 
 		private void UpgradeSchemas(int dbVersion) {
+			var perf = Log.Start("from version " + dbVersion);
+
 			Execute("UPDATE metadata SET value = " + Version + " WHERE key = 'version'");
 
 			if (dbVersion <= 1) {
 				Execute("ALTER TABLE channels ADD parent_id INTEGER");
+				perf.Step("Upgrade to version 2");
 			}
 
 			if (dbVersion <= 2) {
@@ -140,8 +146,14 @@ namespace DHT.Server.Database.Sqlite {
 
 				Execute("ALTER TABLE messages DROP COLUMN replied_to_id");
 				Execute("ALTER TABLE messages DROP COLUMN edit_timestamp");
+
+				perf.Step("Upgrade to version 3");
+
 				Execute("VACUUM");
+				perf.Step("Vacuum");
 			}
+
+			perf.End();
 		}
 	}
 }

app/Server/Database/Sqlite/SqliteDatabaseFile.cs

@@ -334,6 +334,8 @@ LEFT JOIN replied_to rt ON m.message_id = rt.message_id" + filter.GenerateWhereC
 				return;
 			}
 
+			var perf = log.Start();
+
 			// Rider is being stupid...
 			StringBuilder build = new StringBuilder()
 			                      .Append("DELETE ")
@@ -344,6 +346,7 @@ LEFT JOIN replied_to rt ON m.message_id = rt.message_id" + filter.GenerateWhereC
 			cmd.ExecuteNonQuery();
 
 			UpdateMessageStatistics();
+			perf.End();
 		}
 
 		private MultiDictionary<ulong, Attachment> GetAllAttachments() {

app/Utils/Logging/Log.cs

@@ -87,8 +87,8 @@ namespace DHT.Utils.Logging {
 			LogLevel(ConsoleColor.Red, "ERROR", e.ToString());
 		}
 
-		public Perf Start([CallerMemberName] string callerMemberName = "") {
-			return Perf.Start(this, callerMemberName);
+		public Perf Start(string? context = null, [CallerMemberName] string callerMemberName = "") {
+			return Perf.Start(this, context, callerMemberName);
 		}
 	}
 }

app/Utils/Logging/Perf.cs

@@ -3,26 +3,44 @@ using System.Runtime.CompilerServices;
 
 namespace DHT.Utils.Logging {
 	public sealed class Perf {
-		internal static Perf Start(Log log, [CallerMemberName] string callerMemberName = "") {
-			return new Perf(log, callerMemberName);
+		internal static Perf Start(Log log, string? context = null, [CallerMemberName] string callerMemberName = "") {
+			return new Perf(log, callerMemberName, context);
 		}
 
 		private readonly Log log;
 		private readonly string method;
-		private readonly Stopwatch stopwatch;
+		private readonly string? context;
+		private readonly Stopwatch totalStopwatch;
+		private readonly Stopwatch stepStopwatch;
 
-		private Perf(Log log, string method) {
+		private Perf(Log log, string method, string? context) {
 			this.log = log;
 			this.method = method;
-			this.stopwatch = new Stopwatch();
-			this.stopwatch.Start();
+			this.context = context;
+			this.totalStopwatch = new Stopwatch();
+			this.totalStopwatch.Start();
+			this.stepStopwatch = new Stopwatch();
+			this.stepStopwatch.Start();
+		}
+
+		public void Step(string name) {
+			stepStopwatch.Stop();
+
+			if (Log.IsDebugEnabled) {
+				string ctx = context == null ? string.Empty : " " + context;
+				log.Debug($"Finished step '{name}' of '{method}'{ctx} in {stepStopwatch.ElapsedMilliseconds} ms.");
+			}
+
+			stepStopwatch.Restart();
 		}
 
 		public void End() {
-			stopwatch.Stop();
+			totalStopwatch.Stop();
+			stepStopwatch.Stop();
 
 			if (Log.IsDebugEnabled) {
-				log.Debug($"Finished '{method}' in {stopwatch.ElapsedMilliseconds} ms.");
+				string ctx = context == null ? string.Empty : " " + context;
+				log.Debug($"Finished '{method}'{ctx} in {totalStopwatch.ElapsedMilliseconds} ms.");
 			}
 		}
 	}