From 1740e61250142bf5d067ea0264f6a9f0941831ed Mon Sep 17 00:00:00 2001 From: Chris Titus Date: Wed, 1 Jul 2026 22:10:46 -0500 Subject: [PATCH] Add startup performance tracing --- Compile.ps1 | 8 ++ .../private/Start-WinUtilPerformanceTrace.ps1 | 14 +++ .../private/Stop-WinUtilPerformanceTrace.ps1 | 15 ++++ .../private/Test-WinUtilPerformanceTrace.ps1 | 12 +++ .../Write-WinUtilPerformanceCheckpoint.ps1 | 23 +++++ pester/performance.Tests.ps1 | 87 +++++++++++++++++++ scripts/main.ps1 | 13 +++ speed-todo.md | 66 ++++++++++++++ 8 files changed, 238 insertions(+) create mode 100644 functions/private/Start-WinUtilPerformanceTrace.ps1 create mode 100644 functions/private/Stop-WinUtilPerformanceTrace.ps1 create mode 100644 functions/private/Test-WinUtilPerformanceTrace.ps1 create mode 100644 functions/private/Write-WinUtilPerformanceCheckpoint.ps1 create mode 100644 pester/performance.Tests.ps1 create mode 100644 speed-todo.md diff --git a/Compile.ps1 b/Compile.ps1 index 22f29bb6..f9965c33 100644 --- a/Compile.ps1 +++ b/Compile.ps1 @@ -12,6 +12,11 @@ $script = (Get-Content -Path scripts\start.ps1) -replace '#{replaceme}', (Get-Da $script += Get-ChildItem -Path functions -Recurse -File | Get-Content -Raw +$script += @' +Start-WinUtilPerformanceTrace +Write-WinUtilPerformanceCheckpoint -Name "Config load start" +'@ + Get-ChildItem config | ForEach-Object { $obj = Get-Content -Path $_.FullName -Raw | ConvertFrom-Json @@ -27,8 +32,11 @@ Get-ChildItem config | ForEach-Object { $sync.configs[$_.BaseName] = $obj $script += "`$sync.configs.$($_.BaseName) = @'`r`n$json`r`n'@ | ConvertFrom-Json" + $script += "`r`nWrite-WinUtilPerformanceCheckpoint -Name `"Config $($_.BaseName) loaded`"" } +$script += "`r`nWrite-WinUtilPerformanceCheckpoint -Name `"Config load complete`"" + $xaml = Get-Content -Path xaml\inputXML.xaml -Raw $script += "`$inputXML = @'`r`n$xaml`r`n'@" diff --git a/functions/private/Start-WinUtilPerformanceTrace.ps1 b/functions/private/Start-WinUtilPerformanceTrace.ps1 new file mode 100644 index 00000000..0d936232 --- /dev/null +++ b/functions/private/Start-WinUtilPerformanceTrace.ps1 @@ -0,0 +1,14 @@ +function Start-WinUtilPerformanceTrace { + if (-not (Test-WinUtilPerformanceTrace) -or $null -eq $sync) { + return + } + + if (-not $sync.ContainsKey("PerformanceTrace")) { + $sync.PerformanceTrace = @{ + Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() + LastElapsedMs = 0.0 + } + } + + Write-WinUtilPerformanceCheckpoint -Name "Startup trace started" +} diff --git a/functions/private/Stop-WinUtilPerformanceTrace.ps1 b/functions/private/Stop-WinUtilPerformanceTrace.ps1 new file mode 100644 index 00000000..aa507fe5 --- /dev/null +++ b/functions/private/Stop-WinUtilPerformanceTrace.ps1 @@ -0,0 +1,15 @@ +function Stop-WinUtilPerformanceTrace { + param( + [string]$Name = "Startup trace complete" + ) + + if (-not (Test-WinUtilPerformanceTrace) -or $null -eq $sync -or -not $sync.ContainsKey("PerformanceTrace")) { + return + } + + Write-WinUtilPerformanceCheckpoint -Name $Name + + if ($null -ne $sync.PerformanceTrace.Stopwatch) { + $sync.PerformanceTrace.Stopwatch.Stop() + } +} diff --git a/functions/private/Test-WinUtilPerformanceTrace.ps1 b/functions/private/Test-WinUtilPerformanceTrace.ps1 new file mode 100644 index 00000000..1b899590 --- /dev/null +++ b/functions/private/Test-WinUtilPerformanceTrace.ps1 @@ -0,0 +1,12 @@ +function Test-WinUtilPerformanceTrace { + $enabledValue = ([string]$env:WINUTIL_PERF_LOG).ToLowerInvariant() + if ($enabledValue -in @("1", "true", "yes", "on")) { + return $true + } + + if ($null -ne $sync -and $sync.ContainsKey("PerformanceTraceEnabled")) { + return [bool]$sync.PerformanceTraceEnabled + } + + return $false +} diff --git a/functions/private/Write-WinUtilPerformanceCheckpoint.ps1 b/functions/private/Write-WinUtilPerformanceCheckpoint.ps1 new file mode 100644 index 00000000..9f244c16 --- /dev/null +++ b/functions/private/Write-WinUtilPerformanceCheckpoint.ps1 @@ -0,0 +1,23 @@ +function Write-WinUtilPerformanceCheckpoint { + param( + [Parameter(Mandatory = $true)] + [string]$Name + ) + + if (-not (Test-WinUtilPerformanceTrace) -or $null -eq $sync) { + return + } + + if (-not $sync.ContainsKey("PerformanceTrace") -or $null -eq $sync.PerformanceTrace.Stopwatch) { + $sync.PerformanceTrace = @{ + Stopwatch = [System.Diagnostics.Stopwatch]::StartNew() + LastElapsedMs = 0.0 + } + } + + $elapsedMs = [math]::Round($sync.PerformanceTrace.Stopwatch.Elapsed.TotalMilliseconds, 2) + $deltaMs = [math]::Round($elapsedMs - [double]$sync.PerformanceTrace.LastElapsedMs, 2) + $sync.PerformanceTrace.LastElapsedMs = $elapsedMs + + Write-WinUtilLog -Level "DEBUG" -Component "StartupPerf" -Message ("{0}: {1:N2} ms (+{2:N2} ms)" -f $Name, $elapsedMs, $deltaMs) +} diff --git a/pester/performance.Tests.ps1 b/pester/performance.Tests.ps1 new file mode 100644 index 00000000..73876398 --- /dev/null +++ b/pester/performance.Tests.ps1 @@ -0,0 +1,87 @@ +#=========================================================================== +# Tests - Performance tracing +#=========================================================================== + +BeforeAll { + $script:repoRoot = (Resolve-Path (Join-Path $PSScriptRoot "..")).Path + + . (Join-Path $script:repoRoot "functions\private\Write-WinUtilLog.ps1") + . (Join-Path $script:repoRoot "functions\private\Test-WinUtilPerformanceTrace.ps1") + . (Join-Path $script:repoRoot "functions\private\Write-WinUtilPerformanceCheckpoint.ps1") + . (Join-Path $script:repoRoot "functions\private\Start-WinUtilPerformanceTrace.ps1") + . (Join-Path $script:repoRoot "functions\private\Stop-WinUtilPerformanceTrace.ps1") +} + +Describe "WinUtil performance tracing helpers" { + BeforeEach { + $script:originalPerfEnv = $env:WINUTIL_PERF_LOG + Remove-Item Env:\WINUTIL_PERF_LOG -ErrorAction SilentlyContinue + $script:sync = [Hashtable]::Synchronized(@{}) + } + + AfterEach { + if ($null -eq $script:originalPerfEnv) { + Remove-Item Env:\WINUTIL_PERF_LOG -ErrorAction SilentlyContinue + } else { + $env:WINUTIL_PERF_LOG = $script:originalPerfEnv + } + + Remove-Variable -Name sync -Scope Script -ErrorAction SilentlyContinue + Remove-Variable -Name originalPerfEnv -Scope Script -ErrorAction SilentlyContinue + } + + It "is disabled by default" { + Test-WinUtilPerformanceTrace | Should -BeFalse + } + + It "can be enabled by environment variable" { + $env:WINUTIL_PERF_LOG = "1" + + Test-WinUtilPerformanceTrace | Should -BeTrue + } + + It "writes startup checkpoints through the normal WinUtil log helper" { + $env:WINUTIL_PERF_LOG = "1" + Mock Write-WinUtilLog { } + + Start-WinUtilPerformanceTrace + Write-WinUtilPerformanceCheckpoint -Name "XAML loaded" + Stop-WinUtilPerformanceTrace + + Should -Invoke -CommandName Write-WinUtilLog -Times 3 -Exactly -ParameterFilter { + $Component -eq "StartupPerf" -and $Level -eq "DEBUG" + } + Should -Invoke -CommandName Write-WinUtilLog -Times 1 -Exactly -ParameterFilter { + $Message -like "XAML loaded:*" + } + } +} + +Describe "Startup performance checkpoints" { + It "adds config-load checkpoints to compiled output" { + $compileScript = Get-Content -Path (Join-Path $script:repoRoot "Compile.ps1") -Raw + + $compileScript | Should -Match "Start-WinUtilPerformanceTrace" + $compileScript | Should -Match "Config load start" + $compileScript | Should -Match "Config load complete" + $compileScript | Should -Match "Config .* loaded" + } + + It "adds runtime checkpoints for startup hotspots" { + $mainScript = Get-Content -Path (Join-Path $script:repoRoot "scripts\main.ps1") -Raw + + foreach ($checkpoint in @( + "Runspace pool initialized", + "XAML loaded", + "Theme applied", + "Install UI created", + "Tweaks UI created", + "Features UI created", + "AppX UI created", + "Assets rendered", + "First content rendered" + )) { + $mainScript | Should -Match ([regex]::Escape($checkpoint)) + } + } +} diff --git a/scripts/main.ps1 b/scripts/main.ps1 index faf9af54..970972e4 100644 --- a/scripts/main.ps1 +++ b/scripts/main.ps1 @@ -61,6 +61,7 @@ $sync.runspace = [runspacefactory]::CreateRunspacePool( # Open the RunspacePool instance $sync.runspace.Open() +Write-WinUtilPerformanceCheckpoint -Name "Runspace pool initialized" # Create classes for different exceptions @@ -90,8 +91,10 @@ $sync.configs.appxHashtable = @{} $sync.configs.appx.PSObject.Properties | ForEach-Object { $sync.configs.appxHashtable[$_.Name] = $_.Value } +Write-WinUtilPerformanceCheckpoint -Name "Config hashtables initialized" Set-Preferences +Write-WinUtilPerformanceCheckpoint -Name "Preferences loaded" if ($Preset) { # Selects the tweaks from $Preset varible @@ -130,6 +133,7 @@ $reader = (New-Object System.Xml.XmlNodeReader $xaml) try { $sync["Form"] = [Windows.Markup.XamlReader]::Load( $reader ) $readerOperationSuccessful = $true + Write-WinUtilPerformanceCheckpoint -Name "XAML loaded" } catch [System.Management.Automation.MethodInvocationException] { Write-Host "We ran into a problem with the XAML code. Check the syntax for this control..." -ForegroundColor Red Write-Host $error[0].Exception.Message -ForegroundColor Red @@ -179,19 +183,25 @@ $sync.Form.Add_Loaded({ }) Invoke-WinutilThemeChange -theme $sync.preferences.theme +Write-WinUtilPerformanceCheckpoint -Name "Theme applied" # Now call the function with the final merged config Invoke-WPFUIElements -configVariable $sync.configs.appnavigation -targetGridName "appscategory" -columncount 1 Initialize-WPFUI -targetGridName "appscategory" +Write-WinUtilPerformanceCheckpoint -Name "App navigation UI created" Initialize-WPFUI -targetGridName "appspanel" +Write-WinUtilPerformanceCheckpoint -Name "Install UI created" Invoke-WPFUIElements -configVariable $sync.configs.tweaks -targetGridName "tweakspanel" -columncount 2 +Write-WinUtilPerformanceCheckpoint -Name "Tweaks UI created" Invoke-WPFUIElements -configVariable $sync.configs.feature -targetGridName "featurespanel" -columncount 2 +Write-WinUtilPerformanceCheckpoint -Name "Features UI created" Invoke-WPFUIElements -configVariable $sync.configs.appx -targetGridName "appxpanel" -columncount 2 +Write-WinUtilPerformanceCheckpoint -Name "AppX UI created" # Future implementation: Add Windows Version to updates panel #Invoke-WPFUIElements -configVariable $sync.configs.updates -targetGridName "updatespanel" -columncount 1 @@ -257,6 +267,7 @@ Set-WinUtilTaskbaritem -state "None" $sync["Form"].title = $sync["Form"].title + " " + $sync.version # Set the commands that will run when the form is closed $sync["Form"].Add_Closing({ + Stop-WinUtilPerformanceTrace -Name "Window closing" $sync.runspace.Dispose() $sync.runspace.Close() [System.GC]::Collect() @@ -326,6 +337,7 @@ $sync["Form"].Add_Deactivated({ }) $sync["Form"].Add_ContentRendered({ + Write-WinUtilPerformanceCheckpoint -Name "First content rendered" # Load the Windows Forms assembly Add-Type -AssemblyName System.Windows.Forms $primaryScreen = [System.Windows.Forms.Screen]::PrimaryScreen @@ -422,6 +434,7 @@ $NavLogoPanel.Children.Add((Invoke-WinUtilAssets -Type "logo" -Size 25)) | Out-N $sync["logorender"] = (Invoke-WinUtilAssets -Type "Logo" -Size 90 -Render) $sync["checkmarkrender"] = (Invoke-WinUtilAssets -Type "checkmark" -Size 512 -Render) $sync["warningrender"] = (Invoke-WinUtilAssets -Type "warning" -Size 512 -Render) +Write-WinUtilPerformanceCheckpoint -Name "Assets rendered" Set-WinUtilTaskbaritem -overlay "logo" diff --git a/speed-todo.md b/speed-todo.md new file mode 100644 index 00000000..39b86fba --- /dev/null +++ b/speed-todo.md @@ -0,0 +1,66 @@ +# Speed TODO + +WinUtil currently does too much work before the first GUI paint. Work from the top down: measure first, improve perceived launch time next, then clean up deeper execution/runspace paths. + +## P0 - Measure First + +- [x] Add temporary startup timing checkpoints with `System.Diagnostics.Stopwatch`. +- [x] Measure config embedding/load, runspace pool initialization, XAML load, theme application, install UI creation, tweaks UI creation, feature UI creation, AppX UI creation, and asset rendering. +- [x] Record baseline launch timing on a clean run and a warm run. +- [x] Keep timing output in the existing WinUtil log/transcript path. +- [x] Remove or gate temporary timing noise after the optimization work is validated. + +## P1 - Faster First Paint + +- [ ] Show the main window before building every non-visible panel. +- [ ] Build only the default visible tab during startup. +- [ ] Move Tweaks, Features, AppX, and Win11 ISO tab initialization to first tab activation. +- [ ] Add one-time guards so each lazy tab initializes only once. +- [ ] Preserve current behavior for `-Preset` and `-Config` automation paths. + +## P2 - Install Tab Rendering + +- [ ] Reduce up-front creation of all install app entries. +- [ ] Keep category/app grouping as pure data before touching WPF controls. +- [ ] Create WPF controls only on the UI thread. +- [ ] Investigate replacing eager app-entry creation with item templates or incremental category rendering. +- [ ] Verify search, selected-app counts, right-click popup, install, uninstall, and import/export selection state still work. + +## P3 - Toggle And Registry Startup Cost + +- [ ] Stop doing expensive registry-backed toggle status checks while constructing invisible UI. +- [ ] Defer toggle state reads until the Tweaks tab is first opened. +- [ ] Review `Get-WinUtilToggleStatus` so a status read does not create missing registry paths unless that behavior is explicitly required. +- [ ] Batch or cache repeated registry checks where possible. +- [ ] Verify toggle import, undo, preset, and manual click behavior still match current expectations. + +## P4 - Runspace Cleanup + +- [ ] Refactor `Invoke-WPFRunspace` to avoid shared `$script:powershell` and `$script:handle` state for concurrent callers. +- [ ] Keep the shared runspace pool alive for the app lifetime instead of disposing it from individual queued calls. +- [ ] Add explicit completion cleanup for each PowerShell instance after `EndInvoke`. +- [ ] Add focused Pester coverage for multiple queued runspace calls, failures, and cleanup. +- [ ] Do not parallelize winget/choco package installs by default; package manager locking and prompts make that unsafe. + +## P5 - Defer Runspace Pool Startup + +- [ ] Move GUI runspace pool creation after first render when no automation mode is active. +- [ ] Keep synchronous runspace pool creation for `-Preset` and `-Config`. +- [ ] Prewarm the pool shortly after `ContentRendered` so later actions do not feel delayed. +- [ ] Ensure closing the form disposes the pool if it was created. +- [ ] Verify buttons that queue work create or reuse the pool safely. + +## P6 - Asset And Theme Cost + +- [ ] Measure `Invoke-WinUtilAssets -Render` calls during startup. +- [ ] Cache rendered logo, checkmark, and warning images once per process. +- [ ] Defer non-critical taskbar overlay assets until after first render if measurable. +- [ ] Verify taskbar overlay success/error states still display correctly. + +## P7 - Verification + +- [ ] Run `.\Compile.ps1`. +- [ ] Run focused Pester tests for runspace, config, XAML wiring, install workflow, tweaks, and preferences/theme. +- [ ] Run the full Pester gate before marking speed work complete. +- [ ] Manually launch with `.\Compile.ps1 -Run` and verify first paint, default tab, lazy tabs, search, install selection, tweak toggles, AppX tab, and Win11 ISO tab. +- [ ] Check `git status --short` and do not stage or commit generated `winutil.ps1`.