Add targeted startup logging

JournalApp/Data/AppDbSeeder.cs

@@ -11,8 +11,13 @@ public class AppDbSeeder(ILogger<AppDbSeeder> logger, IDbContextFactory<AppDbCon
     public void PrepareDatabase()
     {
         logger.LogInformation("Preparing database");
-        using var db = dbFactory.CreateDbContext();
         var sw = Stopwatch.StartNew();
+        var phaseStopwatch = Stopwatch.StartNew();
+        using var db = dbFactory.CreateDbContext();
+        logger.LogInformation(
+            "Database prepare phase {PhaseName} completed in {ElapsedMilliseconds}ms",
+            "CreateDbContext",
+            phaseStopwatch.ElapsedMilliseconds);
 
 #if DEBUG && false
             // ⚠️ Dangerous: This block deletes the database and all preferences.
@@ -24,8 +29,13 @@ public void PrepareDatabase()
 #endif
         try
         {
+            phaseStopwatch.Restart();
             var anyPendingMigrations = db.Database.GetPendingMigrations().Any();
-            logger.LogInformation("Pending migrations detected: {HasPendingMigrations}", anyPendingMigrations);
+            logger.LogInformation(
+                "Database prepare phase {PhaseName} completed in {ElapsedMilliseconds}ms (pending migrations: {HasPendingMigrations})",
+                "CheckPendingMigrations",
+                phaseStopwatch.ElapsedMilliseconds,
+                anyPendingMigrations);
 
             if (anyPendingMigrations)
             {
@@ -48,7 +58,13 @@ public void PrepareDatabase()
             throw;
         }
 
+        phaseStopwatch.Restart();
         db.SaveChanges();
+        logger.LogInformation(
+            "Database prepare phase {PhaseName} completed in {ElapsedMilliseconds}ms",
+            "SaveChanges",
+            phaseStopwatch.ElapsedMilliseconds);
+
         sw.Stop();
         logger.LogInformation("Finished preparing database in {ElapsedMilliseconds}ms", sw.ElapsedMilliseconds);
     }
@@ -61,6 +77,9 @@ public void SeedCategories()
         logger.LogInformation("Seeding categories");
         using var db = dbFactory.CreateDbContext();
         var sw = Stopwatch.StartNew();
+        var addedCount = 0;
+        var existingCount = 0;
+        var saveCount = 0;
 
         void AddOrUpdate(
             string guidString,
@@ -105,15 +124,18 @@ void AddOrUpdate(
 
             if (doesExist)
             {
+                existingCount++;
                 logger.LogDebug("Updating category {CategoryGuid}", guidString);
             }
             else
             {
+                addedCount++;
                 logger.LogDebug("Adding category {CategoryGuid}", guidString);
                 db.AddCategory(category);
             }
 
             db.SaveChanges();
+            saveCount++;
         }
 
         AddOrUpdate(
@@ -222,7 +244,12 @@ void AddOrUpdate(
             medEveryDaySince: DateTimeOffset.Now);
 
         sw.Stop();
-        logger.LogInformation("Seeded categories in {ElapsedMilliseconds}ms", sw.ElapsedMilliseconds);
+        logger.LogInformation(
+            "Seeded categories in {ElapsedMilliseconds}ms (added: {AddedCount}, existing: {ExistingCount}, save changes calls: {SaveCount})",
+            sw.ElapsedMilliseconds,
+            addedCount,
+            existingCount,
+            saveCount);
     }
 
     /// <summary>
@@ -233,15 +260,19 @@ public void SeedDays(IEnumerable<DateOnly> dates)
     {
         using var db = dbFactory.CreateDbContext();
         var sw = Stopwatch.StartNew();
+        var requestedDates = dates as IReadOnlyCollection<DateOnly> ?? 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);
     }
 
     /// <summary>

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<AppDbSeeder>();
+        var logger = provider.GetRequiredService<ILoggerFactory>().CreateLogger("JournalApp.Startup");
+        logger.LogInformation(
+            "Startup phase {PhaseName} completed in {ElapsedMilliseconds}ms (total: {TotalElapsedMilliseconds}ms)",
+            "BuildServiceProvider",
+            phaseStopwatch.ElapsedMilliseconds,
+            startupStopwatch.ElapsedMilliseconds);
 
+        var dbSeeder = provider.GetRequiredService<AppDbSeeder>();
+
+        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<ILoggerFactory>().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;
     }
 }

JournalApp/Pages/Index.razor

@@ -143,27 +143,47 @@
 
     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)
         {
             // If we recently navigated away from the index, restore the date it was on before.
             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,34 +228,51 @@
         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();
     }
 
     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)

JournalApp/Pages/MainLayout.razor

@@ -3,6 +3,7 @@
 @implements IDisposable
 @inject KeyEventService KeyEventService
 @inject PreferenceService PreferenceService
+@inject ILogger<MainLayout> logger
 
 <MudThemeProvider Theme="_theme" IsDarkMode="PreferenceService.IsDarkMode" DefaultScrollbar />
 
@@ -96,6 +97,7 @@
         if (firstRender)
         {
             _hasInitiallyRendered = true;
+            logger.LogInformation("Blazor layout first render completed");
         }
     }