From 7fb2ff5119abf5b9fbf8a08e2e28331de5920842 Mon Sep 17 00:00:00 2001
From: Mike Griese <migrie@microsoft.com>
Date: Tue, 2 Sep 2025 06:20:56 -0500
Subject: [PATCH] CmdPal: init Details in a slow pass; add more winget logs
 (#41425)

Related to #41384

We should load the `IDetails` from a `IListItem` in the slow pass,
instead of immediately when we load the list of items.

see also #39215

Also adds a lot of logging on our side, which helped ID that it isn't
our fault that the winget APIs are returning slowly. That's tracked
upstream (somewhere)
---
 .../CommandItemViewModel.cs                    |  2 +-
 .../ListItemViewModel.cs                       | 18 +++++++++++++++---
 .../Pages/WinGetExtensionPage.cs               | 12 ++++++++++++
 3 files changed, 28 insertions(+), 4 deletions(-)

diff --git a/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/CommandItemViewModel.cs b/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/CommandItemViewModel.cs
index ea7b8fb516..5e2fcea295 100644
--- a/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/CommandItemViewModel.cs
+++ b/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/CommandItemViewModel.cs
@@ -160,7 +160,7 @@ public partial class CommandItemViewModel : ExtensionObjectViewModel, ICommandBa
         Initialized |= InitializedState.Initialized;
     }
 
-    public void SlowInitializeProperties()
+    public virtual void SlowInitializeProperties()
     {
         if (IsSelectedInitialized)
         {
diff --git a/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/ListItemViewModel.cs b/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/ListItemViewModel.cs
index ad1aebe2d1..43dc24f72f 100644
--- a/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/ListItemViewModel.cs
+++ b/src/modules/cmdpal/Microsoft.CmdPal.Core.ViewModels/ListItemViewModel.cs
@@ -47,9 +47,21 @@ public partial class ListItemViewModel(IListItem model, WeakReference<IPageConte
 
         UpdateTags(li.Tags);
 
-        TextToSuggest = li.TextToSuggest;
         Section = li.Section ?? string.Empty;
-        var extensionDetails = li.Details;
+
+        UpdateProperty(nameof(Section));
+    }
+
+    public override void SlowInitializeProperties()
+    {
+        base.SlowInitializeProperties();
+        var model = Model.Unsafe;
+        if (model is null)
+        {
+            return;
+        }
+
+        var extensionDetails = model.Details;
         if (extensionDetails is not null)
         {
             Details = new(extensionDetails, PageContext);
@@ -58,8 +70,8 @@ public partial class ListItemViewModel(IListItem model, WeakReference<IPageConte
             UpdateProperty(nameof(HasDetails));
         }
 
+        TextToSuggest = model.TextToSuggest;
         UpdateProperty(nameof(TextToSuggest));
-        UpdateProperty(nameof(Section));
     }
 
     protected override void FetchProperty(string propertyName)
diff --git a/src/modules/cmdpal/ext/Microsoft.CmdPal.Ext.WinGet/Pages/WinGetExtensionPage.cs b/src/modules/cmdpal/ext/Microsoft.CmdPal.Ext.WinGet/Pages/WinGetExtensionPage.cs
index 155478cb52..1d7758769a 100644
--- a/src/modules/cmdpal/ext/Microsoft.CmdPal.Ext.WinGet/Pages/WinGetExtensionPage.cs
+++ b/src/modules/cmdpal/ext/Microsoft.CmdPal.Ext.WinGet/Pages/WinGetExtensionPage.cs
@@ -65,6 +65,7 @@ internal sealed partial class WinGetExtensionPage : DynamicListPage, IDisposable
 
             if (_results is not null && _results.Count != 0)
             {
+                var stopwatch = Stopwatch.StartNew();
                 var count = _results.Count;
                 var results = new ListItem[count];
                 var next = 0;
@@ -82,6 +83,8 @@ internal sealed partial class WinGetExtensionPage : DynamicListPage, IDisposable
                     }
                 }
 
+                stopwatch.Stop();
+                Logger.LogDebug($"Building ListItems took {stopwatch.ElapsedMilliseconds}ms", memberName: nameof(GetItems));
                 IsLoading = false;
                 return results;
             }
@@ -244,15 +247,22 @@ internal sealed partial class WinGetExtensionPage : DynamicListPage, IDisposable
 
         // foreach (var catalog in connections)
         {
+            Stopwatch findPackages_stopwatch = new();
+            findPackages_stopwatch.Start();
             Logger.LogDebug($"  Searching {catalog.Info.Name} ({query})", memberName: nameof(DoSearchAsync));
 
             ct.ThrowIfCancellationRequested();
 
+            Logger.LogDebug($"Preface for \"{searchDebugText}\" took {stopwatch.ElapsedMilliseconds}ms", memberName: nameof(DoSearchAsync));
+
             // BODGY, re: microsoft/winget-cli#5151
             // FindPackagesAsync isn't actually async.
             var internalSearchTask = Task.Run(() => catalog.FindPackages(opts), ct);
             var searchResults = await internalSearchTask;
 
+            findPackages_stopwatch.Stop();
+            Logger.LogDebug($"FindPackages for \"{searchDebugText}\" took {findPackages_stopwatch.ElapsedMilliseconds}ms", memberName: nameof(DoSearchAsync));
+
             // TODO more error handling like this:
             if (searchResults.Status != FindPackagesResultStatus.Ok)
             {
@@ -261,6 +271,8 @@ internal sealed partial class WinGetExtensionPage : DynamicListPage, IDisposable
                 return [];
             }
 
+            ct.ThrowIfCancellationRequested();
+
             Logger.LogDebug($"    got results for ({query})", memberName: nameof(DoSearchAsync));
 
             // FYI Using .ToArray or any other kind of enumerable loop