Add more performance logging to the app

app/Desktop/Main/MainWindowModel.cs

@@ -106,8 +106,10 @@ namespace DHT.Desktop.Main {
 		}
 
 		public void Dispose() {
+			WelcomeScreenModel.Dispose();
 			MainContentScreenModel?.Dispose();
 			db?.Dispose();
+			db = null;
 		}
 	}
 }

app/Desktop/Main/WelcomeScreenModel.cs

@@ -8,7 +8,7 @@ using DHT.Server.Database;
 using DHT.Utils.Models;
 
 namespace DHT.Desktop.Main {
-	sealed class WelcomeScreenModel : BaseModel {
+	sealed class WelcomeScreenModel : BaseModel, IDisposable {
 		public string Version => Program.Version;
 
 		public IDatabaseFile? Db { get; private set; }
@@ -52,8 +52,7 @@ namespace DHT.Desktop.Main {
 		}
 
 		public void CloseDatabase() {
-			Db = null;
+			Dispose();
-
 			OnPropertyChanged(nameof(Db));
 			OnPropertyChanged(nameof(HasDatabase));
 		}
@@ -65,5 +64,10 @@ namespace DHT.Desktop.Main {
 		public void Exit() {
 			window.Close();
 		}
+
+		public void Dispose() {
+			Db?.Dispose();
+			Db = null;
+		}
 	}
 }

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,11 +1,14 @@
 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 = 2;
+		internal const int Version = 3;
+
+		private static readonly Log Log = Log.ForType<Schema>();
 
 		private readonly SqliteConnection conn;
 
@@ -97,6 +100,9 @@ namespace DHT.Server.Database.Sqlite {
 					emoji_flags INTEGER NOT NULL,
 					count INTEGER NOT NULL)");
 
+			CreateMessageEditTimestampTable();
+			CreateMessageRepliedToTable();
+
 			Execute("CREATE INDEX attachments_message_ix ON attachments(message_id)");
 			Execute("CREATE INDEX embeds_message_ix ON embeds(message_id)");
 			Execute("CREATE INDEX reactions_message_ix ON reactions(message_id)");
@@ -104,12 +110,50 @@ namespace DHT.Server.Database.Sqlite {
 			Execute("INSERT INTO metadata (key, value) VALUES ('version', " + Version + ")");
 		}
 
+		private void CreateMessageEditTimestampTable() {
+			Execute(@"CREATE TABLE edit_timestamps (
+			        message_id INTEGER PRIMARY KEY NOT NULL,
+			        edit_timestamp INTEGER NOT NULL)");
+		}
+
+		private void CreateMessageRepliedToTable() {
+			Execute(@"CREATE TABLE replied_to (
+			        message_id INTEGER PRIMARY KEY NOT NULL,
+			        replied_to_id INTEGER NOT NULL)");
+		}
+
 		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) {
+				CreateMessageEditTimestampTable();
+				CreateMessageRepliedToTable();
+
+				Execute(@"INSERT INTO edit_timestamps (message_id, edit_timestamp)
+						SELECT message_id, edit_timestamp FROM messages
+						WHERE edit_timestamp IS NOT NULL");
+
+				Execute(@"INSERT INTO replied_to (message_id, replied_to_id)
+						SELECT message_id, replied_to_id FROM messages
+						WHERE replied_to_id IS NOT NULL");
+
+				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

@@ -6,6 +6,7 @@ using System.Threading.Tasks;
 using DHT.Server.Data;
 using DHT.Server.Data.Filters;
 using DHT.Utils.Collections;
+using DHT.Utils.Logging;
 using Microsoft.Data.Sqlite;
 
 namespace DHT.Server.Database.Sqlite {
@@ -25,9 +26,11 @@ namespace DHT.Server.Database.Sqlite {
 		public string Path { get; }
 		public DatabaseStatistics Statistics { get; }
 
+		private readonly Log log;
 		private readonly SqliteConnection conn;
 
 		private SqliteDatabaseFile(string path, SqliteConnection conn) {
+			this.log = Log.ForType(typeof(SqliteDatabaseFile), System.IO.Path.GetFileName(path));
 			this.conn = conn;
 			this.Path = path;
 			this.Statistics = new DatabaseStatistics();
@@ -56,6 +59,7 @@ namespace DHT.Server.Database.Sqlite {
 		}
 
 		public List<Data.Server> GetAllServers() {
+			var perf = log.Start();
 			var list = new List<Data.Server>();
 
 			using var cmd = conn.Command("SELECT id, name, type FROM servers");
@@ -69,6 +73,7 @@ namespace DHT.Server.Database.Sqlite {
 				});
 			}
 
+			perf.End();
 			return list;
 		}
 
@@ -137,6 +142,7 @@ namespace DHT.Server.Database.Sqlite {
 		}
 
 		public List<User> GetAllUsers() {
+			var perf = log.Start();
 			var list = new List<User>();
 
 			using var cmd = conn.Command("SELECT id, name, avatar_url, discriminator FROM users");
@@ -151,10 +157,20 @@ namespace DHT.Server.Database.Sqlite {
 				});
 			}
 
+			perf.End();
 			return list;
 		}
 
 		public void AddMessages(Message[] messages) {
+			static SqliteCommand DeleteByMessageId(SqliteConnection conn, string tableName) {
+				return conn.Delete(tableName, ("message_id", SqliteType.Integer));
+			}
+
+			static void ExecuteDeleteByMessageId(SqliteCommand cmd, object id) {
+				cmd.Set(":message_id", id);
+				cmd.ExecuteNonQuery();
+			}
+
 			using var tx = conn.BeginTransaction();
 
 			using var messageCmd = conn.Upsert("messages", new[] {
@@ -162,14 +178,25 @@ namespace DHT.Server.Database.Sqlite {
 				("sender_id", SqliteType.Integer),
 				("channel_id", SqliteType.Integer),
 				("text", SqliteType.Text),
-				("timestamp", SqliteType.Integer),
+				("timestamp", SqliteType.Integer)
-				("edit_timestamp", SqliteType.Integer),
-				("replied_to_id", SqliteType.Integer)
 			});
 
-			using var deleteAttachmentsCmd = conn.Delete("attachments", ("message_id", SqliteType.Integer));
+			using var deleteEditTimestampCmd = DeleteByMessageId(conn, "edit_timestamps");
-			using var deleteEmbedsCmd = conn.Delete("embeds", ("message_id", SqliteType.Integer));
+			using var deleteRepliedToCmd = DeleteByMessageId(conn, "replied_to");
-			using var deleteReactionsCmd = conn.Delete("reactions", ("message_id", SqliteType.Integer));
+
+			using var deleteAttachmentsCmd = DeleteByMessageId(conn, "attachments");
+			using var deleteEmbedsCmd = DeleteByMessageId(conn, "embeds");
+			using var deleteReactionsCmd = DeleteByMessageId(conn, "reactions");
+
+			using var editTimestampCmd = conn.Insert("edit_timestamps", new [] {
+				("message_id", SqliteType.Integer),
+				("edit_timestamp", SqliteType.Integer)
+			});
+
+			using var repliedToCmd = conn.Insert("replied_to", new [] {
+				("message_id", SqliteType.Integer),
+				("replied_to_id", SqliteType.Integer)
+			});
 
 			using var attachmentCmd = conn.Insert("attachments", new[] {
 				("message_id", SqliteType.Integer),
@@ -201,18 +228,26 @@ namespace DHT.Server.Database.Sqlite {
 				messageCmd.Set(":channel_id", message.Channel);
 				messageCmd.Set(":text", message.Text);
 				messageCmd.Set(":timestamp", message.Timestamp);
-				messageCmd.Set(":edit_timestamp", message.EditTimestamp);
-				messageCmd.Set(":replied_to_id", message.RepliedToId);
 				messageCmd.ExecuteNonQuery();
 
-				deleteAttachmentsCmd.Set(":message_id", messageId);
+				ExecuteDeleteByMessageId(deleteEditTimestampCmd, messageId);
-				deleteAttachmentsCmd.ExecuteNonQuery();
+				ExecuteDeleteByMessageId(deleteRepliedToCmd, messageId);
 
-				deleteEmbedsCmd.Set(":message_id", messageId);
+				ExecuteDeleteByMessageId(deleteAttachmentsCmd, messageId);
-				deleteEmbedsCmd.ExecuteNonQuery();
+				ExecuteDeleteByMessageId(deleteEmbedsCmd, messageId);
+				ExecuteDeleteByMessageId(deleteReactionsCmd, messageId);
 
-				deleteReactionsCmd.Set(":message_id", messageId);
+				if (message.EditTimestamp is {} timestamp) {
-				deleteReactionsCmd.ExecuteNonQuery();
+					editTimestampCmd.Set(":message_id", messageId);
+					editTimestampCmd.Set(":edit_timestamp", timestamp);
+					editTimestampCmd.ExecuteNonQuery();
+				}
+
+				if (message.RepliedToId is {} repliedToId) {
+					repliedToCmd.Set(":message_id", messageId);
+					repliedToCmd.Set(":replied_to_id", repliedToId);
+					repliedToCmd.ExecuteNonQuery();
+				}
 
 				if (!message.Attachments.IsEmpty) {
 					foreach (var attachment in message.Attachments) {
@@ -258,13 +293,18 @@ namespace DHT.Server.Database.Sqlite {
 		}
 
 		public List<Message> GetMessages(MessageFilter? filter = null) {
+			var perf = log.Start();
+			var list = new List<Message>();
+
 			var attachments = GetAllAttachments();
 			var embeds = GetAllEmbeds();
 			var reactions = GetAllReactions();
 
-			var list = new List<Message>();
+			using var cmd = conn.Command(@"
-
+SELECT m.message_id, m.sender_id, m.channel_id, m.text, m.timestamp, et.edit_timestamp, rt.replied_to_id
-			using var cmd = conn.Command("SELECT message_id, sender_id, channel_id, text, timestamp, edit_timestamp, replied_to_id FROM messages" + filter.GenerateWhereClause());
+FROM messages m
+LEFT JOIN edit_timestamps et ON m.message_id = et.message_id
+LEFT JOIN replied_to rt ON m.message_id = rt.message_id" + filter.GenerateWhereClause("m"));
 			using var reader = cmd.ExecuteReader();
 
 			while (reader.Read()) {
@@ -284,6 +324,7 @@ namespace DHT.Server.Database.Sqlite {
 				});
 			}
 
+			perf.End();
 			return list;
 		}
 
@@ -293,6 +334,8 @@ namespace DHT.Server.Database.Sqlite {
 				return;
 			}
 
+			var perf = log.Start();
+
 			// Rider is being stupid...
 			StringBuilder build = new StringBuilder()
 			                      .Append("DELETE ")
@@ -303,6 +346,7 @@ namespace DHT.Server.Database.Sqlite {
 			cmd.ExecuteNonQuery();
 
 			UpdateMessageStatistics();
+			perf.End();
 		}
 
 		private MultiDictionary<ulong, Attachment> GetAllAttachments() {

app/Server/Database/Sqlite/SqliteMessageFilter.cs

@@ -4,31 +4,35 @@ using DHT.Server.Data.Filters;
 
 namespace DHT.Server.Database.Sqlite {
 	static class SqliteMessageFilter {
-		public static string GenerateWhereClause(this MessageFilter? filter, bool invert = false) {
+		public static string GenerateWhereClause(this MessageFilter? filter, string? tableAlias = null, bool invert = false) {
 			if (filter == null) {
 				return "";
 			}
 
+			if (tableAlias != null) {
+				tableAlias += ".";
+			}
+
 			List<string> conditions = new();
 
 			if (filter.StartDate != null) {
-				conditions.Add("timestamp >= " + new DateTimeOffset(filter.StartDate.Value).ToUnixTimeMilliseconds());
+				conditions.Add(tableAlias + "timestamp >= " + new DateTimeOffset(filter.StartDate.Value).ToUnixTimeMilliseconds());
 			}
 
 			if (filter.EndDate != null) {
-				conditions.Add("timestamp <= " + new DateTimeOffset(filter.EndDate.Value).ToUnixTimeMilliseconds());
+				conditions.Add(tableAlias + "timestamp <= " + new DateTimeOffset(filter.EndDate.Value).ToUnixTimeMilliseconds());
 			}
 
 			if (filter.ChannelIds != null) {
-				conditions.Add("channel_id IN (" + string.Join(",", filter.ChannelIds) + ")");
+				conditions.Add(tableAlias + "channel_id IN (" + string.Join(",", filter.ChannelIds) + ")");
 			}
 
 			if (filter.UserIds != null) {
-				conditions.Add("sender_id IN (" + string.Join(",", filter.UserIds) + ")");
+				conditions.Add(tableAlias + "sender_id IN (" + string.Join(",", filter.UserIds) + ")");
 			}
 
 			if (filter.MessageIds != null) {
-				conditions.Add("message_id IN (" + string.Join(",", filter.MessageIds) + ")");
+				conditions.Add(tableAlias + "message_id IN (" + string.Join(",", filter.MessageIds) + ")");
 			}
 
 			if (conditions.Count == 0) {

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 = "") {
+		public Perf Start(string? context = null, [CallerMemberName] string callerMemberName = "") {
-			return Perf.Start(this, 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 = "") {
+		internal static Perf Start(Log log, string? context = null, [CallerMemberName] string callerMemberName = "") {
-			return new Perf(log, 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.context = context;
-			this.stopwatch.Start();
+			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.");
 			}
 		}
 	}