From 777c4a77c21c9ae7776b5a686ac4970c9543b1e7 Mon Sep 17 00:00:00 2001 From: Daniel Chalmers Date: Tue, 16 Jun 2026 15:29:46 -0500 Subject: [PATCH] Add targeted startup logging --- JournalApp/Data/AppDbSeeder.cs | 51 +++++++++++++++++++++---- JournalApp/MauiProgram.cs | 46 ++++++++++++++++++++--- JournalApp/Pages/Index.razor | 62 ++++++++++++++++++++++++++----- JournalApp/Pages/MainLayout.razor | 2 + 4 files changed, 139 insertions(+), 22 deletions(-) diff --git a/JournalApp/Data/AppDbSeeder.cs b/JournalApp/Data/AppDbSeeder.cs index b62e1cc0..e27ad9fc 100644 --- a/JournalApp/Data/AppDbSeeder.cs +++ b/JournalApp/Data/AppDbSeeder.cs @@ -11,8 +11,13 @@ public class AppDbSeeder(ILogger logger, IDbContextFactory @@ -233,15 +260,19 @@ public void SeedDays(IEnumerable dates) { using var db = dbFactory.CreateDbContext(); var sw = Stopwatch.StartNew(); + var requestedDates = dates as IReadOnlyCollection ?? dates.ToList(); // Only seed new days - skip dates that already exist. - var existingDates = db.Days.Where(d => dates.Contains(d.Date)).Select(d => d.Date).ToHashSet(); - var newDays = dates.Except(existingDates).Order().Select(Day.Create).ToList(); + var existingDates = db.Days.Where(d => requestedDates.Contains(d.Date)).Select(d => d.Date).ToHashSet(); + var newDays = requestedDates.Except(existingDates).Order().Select(Day.Create).ToList(); if (newDays.Count == 0) { sw.Stop(); - logger.LogDebug("SeedDays skipped; no new dates detected"); + logger.LogInformation( + "SeedDays skipped in {ElapsedMilliseconds}ms; all {RequestedDayCount} requested dates already exist", + sw.ElapsedMilliseconds, + requestedDates.Count); return; } @@ -280,7 +311,13 @@ void SeedDaysWithCategory() db.Days.AddRange(newDays); db.SaveChanges(); sw.Stop(); - logger.LogInformation("Seeded {DayCount} new days with {PointCount} points in {ElapsedMilliseconds}ms", newDays.Count, newPoints.Count, sw.ElapsedMilliseconds); + logger.LogInformation( + "Seeded {DayCount} new days with {PointCount} points in {ElapsedMilliseconds}ms (requested: {RequestedDayCount}, existing: {ExistingDayCount})", + newDays.Count, + newPoints.Count, + sw.ElapsedMilliseconds, + requestedDates.Count, + existingDates.Count); } /// diff --git a/JournalApp/MauiProgram.cs b/JournalApp/MauiProgram.cs index d6bef6c4..72ee3521 100644 --- a/JournalApp/MauiProgram.cs +++ b/JournalApp/MauiProgram.cs @@ -12,7 +12,7 @@ public static class MauiProgram public static MauiApp CreateMauiApp() { - var stopwatch = Stopwatch.StartNew(); + var startupStopwatch = Stopwatch.StartNew(); #pragma warning disable CA1416 // MAUI startup is only used from platform entry points. var builder = MauiApp.CreateBuilder() @@ -60,21 +60,55 @@ public static MauiApp CreateMauiApp() builder.Services.AddSingleton(CommunityToolkit.Maui.Storage.FileSaver.Default); // Seed the database with required data. + var phaseStopwatch = Stopwatch.StartNew(); using var provider = builder.Services.BuildServiceProvider(); - var dbSeeder = provider.GetService(); + var logger = provider.GetRequiredService().CreateLogger("JournalApp.Startup"); + logger.LogInformation( + "Startup phase {PhaseName} completed in {ElapsedMilliseconds}ms (total: {TotalElapsedMilliseconds}ms)", + "BuildServiceProvider", + phaseStopwatch.ElapsedMilliseconds, + startupStopwatch.ElapsedMilliseconds); + var dbSeeder = provider.GetRequiredService(); + + phaseStopwatch.Restart(); dbSeeder.PrepareDatabase(); + logger.LogInformation( + "Startup phase {PhaseName} completed in {ElapsedMilliseconds}ms (total: {TotalElapsedMilliseconds}ms)", + nameof(AppDbSeeder.PrepareDatabase), + phaseStopwatch.ElapsedMilliseconds, + startupStopwatch.ElapsedMilliseconds); + + phaseStopwatch.Restart(); dbSeeder.SeedCategories(); + logger.LogInformation( + "Startup phase {PhaseName} completed in {ElapsedMilliseconds}ms (total: {TotalElapsedMilliseconds}ms)", + nameof(AppDbSeeder.SeedCategories), + phaseStopwatch.ElapsedMilliseconds, + startupStopwatch.ElapsedMilliseconds); #if DEBUG // Only seed sample days in debug mode. + phaseStopwatch.Restart(); dbSeeder.SeedDays(); + logger.LogInformation( + "Startup phase {PhaseName} completed in {ElapsedMilliseconds}ms (total: {TotalElapsedMilliseconds}ms)", + "SeedDebugDays", + phaseStopwatch.ElapsedMilliseconds, + startupStopwatch.ElapsedMilliseconds); #endif - stopwatch.Stop(); - var logger = provider.GetRequiredService().CreateLogger("JournalApp.MauiProgram"); - logger.LogInformation("Created MAUI app in {ElapsedMilliseconds}ms", stopwatch.ElapsedMilliseconds); + phaseStopwatch.Restart(); + var app = builder.Build(); + logger.LogInformation( + "Startup phase {PhaseName} completed in {ElapsedMilliseconds}ms (total: {TotalElapsedMilliseconds}ms)", + "BuildMauiApp", + phaseStopwatch.ElapsedMilliseconds, + startupStopwatch.ElapsedMilliseconds); + + startupStopwatch.Stop(); + logger.LogInformation("Created MAUI app in {ElapsedMilliseconds}ms", startupStopwatch.ElapsedMilliseconds); - return builder.Build(); + return app; } } diff --git a/JournalApp/Pages/Index.razor b/JournalApp/Pages/Index.razor index 30af11df..927fbc81 100644 --- a/JournalApp/Pages/Index.razor +++ b/JournalApp/Pages/Index.razor @@ -143,15 +143,23 @@ protected override async Task OnInitializedAsync() { + var sw = Stopwatch.StartNew(); logger.LogDebug("Initializing asynchronously"); + + var dbContextStopwatch = Stopwatch.StartNew(); db = await DbFactory.CreateDbContextAsync(); + dbContextStopwatch.Stop(); + logger.LogInformation("Home init phase {PhaseName} completed in {ElapsedMilliseconds}ms", "CreateDbContext", dbContextStopwatch.ElapsedMilliseconds); + await base.OnInitializedAsync(); DateOnly date = DateOnly.FromDateTime(DateTime.Now); + var dateSource = "today"; if (DateOnly.TryParseExact(OpenToDateString, "yyyyMMdd", out var parsed)) { // Use the parameter date (from when you click a day in the calendar, etc). date = parsed; + dateSource = "route"; } else if (App.IndexDateState.HasValue) { @@ -159,11 +167,23 @@ if (DateTimeOffset.Now - App.IndexDateState.Value.LeftAt < TimeSpan.FromHours(1)) { date = App.IndexDateState.Value.LastDate; + dateSource = "restored"; } } logger.LogInformation($"Opening to {date}"); - await GoToDay(date); + var dayLoadStopwatch = Stopwatch.StartNew(); + await GoToDay(date, "initial-load"); + dayLoadStopwatch.Stop(); + + sw.Stop(); + logger.LogInformation( + "Home initialized in {ElapsedMilliseconds}ms (route date: {RouteDate}, open date: {OpenDate}, date source: {DateSource}, day load: {DayLoadMilliseconds}ms)", + sw.ElapsedMilliseconds, + OpenToDateString, + date, + dateSource, + dayLoadStopwatch.ElapsedMilliseconds); } protected override void OnWindowDeactivatedOrDestroying(object sender, EventArgs e) @@ -185,7 +205,7 @@ if (KeyEventService.CurrentDepth == 0) { logger.LogInformation($"Switching from {_day} to current day after user was gone since {_stoppedDate}"); - await GoToDay(DateOnly.FromDateTime(DateTime.Now)); + await GoToDay(DateOnly.FromDateTime(DateTime.Now), "resume"); await ScrollToTop(); } else @@ -198,7 +218,7 @@ async Task GoHome() { logger.LogDebug("Home button was clicked"); - await GoToDay(DateOnly.FromDateTime(DateTime.Now)); + await GoToDay(DateOnly.FromDateTime(DateTime.Now), "home-button"); await ScrollToTop(); } @@ -208,20 +228,37 @@ await JSRuntime.InvokeVoidAsync("scrollToAbsoluteTop", "instant"); } - async Task GoToDay(DateOnly date) + async Task GoToDay(DateOnly date, string reason) { var sw = Stopwatch.StartNew(); + var pendingChangesBeforeSave = db.ChangeTracker.Entries().Count(e => e.State != EntityState.Unchanged); + var phaseStopwatch = Stopwatch.StartNew(); await db.SaveChangesAsync(); // Save any changes that could have been made from the DataPointViews. + var preSaveMilliseconds = phaseStopwatch.ElapsedMilliseconds; + + phaseStopwatch.Restart(); _day = await db.GetOrCreateDayAndAddPoints(date); + var loadOrCreateMilliseconds = phaseStopwatch.ElapsedMilliseconds; + var pendingChangesAfterLoad = db.ChangeTracker.Entries().Count(e => e.State != EntityState.Unchanged); + + phaseStopwatch.Restart(); await db.SaveChangesAsync(); // Save potentially new day and points. + var finalSaveMilliseconds = phaseStopwatch.ElapsedMilliseconds; + var trackedEntryCount = db.ChangeTracker.Entries().Count(); sw.Stop(); - logger.LogDebug( - "Loaded day {Day} in {ElapsedMilliseconds}ms ({ElapsedTicks} ticks)", + logger.LogInformation( + "Loaded day {Day} in {ElapsedMilliseconds}ms (reason: {Reason}, pre-save: {PreSaveMilliseconds}ms, load/create: {LoadOrCreateMilliseconds}ms, final-save: {FinalSaveMilliseconds}ms, pending before save: {PendingChangesBeforeSave}, pending after load: {PendingChangesAfterLoad}, tracked entries: {TrackedEntryCount})", _day, sw.ElapsedMilliseconds, - sw.ElapsedTicks); + reason, + preSaveMilliseconds, + loadOrCreateMilliseconds, + finalSaveMilliseconds, + pendingChangesBeforeSave, + pendingChangesAfterLoad, + trackedEntryCount); StateHasChanged(); } @@ -229,13 +266,13 @@ async Task PreviousDay() { logger.LogInformation("Going to the previous day from {CurrentDay}", _day); - await GoToDay(_day.Date.Previous()); + await GoToDay(_day.Date.Previous(), "previous-day"); } async Task NextDay() { logger.LogInformation("Going to the next day from {CurrentDay}", _day); - await GoToDay(_day.Date.Next()); + await GoToDay(_day.Date.Next(), "next-day"); } void OpenCalendar() @@ -314,7 +351,14 @@ App.IndexDateState = (DateTimeOffset.Now, _day.Date); + var sw = Stopwatch.StartNew(); + var pendingChanges = db.ChangeTracker.Entries().Count(e => e.State != EntityState.Unchanged); db.SaveChanges(); + sw.Stop(); + logger.LogInformation( + "Saved home page state in {ElapsedMilliseconds}ms (pending changes: {PendingChanges})", + sw.ElapsedMilliseconds, + pendingChanges); } protected override void Dispose(bool disposing) diff --git a/JournalApp/Pages/MainLayout.razor b/JournalApp/Pages/MainLayout.razor index 9421ce2b..00834be3 100644 --- a/JournalApp/Pages/MainLayout.razor +++ b/JournalApp/Pages/MainLayout.razor @@ -3,6 +3,7 @@ @implements IDisposable @inject KeyEventService KeyEventService @inject PreferenceService PreferenceService +@inject ILogger logger @@ -96,6 +97,7 @@ if (firstRender) { _hasInitiallyRendered = true; + logger.LogInformation("Blazor layout first render completed"); } }