Add startup performance tracing
This commit is contained in:
Chris Titus
@@ -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'@"
|
||||
|
||||
|
||||
@@ -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"
|
||||
}
|
||||
@@ -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()
|
||||
}
|
||||
}
|
||||
@@ -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
|
||||
}
|
||||
@@ -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)
|
||||
}
|
||||
@@ -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))
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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"
|
||||
|
||||
|
||||
@@ -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`.
|
||||
Reference in New Issue
Block a user