From 6051e4930760bee616b08f608c36230f078acad1 Mon Sep 17 00:00:00 2001 From: Jon Kazama Date: Thu, 14 May 2026 23:33:56 +0200 Subject: [PATCH] chore(profiling): instrument plugin-load hot paths (v1.4.9 R3) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bump AutoTranslate-warmup and FilterAllTabs log-level from Debug to Information so the xllog tail surfaces them without a Debug filter. Wrap MessageStore.Connect and MessageStore.Migrate in Stopwatches so the SQLite open and migration-chain costs are visible too. Sub-Task 3.4 Befund on v1.4.8-baseline (4 reloads, medians): - MessageStore.Connect: 50.5 ms - MessageStore.Migrate: 2 ms - MessageManager.FilterAllTabs: 68.5 ms - AutoTranslate warmup: 108 ms - UiBuilder HITCH: 108.9 ms Outcome D — none of the three dominates the 200 ms threshold. The ChatTwo "300 ms" comment for AutoTranslate is falsified at ~108 ms; SQLite is not the bottleneck (52.5 ms total); FilterAllTabs runs on the worker thread and only competes for CPU slots. The HITCH is left unexplained by these probes, which keeps Hypothesis c (multi-window WindowSystem.Draw initial pass) as the main R2 suspect to be validated by the R1 lazy-window refactor. Logs stay in as belt-and-suspenders for future plugin-load regressions. --- HellionChat/MessageManager.cs | 5 ++++- HellionChat/MessageStore.cs | 15 +++++++++++++++ HellionChat/Util/AutoTranslate.cs | 7 ++++++- 3 files changed, 25 insertions(+), 2 deletions(-) diff --git a/HellionChat/MessageManager.cs b/HellionChat/MessageManager.cs index 99a9bf1..64f3bd1 100644 --- a/HellionChat/MessageManager.cs +++ b/HellionChat/MessageManager.cs @@ -206,7 +206,10 @@ internal class MessageManager : IAsyncDisposable Plugin.LogProxy.Error(ex, "Error in FilterAllTabs"); } - Plugin.LogProxy.Debug($"FilterAllTabs took {stopwatch.ElapsedMilliseconds}ms"); + // v1.4.9 R3 profiling: Information so the xllog tail surfaces this + // without a Debug filter. Belt-and-suspenders for future plugin-load + // regressions; remains in place after Sub-Task 3.4 Befund. + Plugin.LogProxy.Information($"FilterAllTabs took {stopwatch.ElapsedMilliseconds}ms"); }); } diff --git a/HellionChat/MessageStore.cs b/HellionChat/MessageStore.cs index f3acb4a..dd5f51f 100644 --- a/HellionChat/MessageStore.cs +++ b/HellionChat/MessageStore.cs @@ -237,14 +237,26 @@ internal class MessageStore : IDisposable private SqliteConnection Connect() { + // v1.4.9 R3 profiling: trace cost of SQLite open + pragma-apply. Paired + // with the Migrate-Stopwatch below — Connect alone is the cheap half + // (Open + a handful of PRAGMAs); the expensive half typically lives in + // Migrate, especially on a large DB after a schema bump. + var connectSw = System.Diagnostics.Stopwatch.StartNew(); var conn = new SqliteConnection(BuildConnectionString(DbPath)); conn.Open(); ApplyPragmas(conn); + connectSw.Stop(); + _logger.Information($"MessageStore.Connect took {connectSw.ElapsedMilliseconds}ms"); return conn; } private void Migrate() { + // v1.4.9 R3 profiling: trace cost of the schema-migration chain. On a + // large DB after a fresh schema bump this is the dominant SQLite cost + // at plugin-load, not Connect. + var migrateSw = System.Diagnostics.Stopwatch.StartNew(); + using var cmd = Connection.CreateCommand(); cmd.CommandText = "PRAGMA user_version;"; var userVersion = Convert.ToInt32(cmd.ExecuteScalar()); @@ -276,6 +288,9 @@ internal class MessageStore : IDisposable foreach (var migration in migrationsToDo) migration(); + + migrateSw.Stop(); + _logger.Information($"MessageStore.Migrate took {migrateSw.ElapsedMilliseconds}ms"); } private void Migrate0() diff --git a/HellionChat/Util/AutoTranslate.cs b/HellionChat/Util/AutoTranslate.cs index 80b4c01..f92ccd3 100644 --- a/HellionChat/Util/AutoTranslate.cs +++ b/HellionChat/Util/AutoTranslate.cs @@ -62,7 +62,12 @@ internal static class AutoTranslate { var sw = Stopwatch.StartNew(); AllEntries(); - Plugin.LogProxy.Debug($"Warming up auto-translate took {sw.ElapsedMilliseconds}ms"); + // v1.4.9 R3 profiling: Information so the xllog tail surfaces this + // without a Debug filter. Belt-and-suspenders for future plugin-load + // regressions; remains in place after Sub-Task 3.4 Befund. + Plugin.LogProxy.Information( + $"Warming up auto-translate took {sw.ElapsedMilliseconds}ms" + ); }) { IsBackground = true,