From 724037b150145cae4f7c38e8dd3947ddae01b22c Mon Sep 17 00:00:00 2001 From: hatayama Date: Tue, 28 Jul 2026 10:16:06 +0900 Subject: [PATCH 1/6] feat: add a Windows PowerShell soak harness scripts/soak-loop.sh samples metrics with ps/pgrep/perl and needs jq, so the endurance harness could not run on Windows at all. scripts/soak-loop.ps1 ports it with the same iteration plan and the same CSV schema, so results from either platform are directly comparable. Platform substitutions: ConvertFrom-Json instead of jq, Win32_Process instead of ps/pgrep, Import-Csv/Group-Object instead of awk, and Start-Process with WaitForExit(timeout) + Kill() instead of the sleep+kill watchdog. A killed command is recorded as exit code 124 so a hung IPC call still surfaces as one finite failure. The pause-point line number is derived from the generated ticker source instead of a hand-maintained constant. Windows specifics: Start-Process takes a raw command line, so each argument is quoted against Windows argv rules locally; the script stays ASCII-only because Windows PowerShell 5.1 reads a BOM-less UTF-8 script as ANSI and would mangle the generated C# comments; and all output files are written through UTF8Encoding($false) because Add-Content stamps a BOM onto an empty file. Verified end to end under both PowerShell 7 and Windows PowerShell 5.1 against a stub uloop executable: full loop, argument quoting for paths with spaces and embedded quotes, pause-point arming, three-strike recovery restart, preflight abort, and the kill watchdog. Co-Authored-By: Claude Opus 5 (1M context) --- docs/soak-testing.md | 44 ++- scripts/soak-loop.ps1 | 854 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 887 insertions(+), 11 deletions(-) create mode 100644 scripts/soak-loop.ps1 diff --git a/docs/soak-testing.md b/docs/soak-testing.md index f132a59b60..574aa0b7cd 100644 --- a/docs/soak-testing.md +++ b/docs/soak-testing.md @@ -1,10 +1,14 @@ -# Soak testing with scripts/soak-loop.sh +# Soak testing with the soak-loop harness -`scripts/soak-loop.sh` is an endurance harness that exercises the `uloop` CLI -against a real Unity project for hundreds of iterations. It answers the -question a normal test suite cannot: does uloop stay correct, responsive, and -leak-free across many script compilations, domain reloads, PlayMode cycles, -test runs, and full editor restarts? +`scripts/soak-loop.sh` (macOS/Linux) and `scripts/soak-loop.ps1` (Windows) are +an endurance harness that exercises the `uloop` CLI against a real Unity +project for hundreds of iterations. They answer the question a normal test +suite cannot: does uloop stay correct, responsive, and leak-free across many +script compilations, domain reloads, PlayMode cycles, test runs, and full +editor restarts? + +Both variants run the same iteration plan and write the same CSV schema, so +results from either platform are directly comparable. It works against **any** Unity project that has the uloop package installed — point it at a large production project for the most realistic signal. @@ -16,9 +20,12 @@ point it at a large production project for the most realistic signal. - The Unity Editor does not have to be running: if no editor has the target project open, the harness launches one via `uloop launch`; a running but busy editor (importing/compiling) is waited on for up to 15 minutes. -- `jq`, when the PlayMode cycle is enabled (`--pause-every` > 0). -- macOS or Linux. The harness is POSIX sh but samples metrics with - `ps`/`pgrep`/`perl`; it is not expected to run on Windows. +- macOS/Linux (`soak-loop.sh`): POSIX sh, plus `jq` when the PlayMode cycle is + enabled (`--pause-every` > 0). Metrics are sampled with `ps`/`pgrep`/`perl`, + so this variant is not expected to run on Windows. +- Windows (`soak-loop.ps1`): Windows PowerShell 5.1 or PowerShell 7. No `jq` — + responses are parsed with `ConvertFrom-Json`. Metrics come from + `Win32_Process`, so `unity_rss_kb` is `Unity.exe`'s working set. ## Quick start @@ -29,7 +36,16 @@ sh scripts/soak-loop.sh \ --test-assembly YourProject.Tests.Editor ``` -Options and defaults (also printed by running the script without arguments): +```powershell +powershell -NoProfile -ExecutionPolicy Bypass -File .\scripts\soak-loop.ps1 ` + -ProjectPath C:\path\to\unity-project ` + -Iterations 20 ` + -TestAssembly YourProject.Tests.Editor +``` + +Options and defaults (also printed by running the shell script without +arguments; the PowerShell parameters are the same names in PascalCase, e.g. +`--restart-every` is `-RestartEvery`): | Option | Default | Meaning | | --- | --- | --- | @@ -45,7 +61,13 @@ Options and defaults (also printed by running the script without arguments): Environment: `ULOOP_BIN` selects the uloop binary (default: `uloop` from `PATH`, the realistic released configuration). Point it at a `dist/` binary to -soak unreleased CLI code, per the Native Go CLI Validation rules in CLAUDE.md. +soak unreleased CLI code, per the Native Go CLI Validation rules in CLAUDE.md +(`dist\windows-amd64\uloop.exe` on Windows). + +Every uloop call runs under a 10-minute kill watchdog. A hung IPC call — a +frozen editor that accepted the connection but never answers — is recorded as +one finite failure (exit code `124`) so the consecutive-failure recovery can +fire instead of blocking an unattended soak forever. ## What one iteration does diff --git a/scripts/soak-loop.ps1 b/scripts/soak-loop.ps1 new file mode 100644 index 0000000000..06fe2beffa --- /dev/null +++ b/scripts/soak-loop.ps1 @@ -0,0 +1,854 @@ +<# +Endurance (soak) harness for the uloop CLI against a real Unity project. +Windows/PowerShell port of scripts/soak-loop.sh - same iteration plan, same +CSV schema. Full guide (expected failures, safety, reading results): +docs/soak-testing.md + +Each iteration rewrites a scratch editor script inside the target project to +force a genuine script compilation + domain reload, then exercises the +commands that must survive hundreds of reload crossings: compile, get-logs, +get-hierarchy, screenshot, execute-dynamic-code. On a cadence it also runs +Unity tests, full editor restarts, forced recompiles, and a PlayMode +pause-point cycle against a generated minimal scene. Every command's exit +code, duration, and payload size is appended to a CSV so latency drift and +failure rate over time can be graphed afterwards. Editor working set and +leftover project-runner processes are sampled per iteration as leak signals. + +Usage: + powershell -NoProfile -ExecutionPolicy Bypass -File .\scripts\soak-loop.ps1 -ProjectPath C:\path\to\unity-project + pwsh -NoProfile -File .\scripts\soak-loop.ps1 -ProjectPath C:\path\to\unity-project -Iterations 20 -TestAssembly YourProject.Tests.Editor + +Environment: + ULOOP_BIN uloop binary to use (default: uloop from PATH - the realistic + release configuration; point at a dist\windows-amd64\uloop.exe + to soak unreleased CLI code) + +Prerequisites: + - uloop package installed in the target project + - Unity Editor may or may not be running: a busy editor is waited on, and + a missing one is launched via `uloop launch` + +All generated files live under Assets/UloopSoak/ in the target project (the +recompile scratch script, the PlayMode ticker script, and the pause-point +scene) and are left behind after the run - delete the folder and its .meta +manually when done. When -PauseEvery > 0, the harness opens its generated +scene and keeps it open, so save your own scene changes before running. +#> + +[CmdletBinding()] +param( + # Target Unity project root. + [Parameter(Mandatory = $true)] + [string]$ProjectPath, + # Total iterations. + [int]$Iterations = 100, + # Run `uloop launch -r` every N iterations (0 = never). + [int]$RestartEvery = 25, + # Use compile --force-recompile every N iterations (0 = never). + [int]$ForceEvery = 10, + # Run a PlayMode cycle (UI click + pause-point) every N iterations (0 = never). + [int]$PauseEvery = 5, + # Run `uloop run-tests` every N iterations (0 = never). + [int]$TestsEvery = 10, + # Test assembly passed to run-tests --filter-type assembly (required when + # -TestsEvery > 0; never run the full suite of a large project). + [string]$TestAssembly = "", + # Pause between iterations. + [int]$SleepSeconds = 0, + # Results directory (default: .\uloop-soak-results\). + [string]$OutDir = "" +) + +Set-StrictMode -Version Latest +$ErrorActionPreference = "Stop" + +[string]$UloopBin = "uloop" +if (-not [string]::IsNullOrWhiteSpace($env:ULOOP_BIN)) { + $UloopBin = $env:ULOOP_BIN +} + +if (-not (Test-Path -LiteralPath $ProjectPath)) { + throw "Error: $ProjectPath does not exist" +} +[string]$ResolvedProjectPath = (Resolve-Path -LiteralPath $ProjectPath).Path +if (-not (Test-Path -LiteralPath (Join-Path $ResolvedProjectPath "ProjectSettings\ProjectVersion.txt"))) { + throw "Error: $ResolvedProjectPath does not look like a Unity project (no ProjectSettings/ProjectVersion.txt)" +} +if ($TestsEvery -gt 0 -and [string]::IsNullOrWhiteSpace($TestAssembly)) { + throw "Error: -TestAssembly is required when tests are enabled (pass -TestsEvery 0 to skip tests; running the full suite of a large project is not a safe default)" +} + +# Start-Process needs a real executable path, and resolving once keeps every +# iteration from re-searching PATH. +[string]$ResolvedUloopBin = $UloopBin +if (Test-Path -LiteralPath $UloopBin) { + $ResolvedUloopBin = (Resolve-Path -LiteralPath $UloopBin).Path +} +else { + $ResolvedUloopBin = (Get-Command $UloopBin -CommandType Application -ErrorAction Stop | Select-Object -First 1).Source +} + +if ([string]::IsNullOrWhiteSpace($OutDir)) { + [string]$stamp = (Get-Date).ToString("yyyyMMdd-HHmmss") + $OutDir = Join-Path (Get-Location).Path "uloop-soak-results\$stamp" +} +$null = New-Item -ItemType Directory -Path $OutDir -Force +[string]$ResolvedOutDir = (Resolve-Path -LiteralPath $OutDir).Path + +[string]$CommandsCsv = Join-Path $ResolvedOutDir "commands.csv" +[string]$MetricsCsv = Join-Path $ResolvedOutDir "metrics.csv" +[string]$RunLog = Join-Path $ResolvedOutDir "run.log" +[string]$StdOutFile = Join-Path $ResolvedOutDir ".last-stdout" +[string]$StdErrFile = Join-Path $ResolvedOutDir ".last-stderr" +[string]$SceneSetupFile = Join-Path $ResolvedOutDir "setup-scene.cs" +[string]$SceneSetupForceFile = Join-Path $ResolvedOutDir "setup-scene-force.cs" + +[string]$SoakAssetsDir = Join-Path $ResolvedProjectPath "Assets\UloopSoak" +[string]$ScratchDir = Join-Path $SoakAssetsDir "Editor" +[string]$ScratchFile = Join-Path $ScratchDir "UloopSoakScratch.cs" +[string]$TickerRelativePath = "Assets/UloopSoak/UloopSoakTicker.cs" +[string]$ProbeRelativePath = "Assets/UloopSoak/UloopSoakButtonProbe.cs" +[string]$SceneRelativePath = "Assets/UloopSoak/UloopSoak.unity" + +# Unity reads .cs files as UTF-8; writing without a BOM keeps the generated +# sources byte-identical between Windows PowerShell 5.1 and PowerShell 7, +# whose Set-Content defaults disagree about the BOM. +[System.Text.UTF8Encoding]$Utf8NoBom = New-Object System.Text.UTF8Encoding($false) + +function Write-TextFile { + param( + [string]$Path, + [string]$Content + ) + + [System.IO.File]::WriteAllText($Path, $Content, $Utf8NoBom) +} + +# Add-Content is avoided for appends: Windows PowerShell 5.1 stamps a BOM onto +# an empty file, which would corrupt the first CSV row for readers that do not +# strip it. +function Add-TextLine { + param( + [string]$Path, + [string]$Line + ) + + [System.IO.File]::AppendAllText($Path, $Line + "`r`n", $Utf8NoBom) +} + +Write-TextFile -Path $CommandsCsv -Content "epoch_ms,iteration,command,exit_code,duration_ms,payload_bytes`r`n" +Write-TextFile -Path $MetricsCsv -Content "epoch_ms,iteration,unity_rss_kb,project_runner_procs,outputs_dir_kb`r`n" +# Created up front so the first append has a file to write into. +Write-TextFile -Path $RunLog -Content "" + +function Write-SoakLog { + param( + [string]$Message + ) + + [string]$line = "{0} [soak] {1}" -f (Get-Date).ToString("HH:mm:ss"), $Message + Write-Host $line + Add-TextLine -Path $RunLog -Line $line +} + +function Get-EpochMilliseconds { + return [DateTimeOffset]::UtcNow.ToUnixTimeMilliseconds() +} + +function ConvertTo-NativeCommandLineArgument { + param( + [string]$Argument + ) + + # Start-Process takes a raw command line, so each token is quoted here + # instead of by PowerShell. Windows argv rules treat backslashes specially + # only in front of a quote or the closing quote of a quoted token: ordinary + # paths such as C:\Users must stay unchanged, while a run of backslashes + # that reaches a quote has to be doubled. + [string]$escapedArgument = [regex]::Replace($Argument, '(\\*)"', { + param($match) + + [string]$backslashes = $match.Groups[1].Value + return $backslashes + $backslashes + '\"' + }) + + if ($Argument.Length -gt 0 -and $Argument -notmatch '[\s"]') { + return $escapedArgument + } + + [string]$quotedArgument = [regex]::Replace($escapedArgument, '(\\*)\z', { + param($match) + + [string]$backslashes = $match.Groups[1].Value + return $backslashes + $backslashes + }) + + return '"' + $quotedArgument + '"' +} + +function Get-CapturedText { + param( + [string]$Path + ) + + if (-not (Test-Path -LiteralPath $Path)) { + return "" + } + + [string]$text = Get-Content -LiteralPath $Path -Raw -Encoding UTF8 + if ($null -eq $text) { + return "" + } + + return $text +} + +function Get-FileByteLength { + param( + [string]$Path + ) + + if (-not (Test-Path -LiteralPath $Path)) { + return 0 + } + + return [int64](Get-Item -LiteralPath $Path).Length +} + +# Every uloop call runs under a kill watchdog: a hung IPC call - e.g. a frozen +# editor that accepted the connection but never answers - must surface as one +# failed, finite sample so the consecutive-failure recovery can fire, instead +# of blocking the unattended soak forever. The bound sits well above the +# slowest legitimate command observed under parallel load (forced recompile / +# run-tests, ~4 min). +[int]$CommandTimeoutSeconds = 600 +# Reported for a killed command; matches the exit code GNU timeout(1) uses, so +# a timeout is distinguishable from any exit code uloop itself returns. +[int]$TimeoutExitCode = 124 + +function Invoke-Uloop { + param( + [string[]]$CommandArguments + ) + + [string[]]$allArguments = @($CommandArguments) + @("--project-path", $ResolvedProjectPath) + [string]$commandLine = (@($allArguments | ForEach-Object { ConvertTo-NativeCommandLineArgument -Argument $_ })) -join " " + + Remove-Item -LiteralPath $StdOutFile, $StdErrFile -Force -ErrorAction SilentlyContinue + [System.Diagnostics.Process]$process = Start-Process -FilePath $ResolvedUloopBin ` + -ArgumentList $commandLine ` + -NoNewWindow ` + -PassThru ` + -RedirectStandardOutput $StdOutFile ` + -RedirectStandardError $StdErrFile + # Touching Handle caches the process handle: without it Windows PowerShell + # can report a null ExitCode for a -PassThru process it did not -Wait on. + $null = $process.Handle + + [int]$exitCode = 0 + if ($process.WaitForExit($CommandTimeoutSeconds * 1000)) { + $exitCode = $process.ExitCode + } + else { + try { + $process.Kill() + } + catch { + # Already gone between the timeout and the kill. + } + $process.WaitForExit() + $exitCode = $TimeoutExitCode + } + + [string]$text = (Get-CapturedText -Path $StdOutFile) + (Get-CapturedText -Path $StdErrFile) + [int64]$bytes = (Get-FileByteLength -Path $StdOutFile) + (Get-FileByteLength -Path $StdErrFile) + + return [pscustomobject]@{ + Arguments = $allArguments + ExitCode = $exitCode + Text = $text + Bytes = $bytes + } +} + +# Runs one uloop command, appends a CSV row, and returns the command result. +function Invoke-TimedUloop { + param( + [int]$Iteration, + [string]$Label, + [string[]]$CommandArguments + ) + + [int64]$start = Get-EpochMilliseconds + [pscustomobject]$result = Invoke-Uloop -CommandArguments $CommandArguments + [int64]$end = Get-EpochMilliseconds + + Add-TextLine -Path $CommandsCsv -Line ("{0},{1},{2},{3},{4},{5}" -f $start, $Iteration, $Label, $result.ExitCode, ($end - $start), $result.Bytes) + + if ($result.ExitCode -ne 0) { + [string]$excerpt = $result.Text + if ($excerpt.Length -gt 200) { + $excerpt = $excerpt.Substring(0, 200) + } + $excerpt = ($excerpt -replace '\r?\n', ' ') + Write-SoakLog -Message "FAIL iter=$Iteration $Label exit=$($result.ExitCode) ($excerpt)" + } + + return $result +} + +# Forces a script recompile by rewriting the scratch file with a new constant. +function Write-ScratchScript { + param( + [int]$Iteration + ) + + $null = New-Item -ItemType Directory -Path $ScratchDir -Force + Write-TextFile -Path $ScratchFile -Content @" +// Auto-generated by soak-loop.ps1 - safe to delete. +// Rewritten every iteration to force a script recompile and domain reload. +public static class UloopSoakScratch +{ + public const int Iteration = $Iteration; +} +"@ +} + +[string]$TickerSource = @' +// Auto-generated by soak-loop.ps1 - safe to delete. +// PlayMode ticker whose Update line is the soak's pause-point target. +using UnityEngine; + +public class UloopSoakTicker : MonoBehaviour +{ + private int tickCount; + + private void Update() + { + tickCount++; + } +} +'@ + +# The pause point must be armed on the line that actually executes every +# frame. Deriving it from the source above removes the hand-maintained +# constant the shell harness has to keep in sync with its heredoc. +function Get-TickerPauseLine { + [string[]]$lines = $TickerSource -split "`r?`n" + for ([int]$index = 0; $index -lt $lines.Length; $index++) { + if ($lines[$index] -match 'tickCount\+\+;') { + return $index + 1 + } + } + + throw "The generated ticker source no longer contains its pause-point line." +} + +# The uloop relative paths use forward slashes; joining them onto a Windows +# root needs the separators normalized first. +function Resolve-ProjectRelativePath { + param( + [string]$RelativePath + ) + + return Join-Path $ResolvedProjectPath ($RelativePath -replace '/', '\') +} + +function Write-TickerScripts { + $null = New-Item -ItemType Directory -Path $SoakAssetsDir -Force + Write-TextFile -Path (Resolve-ProjectRelativePath -RelativePath $TickerRelativePath) -Content $TickerSource + # The probe must live in its own file: Unity only serializes a + # MonoBehaviour into a scene when its class name matches the file name, + # and a second class in a shared file saves as a missing-script reference. + Write-TextFile -Path (Resolve-ProjectRelativePath -RelativePath $ProbeRelativePath) -Content @' +// Auto-generated by soak-loop.ps1 - safe to delete. +// Counts EventSystem clicks so the soak can verify simulate-mouse-ui delivery. +using UnityEngine; + +public class UloopSoakButtonProbe : MonoBehaviour, UnityEngine.EventSystems.IPointerClickHandler +{ + public int ClickCount { get; private set; } + + public void OnPointerClick(UnityEngine.EventSystems.PointerEventData eventData) + { + ClickCount++; + Debug.Log("UloopSoakButtonClicked count=" + ClickCount); + } +} +'@ +} + +# Discards any previous soak scene and rebuilds it from scratch: the +# pause-point ticker plus a clickable button wired for the UI simulation +# check. Recreating every time keeps stale generated state from leaking +# between cycles. Two variants are written: the guarded one refuses to +# discard unsaved USER scene changes (returns DIRTY_SCENE), while the force +# variant skips that guard - it is used only right after a harness-initiated +# editor restart, when any dirt in the reopened startup scene was produced +# by project tooling during startup and cannot be user work. +function Write-SceneSetupSnippets { + [string]$forceSource = @" +string scenePath = "$SceneRelativePath"; +UnityEditor.SceneManagement.EditorSceneManager.NewScene(UnityEditor.SceneManagement.NewSceneSetup.EmptyScene, UnityEditor.SceneManagement.NewSceneMode.Single); +if (System.IO.File.Exists(scenePath)) +{ + UnityEditor.AssetDatabase.DeleteAsset(scenePath); +} +UnityEngine.GameObject tickerGo = new UnityEngine.GameObject("SoakTicker"); +tickerGo.AddComponent(); +UnityEngine.GameObject canvasGo = new UnityEngine.GameObject("SoakCanvas"); +UnityEngine.Canvas canvas = canvasGo.AddComponent(); +canvas.renderMode = UnityEngine.RenderMode.ScreenSpaceOverlay; +canvasGo.AddComponent(); +canvasGo.AddComponent(); +UnityEngine.GameObject buttonGo = new UnityEngine.GameObject("SoakButton"); +buttonGo.transform.SetParent(canvasGo.transform, false); +buttonGo.AddComponent(); +buttonGo.AddComponent(); +UnityEngine.RectTransform rect = buttonGo.GetComponent(); +rect.sizeDelta = new UnityEngine.Vector2(320f, 120f); +UnityEngine.GameObject eventSystemGo = new UnityEngine.GameObject("SoakEventSystem"); +eventSystemGo.AddComponent(); +eventSystemGo.AddComponent(); +UnityEditor.SceneManagement.EditorSceneManager.SaveScene(UnityEngine.SceneManagement.SceneManager.GetActiveScene(), scenePath); +return "recreated"; +"@ + + [string]$guard = @" +UnityEngine.SceneManagement.Scene guardActive = UnityEngine.SceneManagement.SceneManager.GetActiveScene(); +if (guardActive.path != "$SceneRelativePath" && guardActive.isDirty) +{ + return "DIRTY_SCENE"; +} +"@ + + Write-TextFile -Path $SceneSetupForceFile -Content $forceSource + Write-TextFile -Path $SceneSetupFile -Content ($guard + "`n" + $forceSource) +} + +# Runs before every pause cycle, not just at setup: an editor restart mid-soak +# reopens the project's own last scene, which would silently leave the ticker +# out of PlayMode and expire every subsequent pause-point. +function Invoke-EnsureSoakScene { + param( + [int]$Iteration + ) + + return Invoke-TimedUloop -Iteration $Iteration -Label "scene-ensure" -CommandArguments @("execute-dynamic-code", "--code-file", $SceneSetupFile) +} + +function Get-UnityProcessForProject { + [object[]]$processes = @(Get-CimInstance Win32_Process -Filter "Name = 'Unity.exe'" -ErrorAction SilentlyContinue | Where-Object { $_.CommandLine }) + foreach ($process in $processes) { + if ($process.CommandLine.IndexOf($ResolvedProjectPath, [System.StringComparison]::OrdinalIgnoreCase) -ge 0) { + return $process + } + } + + return $null +} + +function Get-OutputsDirectoryKb { + [string]$outputsPath = Join-Path $ResolvedProjectPath ".uloop\outputs" + if (-not (Test-Path -LiteralPath $outputsPath)) { + return 0 + } + + [object]$sum = (Get-ChildItem -LiteralPath $outputsPath -Recurse -File -Force -ErrorAction SilentlyContinue | Measure-Object -Property Length -Sum).Sum + if ($null -eq $sum) { + return 0 + } + + return [int64]($sum / 1KB) +} + +function Write-Metrics { + param( + [int]$Iteration + ) + + [string]$workingSetKb = "" + [object]$unityProcess = Get-UnityProcessForProject + if ($null -ne $unityProcess) { + $workingSetKb = [string][int64]([int64]$unityProcess.WorkingSetSize / 1KB) + } + + [int]$runnerCount = @(Get-Process -Name "uloop-project-runner" -ErrorAction SilentlyContinue).Count + Add-TextLine -Path $MetricsCsv -Line ("{0},{1},{2},{3},{4}" -f (Get-EpochMilliseconds), $Iteration, $workingSetKb, $runnerCount, (Get-OutputsDirectoryKb)) +} + +# Polls get-logs until the editor answers again (used after restarts and recovery). +function Wait-Editor { + [datetime]$deadline = (Get-Date).AddSeconds(900) + while ((Get-Date) -lt $deadline) { + [pscustomobject]$result = Invoke-Uloop -CommandArguments @("get-logs", "--max-count", "1") + if ($result.ExitCode -eq 0) { + return $true + } + + Start-Sleep -Seconds 20 + } + + return $false +} + +# A soak aborted mid-pause-cycle would leave the editor paused in PlayMode; +# always hand the editor back in a usable state. +function Reset-EditorState { + if ($PauseEvery -le 0) { + return + } + + try { + $null = Invoke-Uloop -CommandArguments @("clear-pause-point", "--all") + $null = Invoke-Uloop -CommandArguments @("control-play-mode", "--action", "Stop") + } + catch { + Write-SoakLog -Message "Editor state cleanup failed: $($_.Exception.Message)" + } +} + +function Write-Summary { + Reset-EditorState + Write-SoakLog -Message "Results: $ResolvedOutDir" + + [object[]]$rows = @(Import-Csv -LiteralPath $CommandsCsv) + [string]$header = "{0,-14} {1,8} {2,8} {3,10}" -f "command", "runs", "fails", "avg_ms" + Write-Host $header + Add-TextLine -Path $RunLog -Line $header + foreach ($group in ($rows | Group-Object -Property command)) { + [int]$runs = $group.Count + [int]$fails = @($group.Group | Where-Object { $_.exit_code -ne "0" }).Count + [int64]$totalMs = 0 + foreach ($row in $group.Group) { + $totalMs += [int64]$row.duration_ms + } + + [string]$line = "{0,-14} {1,8} {2,8} {3,10}" -f $group.Name, $runs, $fails, [int64]($totalMs / $runs) + Write-Host $line + Add-TextLine -Path $RunLog -Line $line + } + + Write-SoakLog -Message "Reminder: delete $SoakAssetsDir (and its .meta) from the target project when finished." +} + +# Reads the SoakButton's simulation coordinates out of an annotated screenshot +# response. Returns $null when the element is missing or the payload is not +# the expected JSON, which the caller reports as a failed iteration. +function Get-SoakButtonCoordinates { + param( + [string]$Text + ) + + [object]$json = $null + try { + $json = $Text | ConvertFrom-Json + } + catch { + return $null + } + + if ($null -eq $json -or ($json.PSObject.Properties.Name -notcontains "Screenshots")) { + return $null + } + + [object[]]$screenshots = @($json.Screenshots) + if ($screenshots.Count -eq 0 -or ($screenshots[0].PSObject.Properties.Name -notcontains "AnnotatedElements")) { + return $null + } + + foreach ($element in @($screenshots[0].AnnotatedElements)) { + [string[]]$elementProperties = @($element.PSObject.Properties.Name) + if (($elementProperties -notcontains "Path") -or ($elementProperties -notcontains "SimX") -or ($elementProperties -notcontains "SimY")) { + continue + } + + if ($element.Path -ne "SoakCanvas/SoakButton") { + continue + } + + return [pscustomobject]@{ + X = ([double]$element.SimX).ToString([Globalization.CultureInfo]::InvariantCulture) + Y = ([double]$element.SimY).ToString([Globalization.CultureInfo]::InvariantCulture) + } + } + + return $null +} + +function Invoke-PauseCycle { + param( + [int]$Iteration, + [int]$TickerLine + ) + + [bool]$failed = $false + [pscustomobject]$sceneResult = Invoke-EnsureSoakScene -Iteration $Iteration + if ($sceneResult.ExitCode -ne 0 -or $sceneResult.Text.Contains("DIRTY_SCENE")) { + Write-SoakLog -Message "iter=$Iteration could not open the soak scene (unsaved changes?) - pause cycle failed" + return $true + } + + [pscustomobject]$playResult = Invoke-TimedUloop -Iteration $Iteration -Label "play-start" -CommandArguments @("control-play-mode", "--action", "Play") + if ($playResult.ExitCode -ne 0) { + return $true + } + + # UI simulation runs before the pause-point so EventSystem click + # processing happens while the game is still un-paused. Per the + # simulate-mouse-ui contract, clicks are coordinate-driven - the canonical + # flow is reading the button's SimX/SimY from the screenshot element + # annotation, which this also soaks. + [object]$button = $null + [pscustomobject]$annotateResult = Invoke-TimedUloop -Iteration $Iteration -Label "ui-annotate" -CommandArguments @("screenshot", "--capture-mode", "rendering", "--annotate-elements", "--elements-only") + if ($annotateResult.ExitCode -eq 0) { + $button = Get-SoakButtonCoordinates -Text $annotateResult.Text + } + + if ($null -eq $button) { + Write-SoakLog -Message "iter=$Iteration SoakButton missing from annotated elements" + $failed = $true + } + else { + [pscustomobject]$clickResult = Invoke-TimedUloop -Iteration $Iteration -Label "ui-click" -CommandArguments @("simulate-mouse-ui", "--action", "Click", "--x", $button.X, "--y", $button.Y) + if ($clickResult.ExitCode -ne 0) { + $failed = $true + } + elseif (-not $clickResult.Text.Contains('"HitGameObjectName": "SoakButton"')) { + Write-SoakLog -Message "iter=$Iteration click did not hit SoakButton" + $failed = $true + } + + [pscustomobject]$verifyResult = Invoke-TimedUloop -Iteration $Iteration -Label "ui-verify" -CommandArguments @("execute-dynamic-code", "--code", 'UloopSoakButtonProbe probe = UnityEngine.Object.FindFirstObjectByType(); return probe == null ? "probe-missing" : probe.ClickCount.ToString();') + if ($verifyResult.ExitCode -ne 0) { + $failed = $true + } + elseif (-not $verifyResult.Text.Contains('"Result": "1"')) { + Write-SoakLog -Message "iter=$Iteration button click was not registered by the probe" + $failed = $true + } + } + + [pscustomobject]$armResult = Invoke-TimedUloop -Iteration $Iteration -Label "pause-arm" -CommandArguments @("enable-pause-point", "--file", $TickerRelativePath, "--line", "$TickerLine", "--timeout-seconds", "60") + if ($armResult.ExitCode -ne 0) { + $failed = $true + } + + [pscustomobject]$awaitResult = Invoke-TimedUloop -Iteration $Iteration -Label "pause-await" -CommandArguments @("await-pause-point", "--id", "${TickerRelativePath}:${TickerLine}", "--timeout-seconds", "60") + if ($awaitResult.ExitCode -ne 0) { + $failed = $true + } + else { + if (-not $awaitResult.Text.Contains('"Hit"')) { + Write-SoakLog -Message "iter=$Iteration pause-point await returned without a Hit" + $failed = $true + } + # A Hit whose CapturedVariables lacks the ticker's field means the + # variable-capture pipeline broke even though pausing works. + if (-not $awaitResult.Text.Contains('"tickCount"')) { + Write-SoakLog -Message "iter=$Iteration pause-point hit but tickCount was not captured" + $failed = $true + } + } + + $null = Invoke-Uloop -CommandArguments @("clear-pause-point", "--all") + [pscustomobject]$stopResult = Invoke-TimedUloop -Iteration $Iteration -Label "play-stop" -CommandArguments @("control-play-mode", "--action", "Stop") + if ($stopResult.ExitCode -ne 0) { + $failed = $true + } + + return $failed +} + +try { + Write-SoakLog -Message "Soak start: $Iterations iterations against $ResolvedProjectPath (uloop: $ResolvedUloopBin)" + Write-SoakLog -Message "restart-every=$RestartEvery force-every=$ForceEvery pause-every=$PauseEvery tests-every=$TestsEvery sleep=${SleepSeconds}s" + + # A freshly launched editor can be busy importing/compiling for a long time + # (especially on large projects), so the preflight polls instead of + # one-shotting. No response can mean either a busy editor or no editor at + # all: launching over a busy editor would be wrong, and waiting 15 minutes + # for an editor that was never started would be wasted, so the two cases + # are told apart by whether a Unity process has this project open. + if ((Invoke-Uloop -CommandArguments @("get-logs", "--max-count", "1")).ExitCode -ne 0) { + if ($null -ne (Get-UnityProcessForProject)) { + Write-SoakLog -Message "Editor busy - waiting up to 15 minutes for it to answer" + } + else { + Write-SoakLog -Message "Editor not running - launching it with uloop launch" + if ((Invoke-TimedUloop -Iteration 0 -Label "launch-start" -CommandArguments @("launch")).ExitCode -ne 0) { + Write-SoakLog -Message "Preflight failed: could not launch the editor." + exit 1 + } + } + + if (-not (Wait-Editor)) { + Write-SoakLog -Message "Preflight failed: uloop cannot reach the editor." + exit 1 + } + } + + # Runner generations flipped this flag's polarity: newer runners need an + # explicit --wait-for-domain-reload (off by default), older ones wait by + # default and only expose --no-wait-for-domain-reload. Detect which flavor + # the pinned runner speaks. + [string[]]$CompileWaitArguments = @() + if ((Invoke-Uloop -CommandArguments @("compile", "--help")).Text -match '(?m)^\s*--wait-for-domain-reload') { + $CompileWaitArguments = @("--wait-for-domain-reload") + } + if ($CompileWaitArguments.Count -gt 0) { + Write-SoakLog -Message "compile wait flag: $($CompileWaitArguments[0])" + } + else { + Write-SoakLog -Message "compile wait flag: (runner waits by default)" + } + + [int]$TickerLine = 0 + if ($PauseEvery -gt 0) { + Write-TickerScripts + $TickerLine = Get-TickerPauseLine + if ((Invoke-TimedUloop -Iteration 0 -Label "setup-compile" -CommandArguments (@("compile") + $CompileWaitArguments)).ExitCode -ne 0) { + Write-SoakLog -Message "Setup compile for the pause-point ticker failed - aborting." + exit 1 + } + + Write-SceneSetupSnippets + [pscustomobject]$setupSceneResult = Invoke-EnsureSoakScene -Iteration 0 + if ($setupSceneResult.ExitCode -ne 0) { + Write-SoakLog -Message "Pause-point scene setup failed - aborting." + exit 1 + } + if ($setupSceneResult.Text.Contains("DIRTY_SCENE")) { + Write-SoakLog -Message "The active scene has unsaved changes - save or discard them, then rerun." + exit 1 + } + + Write-SoakLog -Message "pause-point scene ready: $SceneRelativePath" + } + + [int]$consecutiveFails = 0 + for ([int]$i = 1; $i -le $Iterations; $i++) { + Write-ScratchScript -Iteration $i + + [bool]$iterationFailed = $false + # Forced recompiles rebuild every assembly - a heavier reload path + # worth soaking, but far too slow to run on every iteration of a large + # project. Unity may legitimately report an unknown forced result after + # the domain reload (ForceCompileUnknownResult); the tool's own + # guidance is to follow up with a plain compile, so only that follow-up + # counts against the iteration and any other forced failure still does. + if ($ForceEvery -gt 0 -and ($i % $ForceEvery) -eq 0) { + [pscustomobject]$forcedResult = Invoke-TimedUloop -Iteration $i -Label "compile-forced" -CommandArguments (@("compile") + $CompileWaitArguments + @("--force-recompile")) + if ($forcedResult.ExitCode -ne 0 -and -not $forcedResult.Text.Contains("definitive result")) { + $iterationFailed = $true + } + } + + # Right after an editor (re)start, an explicit compile can collide with + # Unity's own startup compilation ("Compilation is already in + # progress", Retryable: true). That race is expected under load, so a + # single retry absorbs it; any other compile failure still fails the + # iteration. + [pscustomobject]$compileResult = Invoke-TimedUloop -Iteration $i -Label "compile" -CommandArguments (@("compile") + $CompileWaitArguments) + if ($compileResult.ExitCode -ne 0) { + if ($compileResult.Text.Contains("Compilation is already in progress")) { + Start-Sleep -Seconds 10 + if ((Invoke-TimedUloop -Iteration $i -Label "compile-retry" -CommandArguments (@("compile") + $CompileWaitArguments)).ExitCode -ne 0) { + $iterationFailed = $true + } + } + else { + $iterationFailed = $true + } + } + + if ((Invoke-TimedUloop -Iteration $i -Label "get-logs" -CommandArguments @("get-logs", "--max-count", "200")).ExitCode -ne 0) { + $iterationFailed = $true + } + if ((Invoke-TimedUloop -Iteration $i -Label "get-hierarchy" -CommandArguments @("get-hierarchy", "--max-depth", "5")).ExitCode -ne 0) { + $iterationFailed = $true + } + if ((Invoke-TimedUloop -Iteration $i -Label "screenshot" -CommandArguments @("screenshot", "--window-name", "Game", "--resolution-scale", "0.5")).ExitCode -ne 0) { + $iterationFailed = $true + } + if ((Invoke-TimedUloop -Iteration $i -Label "dynamic-code" -CommandArguments @("execute-dynamic-code", "--code", "int iteration = $i; return iteration + UnityEngine.SceneManagement.SceneManager.sceneCount;")).ExitCode -ne 0) { + $iterationFailed = $true + } + + if ($PauseEvery -gt 0 -and ($i % $PauseEvery) -eq 0) { + if (Invoke-PauseCycle -Iteration $i -TickerLine $TickerLine) { + $iterationFailed = $true + } + } + + if ($TestsEvery -gt 0 -and ($i % $TestsEvery) -eq 0) { + # Red project tests are not a soak failure - the harness measures + # whether uloop transported and completed the run, so only a + # missing test report (no TestCount in the response) counts against + # the iteration. + [pscustomobject]$testsResult = Invoke-TimedUloop -Iteration $i -Label "run-tests" -CommandArguments @("run-tests", "--test-mode", "EditMode", "--filter-type", "assembly", "--filter-value", $TestAssembly) + if ($testsResult.ExitCode -ne 0 -and -not $testsResult.Text.Contains('"TestCount"')) { + $iterationFailed = $true + } + } + + if ($RestartEvery -gt 0 -and ($i % $RestartEvery) -eq 0 -and $i -lt $Iterations) { + Write-SoakLog -Message "iter=$i scheduled editor restart" + $null = Invoke-TimedUloop -Iteration $i -Label "launch-restart" -CommandArguments @("launch", "-r") + if (-not (Wait-Editor)) { + Write-SoakLog -Message "Editor did not come back within 15 minutes after scheduled restart - aborting." + exit 1 + } + + # The reopened startup scene may be auto-dirtied by project + # tooling, which would trip the DIRTY_SCENE guard on the next pause + # cycle. Right after our own restart that dirt cannot be user work, + # so rebuild the soak scene unconditionally. + if ($PauseEvery -gt 0) { + if ((Invoke-TimedUloop -Iteration $i -Label "scene-restore" -CommandArguments @("execute-dynamic-code", "--code-file", $SceneSetupForceFile)).ExitCode -ne 0) { + Write-SoakLog -Message "iter=$i post-restart scene restore failed" + } + } + } + + Write-Metrics -Iteration $i + + if ($iterationFailed) { + $consecutiveFails++ + } + else { + $consecutiveFails = 0 + } + + if ($consecutiveFails -ge 3) { + Write-SoakLog -Message "3 consecutive failing iterations - attempting one recovery restart." + $null = Invoke-Uloop -CommandArguments @("launch", "-r") + if (-not (Wait-Editor)) { + Write-SoakLog -Message "Recovery restart failed - aborting soak." + exit 1 + } + + # Same post-restart scene restore as the scheduled restart path. + if ($PauseEvery -gt 0) { + if ((Invoke-TimedUloop -Iteration $i -Label "scene-restore" -CommandArguments @("execute-dynamic-code", "--code-file", $SceneSetupForceFile)).ExitCode -ne 0) { + Write-SoakLog -Message "iter=$i post-recovery scene restore failed" + } + } + + $consecutiveFails = 0 + Write-SoakLog -Message "Recovery succeeded, continuing." + } + + if ($SleepSeconds -gt 0) { + Start-Sleep -Seconds $SleepSeconds + } + if (($i % 10) -eq 0) { + Write-SoakLog -Message "progress: $i/$Iterations iterations done" + } + } + + Write-SoakLog -Message "Soak completed: $Iterations iterations." +} +finally { + Write-Summary +} From ba29243c50c78aa0601c0dd9a73700f6a098c9d4 Mon Sep 17 00:00:00 2001 From: hatayama Date: Tue, 28 Jul 2026 11:40:36 +0900 Subject: [PATCH 2/6] feat: keep the Windows soak summary free of ignorable failures A real run against a large project reported four failures that were not uloop defects, which buries any genuine regression. Two of them were preventable. enable-pause-point resolves a file and line through information Unity only keeps under Debug code optimization, so against a Release editor every pause cycle armed a guaranteed failure. The setup now switches the editor to Debug when the PlayMode cycle is enabled and restores the original mode when the run ends; -KeepCodeOptimization opts out. The other two cannot be prevented (ForceCompileUnknownResult, and a completed run-tests whose overall status is Skipped), so they are now reported as what they are: a non-zero exit matching the command's documented benign outcome logs as TOLERATED instead of FAIL and lands in a new tolerated column of the summary rather than fails. commands.csv still records the raw exit code, so it stays the unfiltered record and the schema stays identical to the shell harness. The tolerance rules moved into Invoke-TimedUloop, so the log and the iteration verdict can no longer disagree. Switching code optimization recompiles every assembly, which the following setup compile collided with; the retry that only the per-iteration compile had is now shared by both through Invoke-CompileWithRetry, and exhausting its attempts is reported as a real failure. Verified against the same project: fails is 0 for every command, the pause point arms and hits with tickCount captured, and the editor is left back on Release. Co-Authored-By: Claude Opus 5 (1M context) --- docs/soak-testing.md | 33 +++++++- scripts/soak-loop.ps1 | 179 ++++++++++++++++++++++++++++++++++++------ 2 files changed, 182 insertions(+), 30 deletions(-) diff --git a/docs/soak-testing.md b/docs/soak-testing.md index 574aa0b7cd..9d60d05bff 100644 --- a/docs/soak-testing.md +++ b/docs/soak-testing.md @@ -8,7 +8,11 @@ script compilations, domain reloads, PlayMode cycles, test runs, and full editor restarts? Both variants run the same iteration plan and write the same CSV schema, so -results from either platform are directly comparable. +results from either platform are directly comparable. Two behaviours are so +far implemented only in the PowerShell variant: the Debug code-optimization +setup below, and reporting known-benign outcomes as `TOLERATED` instead of +`FAIL`. The shell variant applies the same tolerance rules to its +pass/fail decisions but still prints them as `FAIL`. It works against **any** Unity project that has the uloop package installed — point it at a large production project for the most realistic signal. @@ -85,10 +89,30 @@ fire instead of blocking an unattended soak forever. Three consecutive failing iterations trigger one recovery restart; a second consecutive trip aborts the run. +## Code optimization (pause points) + +`enable-pause-point` resolves a file and line through information Unity only +keeps under **Debug** code optimization. Against a Release editor every arm +call fails on that precondition, so the whole PlayMode cycle would soak a +guaranteed failure. When `-PauseEvery` > 0, `soak-loop.ps1` reads the editor's +mode at setup, switches it to Debug if needed, and restores the original mode +when the run ends. Both switches trigger a full recompile — the setup compile +absorbs the first one by retrying past `Compilation is already in progress`, +and the restoring recompile runs in the background after the summary. Pass +`-KeepCodeOptimization` to leave the setting alone — expect every pause-point +command to fail if the project stays on Release. + +Debug code optimization also makes compiles slower (on one large project, +`compile` averaged ~53s under Release and ~82s under Debug), so only compare +latency between runs that used the same mode. + ## Expected (tolerated) failures The harness distinguishes uloop defects from known-benign outcomes. These do -NOT fail an iteration: +NOT fail an iteration; they are logged as `TOLERATED` (not `FAIL`) and counted +in the summary's `tolerated` column instead of `fails`. `commands.csv` keeps +the raw non-zero exit code either way, so it remains the unfiltered record for +graphing. - **Forced recompile without a definitive result** — designed behavior (`ForceCompileUnknownResult`); the follow-up plain compile is what counts. @@ -125,8 +149,9 @@ and the harness's scene restore are not protected. The output directory contains: -- `run.log` — human-readable progress, `FAIL` lines, and a per-command - summary table (runs / fails / avg ms) printed at the end. +- `run.log` — human-readable progress, `FAIL` (and, in the PowerShell variant, + `TOLERATED`) lines, and a per-command summary table printed at the end + (runs / fails / avg ms; the PowerShell variant adds a `tolerated` column). - `commands.csv` — `epoch_ms,iteration,command,exit_code,duration_ms,payload_bytes` for every command, for graphing latency drift and failure rate over time. - `metrics.csv` — `epoch_ms,iteration,unity_rss_kb,project_runner_procs,outputs_dir_kb` diff --git a/scripts/soak-loop.ps1 b/scripts/soak-loop.ps1 index 06fe2beffa..2362a1f8b8 100644 --- a/scripts/soak-loop.ps1 +++ b/scripts/soak-loop.ps1 @@ -53,6 +53,10 @@ param( # Test assembly passed to run-tests --filter-type assembly (required when # -TestsEvery > 0; never run the full suite of a large project). [string]$TestAssembly = "", + # Leave the editor's code optimization mode alone. Without this the + # PlayMode cycle switches a Release editor to Debug for the duration of the + # run, because pause points cannot be armed by file and line otherwise. + [switch]$KeepCodeOptimization, # Pause between iterations. [int]$SleepSeconds = 0, # Results directory (default: .\uloop-soak-results\). @@ -271,12 +275,22 @@ function Invoke-Uloop { } } +# Known-benign outcomes are counted per label so the summary can report them +# apart from real failures. The raw exit code still reaches commands.csv: the +# CSV stays the unfiltered record, the log and the summary stay signal. +[hashtable]$ToleratedCounts = @{} + # Runs one uloop command, appends a CSV row, and returns the command result. +# ToleratedPattern names the one documented outcome for this command that is +# expected to fail without being a defect (see docs/soak-testing.md); a +# non-zero exit whose payload contains it is reported as TOLERATED, and the +# returned Tolerated flag tells the caller not to fail the iteration. function Invoke-TimedUloop { param( [int]$Iteration, [string]$Label, - [string[]]$CommandArguments + [string[]]$CommandArguments, + [string]$ToleratedPattern = "" ) [int64]$start = Get-EpochMilliseconds @@ -285,16 +299,78 @@ function Invoke-TimedUloop { Add-TextLine -Path $CommandsCsv -Line ("{0},{1},{2},{3},{4},{5}" -f $start, $Iteration, $Label, $result.ExitCode, ($end - $start), $result.Bytes) + [bool]$tolerated = $false if ($result.ExitCode -ne 0) { + $tolerated = (-not [string]::IsNullOrEmpty($ToleratedPattern)) -and $result.Text.Contains($ToleratedPattern) [string]$excerpt = $result.Text if ($excerpt.Length -gt 200) { $excerpt = $excerpt.Substring(0, 200) } $excerpt = ($excerpt -replace '\r?\n', ' ') - Write-SoakLog -Message "FAIL iter=$Iteration $Label exit=$($result.ExitCode) ($excerpt)" + + if ($tolerated) { + if (-not $ToleratedCounts.ContainsKey($Label)) { + $ToleratedCounts[$Label] = 0 + } + $ToleratedCounts[$Label] = $ToleratedCounts[$Label] + 1 + Write-SoakLog -Message "TOLERATED iter=$Iteration $Label exit=$($result.ExitCode) ($excerpt)" + } + else { + Write-SoakLog -Message "FAIL iter=$Iteration $Label exit=$($result.ExitCode) ($excerpt)" + } + } + + return [pscustomobject]@{ + Arguments = $result.Arguments + ExitCode = $result.ExitCode + Text = $result.Text + Bytes = $result.Bytes + Tolerated = $tolerated + } +} + +# An explicit compile can collide with a compilation Unity started on its own +# ("Compilation is already in progress", Retryable: true) - after an editor +# restart, and after the setup switches code optimization, which recompiles +# every assembly. Retrying absorbs that race; any other failure is returned to +# the caller untouched. Exhausting the attempts is a real failure, so the last +# collision is un-tolerated before returning. +function Invoke-CompileWithRetry { + param( + [int]$Iteration, + [string]$Label, + [string[]]$CompileArguments, + [int]$MaxAttempts = 3 + ) + + [pscustomobject]$result = $null + [string]$attemptLabel = $Label + for ([int]$attempt = 1; $attempt -le $MaxAttempts; $attempt++) { + $attemptLabel = $Label + if ($attempt -gt 1) { + $attemptLabel = "$Label-retry" + } + + $result = Invoke-TimedUloop -Iteration $Iteration -Label $attemptLabel -CommandArguments $CompileArguments -ToleratedPattern "Compilation is already in progress" + if ($result.ExitCode -eq 0 -or -not $result.Tolerated) { + return $result + } + + Start-Sleep -Seconds 10 } - return $result + if ($ToleratedCounts.ContainsKey($attemptLabel)) { + $ToleratedCounts[$attemptLabel] = $ToleratedCounts[$attemptLabel] - 1 + } + Write-SoakLog -Message "FAIL iter=$Iteration $Label still collided with an in-progress compilation after $MaxAttempts attempts" + + return [pscustomobject]@{ + Arguments = $result.Arguments + ExitCode = $result.ExitCode + Text = $result.Text + Bytes = $result.Bytes + Tolerated = $false + } } # Forces a script recompile by rewriting the scratch file with a new constant. @@ -492,6 +568,60 @@ function Wait-Editor { return $false } +# enable-pause-point resolves a file and line through information Unity only +# keeps under Debug code optimization: against a Release editor every arm call +# fails on that precondition, so the whole PlayMode cycle would soak a +# guaranteed failure instead of the paths it is meant to exercise. The original +# mode is remembered here and restored when the run ends. +[string]$PreviousCodeOptimization = "" + +function Initialize-CodeOptimization { + if ($KeepCodeOptimization) { + return + } + + [pscustomobject]$result = Invoke-TimedUloop -Iteration 0 -Label "code-optimization" -CommandArguments @( + "execute-dynamic-code", + "--code", + 'UnityEditor.Compilation.CodeOptimization previous = UnityEditor.Compilation.CompilationPipeline.codeOptimization; if (previous != UnityEditor.Compilation.CodeOptimization.Debug) { UnityEditor.Compilation.CompilationPipeline.codeOptimization = UnityEditor.Compilation.CodeOptimization.Debug; } return previous.ToString();' + ) + if ($result.ExitCode -ne 0) { + Write-SoakLog -Message "Could not set Debug code optimization - pause points will fail while the editor stays on Release." + return + } + + [object]$json = $null + try { + $json = $result.Text | ConvertFrom-Json + } + catch { + return + } + + if ($null -eq $json -or ($json.PSObject.Properties.Name -notcontains "Result") -or ($json.Result -eq "Debug")) { + return + } + + $script:PreviousCodeOptimization = [string]$json.Result + Write-SoakLog -Message "code optimization: switched $($json.Result) -> Debug so pause points can be armed (restored when the run ends)" +} + +function Restore-CodeOptimization { + if ([string]::IsNullOrEmpty($PreviousCodeOptimization)) { + return + } + + [string]$previous = $PreviousCodeOptimization + # Cleared first so a failing restore is not retried on every later call. + $script:PreviousCodeOptimization = "" + $null = Invoke-Uloop -CommandArguments @( + "execute-dynamic-code", + "--code", + "UnityEditor.Compilation.CompilationPipeline.codeOptimization = UnityEditor.Compilation.CodeOptimization.$previous; return UnityEditor.Compilation.CompilationPipeline.codeOptimization.ToString();" + ) + Write-SoakLog -Message "code optimization: restored $previous (the editor recompiles once more in the background)" +} + # A soak aborted mid-pause-cycle would leave the editor paused in PlayMode; # always hand the editor back in a usable state. function Reset-EditorState { @@ -502,6 +632,8 @@ function Reset-EditorState { try { $null = Invoke-Uloop -CommandArguments @("clear-pause-point", "--all") $null = Invoke-Uloop -CommandArguments @("control-play-mode", "--action", "Stop") + # Only after PlayMode has stopped: Unity refuses to recompile while playing. + Restore-CodeOptimization } catch { Write-SoakLog -Message "Editor state cleanup failed: $($_.Exception.Message)" @@ -513,18 +645,23 @@ function Write-Summary { Write-SoakLog -Message "Results: $ResolvedOutDir" [object[]]$rows = @(Import-Csv -LiteralPath $CommandsCsv) - [string]$header = "{0,-14} {1,8} {2,8} {3,10}" -f "command", "runs", "fails", "avg_ms" + [string]$header = "{0,-20} {1,8} {2,8} {3,10} {4,10}" -f "command", "runs", "fails", "tolerated", "avg_ms" Write-Host $header Add-TextLine -Path $RunLog -Line $header foreach ($group in ($rows | Group-Object -Property command)) { [int]$runs = $group.Count - [int]$fails = @($group.Group | Where-Object { $_.exit_code -ne "0" }).Count + [int]$nonZero = @($group.Group | Where-Object { $_.exit_code -ne "0" }).Count + [int]$tolerated = 0 + if ($ToleratedCounts.ContainsKey($group.Name)) { + $tolerated = $ToleratedCounts[$group.Name] + } + [int]$fails = $nonZero - $tolerated [int64]$totalMs = 0 foreach ($row in $group.Group) { $totalMs += [int64]$row.duration_ms } - [string]$line = "{0,-14} {1,8} {2,8} {3,10}" -f $group.Name, $runs, $fails, [int64]($totalMs / $runs) + [string]$line = "{0,-20} {1,8} {2,8} {3,10} {4,10}" -f $group.Name, $runs, $fails, $tolerated, [int64]($totalMs / $runs) Write-Host $line Add-TextLine -Path $RunLog -Line $line } @@ -707,7 +844,10 @@ try { if ($PauseEvery -gt 0) { Write-TickerScripts $TickerLine = Get-TickerPauseLine - if ((Invoke-TimedUloop -Iteration 0 -Label "setup-compile" -CommandArguments (@("compile") + $CompileWaitArguments)).ExitCode -ne 0) { + # Before the setup compile: switching the mode recompiles everything + # anyway, so the compile below doubles as the confirmation. + Initialize-CodeOptimization + if ((Invoke-CompileWithRetry -Iteration 0 -Label "setup-compile" -CompileArguments (@("compile") + $CompileWaitArguments)).ExitCode -ne 0) { Write-SoakLog -Message "Setup compile for the pause-point ticker failed - aborting." exit 1 } @@ -738,28 +878,15 @@ try { # guidance is to follow up with a plain compile, so only that follow-up # counts against the iteration and any other forced failure still does. if ($ForceEvery -gt 0 -and ($i % $ForceEvery) -eq 0) { - [pscustomobject]$forcedResult = Invoke-TimedUloop -Iteration $i -Label "compile-forced" -CommandArguments (@("compile") + $CompileWaitArguments + @("--force-recompile")) - if ($forcedResult.ExitCode -ne 0 -and -not $forcedResult.Text.Contains("definitive result")) { + [pscustomobject]$forcedResult = Invoke-TimedUloop -Iteration $i -Label "compile-forced" -CommandArguments (@("compile") + $CompileWaitArguments + @("--force-recompile")) -ToleratedPattern "definitive result" + if ($forcedResult.ExitCode -ne 0 -and -not $forcedResult.Tolerated) { $iterationFailed = $true } } - # Right after an editor (re)start, an explicit compile can collide with - # Unity's own startup compilation ("Compilation is already in - # progress", Retryable: true). That race is expected under load, so a - # single retry absorbs it; any other compile failure still fails the - # iteration. - [pscustomobject]$compileResult = Invoke-TimedUloop -Iteration $i -Label "compile" -CommandArguments (@("compile") + $CompileWaitArguments) + [pscustomobject]$compileResult = Invoke-CompileWithRetry -Iteration $i -Label "compile" -CompileArguments (@("compile") + $CompileWaitArguments) if ($compileResult.ExitCode -ne 0) { - if ($compileResult.Text.Contains("Compilation is already in progress")) { - Start-Sleep -Seconds 10 - if ((Invoke-TimedUloop -Iteration $i -Label "compile-retry" -CommandArguments (@("compile") + $CompileWaitArguments)).ExitCode -ne 0) { - $iterationFailed = $true - } - } - else { - $iterationFailed = $true - } + $iterationFailed = $true } if ((Invoke-TimedUloop -Iteration $i -Label "get-logs" -CommandArguments @("get-logs", "--max-count", "200")).ExitCode -ne 0) { @@ -786,8 +913,8 @@ try { # whether uloop transported and completed the run, so only a # missing test report (no TestCount in the response) counts against # the iteration. - [pscustomobject]$testsResult = Invoke-TimedUloop -Iteration $i -Label "run-tests" -CommandArguments @("run-tests", "--test-mode", "EditMode", "--filter-type", "assembly", "--filter-value", $TestAssembly) - if ($testsResult.ExitCode -ne 0 -and -not $testsResult.Text.Contains('"TestCount"')) { + [pscustomobject]$testsResult = Invoke-TimedUloop -Iteration $i -Label "run-tests" -CommandArguments @("run-tests", "--test-mode", "EditMode", "--filter-type", "assembly", "--filter-value", $TestAssembly) -ToleratedPattern '"TestCount"' + if ($testsResult.ExitCode -ne 0 -and -not $testsResult.Tolerated) { $iterationFailed = $true } } From 3a4ee1eb47430411f3e3acd172dc15e7e2e00051 Mon Sep 17 00:00:00 2001 From: hatayama Date: Tue, 28 Jul 2026 14:21:28 +0900 Subject: [PATCH 3/6] fix: make the soak watchdog configurable and verify the code-optimization restore A three-way parallel soak against one large project exposed two harness defects. The 600-second per-command kill watchdog was a hard-coded constant. Switching code optimization recompiles every assembly, and with three editors compiling at once that setup compile passed ten minutes, so two of the three runs were killed at exit 124 before their first iteration. The bound is now -CommandTimeoutSeconds, echoed in the run's opening log line so a result directory says which bound produced it. The default stays 600. The code-optimization restore claimed success without looking at the result. Teardown runs while the editor is often still compiling, which makes the command bounce off UNITY_SERVER_BUSY, and all three runs logged "restored Release" while leaving their project on Debug. It now retries and only reports success once the editor echoes the restored mode back, otherwise it warns and names the toolbar control. Both fixes were exercised by the rerun: the restore succeeded on all three projects after several busy retries. Co-Authored-By: Claude Opus 5 (1M context) --- scripts/soak-loop.ps1 | 42 +++++++++++++++++++++++++++++++----------- 1 file changed, 31 insertions(+), 11 deletions(-) diff --git a/scripts/soak-loop.ps1 b/scripts/soak-loop.ps1 index 2362a1f8b8..5a1bb8e39d 100644 --- a/scripts/soak-loop.ps1 +++ b/scripts/soak-loop.ps1 @@ -57,6 +57,10 @@ param( # PlayMode cycle switches a Release editor to Debug for the duration of the # run, because pause points cannot be armed by file and line otherwise. [switch]$KeepCodeOptimization, + # Kill bound for a single uloop call. Raise it for a large project, and + # especially for parallel soaks: a full recompile of one large project took + # over 10 minutes with three editors compiling at once. + [int]$CommandTimeoutSeconds = 600, # Pause between iterations. [int]$SleepSeconds = 0, # Results directory (default: .\uloop-soak-results\). @@ -222,10 +226,11 @@ function Get-FileByteLength { # Every uloop call runs under a kill watchdog: a hung IPC call - e.g. a frozen # editor that accepted the connection but never answers - must surface as one # failed, finite sample so the consecutive-failure recovery can fire, instead -# of blocking the unattended soak forever. The bound sits well above the -# slowest legitimate command observed under parallel load (forced recompile / -# run-tests, ~4 min). -[int]$CommandTimeoutSeconds = 600 +# of blocking the unattended soak forever. The bound has to stay above the +# slowest legitimate command, which is project- and load-dependent, so +# -CommandTimeoutSeconds exists: a forced recompile of a large project takes +# ~8 minutes on its own and longer while other editors compile in parallel. +# # Reported for a killed command; matches the exit code GNU timeout(1) uses, so # a timeout is distinguishable from any exit code uloop itself returns. [int]$TimeoutExitCode = 124 @@ -606,6 +611,11 @@ function Initialize-CodeOptimization { Write-SoakLog -Message "code optimization: switched $($json.Result) -> Debug so pause points can be armed (restored when the run ends)" } +# Teardown runs right after whatever ended the soak, so the editor is often +# still busy (a killed compile keeps running inside Unity) and rejects the +# command. Leaving a project on Debug because one attempt bounced is a state +# leak the operator has no reason to expect, so this retries and only claims +# success once the editor reports the restored mode back. function Restore-CodeOptimization { if ([string]::IsNullOrEmpty($PreviousCodeOptimization)) { return @@ -614,12 +624,22 @@ function Restore-CodeOptimization { [string]$previous = $PreviousCodeOptimization # Cleared first so a failing restore is not retried on every later call. $script:PreviousCodeOptimization = "" - $null = Invoke-Uloop -CommandArguments @( - "execute-dynamic-code", - "--code", - "UnityEditor.Compilation.CompilationPipeline.codeOptimization = UnityEditor.Compilation.CodeOptimization.$previous; return UnityEditor.Compilation.CompilationPipeline.codeOptimization.ToString();" - ) - Write-SoakLog -Message "code optimization: restored $previous (the editor recompiles once more in the background)" + + for ([int]$attempt = 1; $attempt -le 10; $attempt++) { + [pscustomobject]$result = Invoke-Uloop -CommandArguments @( + "execute-dynamic-code", + "--code", + "UnityEditor.Compilation.CompilationPipeline.codeOptimization = UnityEditor.Compilation.CodeOptimization.$previous; return UnityEditor.Compilation.CompilationPipeline.codeOptimization.ToString();" + ) + if ($result.ExitCode -eq 0 -and $result.Text.Contains('"Result": "' + $previous + '"')) { + Write-SoakLog -Message "code optimization: restored $previous (the editor recompiles once more in the background)" + return + } + + Start-Sleep -Seconds 30 + } + + Write-SoakLog -Message "WARNING: could not restore code optimization to $previous - the editor is still on Debug, switch it back from the bug icon in the main toolbar." } # A soak aborted mid-pause-cycle would leave the editor paused in PlayMode; @@ -799,7 +819,7 @@ function Invoke-PauseCycle { try { Write-SoakLog -Message "Soak start: $Iterations iterations against $ResolvedProjectPath (uloop: $ResolvedUloopBin)" - Write-SoakLog -Message "restart-every=$RestartEvery force-every=$ForceEvery pause-every=$PauseEvery tests-every=$TestsEvery sleep=${SleepSeconds}s" + Write-SoakLog -Message "restart-every=$RestartEvery force-every=$ForceEvery pause-every=$PauseEvery tests-every=$TestsEvery sleep=${SleepSeconds}s command-timeout=${CommandTimeoutSeconds}s" # A freshly launched editor can be busy importing/compiling for a long time # (especially on large projects), so the preflight polls instead of From 7ad2c89cf8b43323a67a435d583f741e2a9024d8 Mon Sep 17 00:00:00 2001 From: hatayama Date: Tue, 28 Jul 2026 14:39:22 +0900 Subject: [PATCH 4/6] fix: stop one slow compile from failing a whole soak iteration A three-way parallel soak lost the same iteration in all three runs. A forced recompile outlived the project runner's own ten-minute compile wait, Unity kept compiling, and every command behind it - compile, get-logs, get-hierarchy, screenshot, execute-dynamic-code, the scene rebuild and run-tests - was refused at dispatch with UNITY_SERVER_BUSY and counted as a failure. Eight failures, one cause, and none of them a defect. A busy editor is back-pressure from work the harness itself started, and the error says Retryable: true, so it is now waited out (up to 20 tries, 30s apart) instead of counted. Only the decisive attempt reaches commands.csv, so the CSV keeps one row per intended invocation and the recorded duration stays the command's own. The cadences made this collision routine rather than unlucky: --force-every and --tests-every both default to 10, so a full rebuild was always serialised in front of the test run. Tests due on a forced-recompile iteration now run one iteration later, except on the last iteration where deferring would drop the run entirely. Also split the pause cycle's scene failure message in two. It blamed unsaved changes for every failure, including the busy-editor ones above, when DIRTY_SCENE is a specific answer from the guard. Co-Authored-By: Claude Opus 5 (1M context) --- docs/soak-testing.md | 30 ++++++++++++++++--- scripts/soak-loop.ps1 | 69 ++++++++++++++++++++++++++++++++++++++----- 2 files changed, 88 insertions(+), 11 deletions(-) diff --git a/docs/soak-testing.md b/docs/soak-testing.md index 9d60d05bff..3cb443a324 100644 --- a/docs/soak-testing.md +++ b/docs/soak-testing.md @@ -63,15 +63,37 @@ arguments; the PowerShell parameters are the same names in PascalCase, e.g. | `--sleep-seconds` | 0 | Pause between iterations | | `--out-dir` | `./uloop-soak-results/` | Results directory | +PowerShell-only parameters: + +| Parameter | Default | Meaning | +| --- | --- | --- | +| `-CommandTimeoutSeconds` | 600 | Kill bound for one uloop call. Raise it for large projects and parallel soaks (see below) | +| `-KeepCodeOptimization` | off | Leave the editor's code optimization mode alone (see below) | + Environment: `ULOOP_BIN` selects the uloop binary (default: `uloop` from `PATH`, the realistic released configuration). Point it at a `dist/` binary to soak unreleased CLI code, per the Native Go CLI Validation rules in CLAUDE.md (`dist\windows-amd64\uloop.exe` on Windows). -Every uloop call runs under a 10-minute kill watchdog. A hung IPC call — a -frozen editor that accepted the connection but never answers — is recorded as -one finite failure (exit code `124`) so the consecutive-failure recovery can -fire instead of blocking an unattended soak forever. +Every uloop call runs under a kill watchdog (10 minutes by default). A hung IPC +call — a frozen editor that accepted the connection but never answers — is +recorded as one finite failure (exit code `124`) so the consecutive-failure +recovery can fire instead of blocking an unattended soak forever. The default +is not enough for every project: a forced full recompile of one large project +took ~8 minutes on its own, and over 10 minutes with three editors compiling in +parallel, so raise `-CommandTimeoutSeconds` for runs like that. + +uloop is single-flight, so a command issued while Unity still runs an earlier +one is refused at dispatch with `UNITY_SERVER_BUSY`. That is back-pressure from +the harness's own previous command, not a defect: the PowerShell variant waits +(up to 20 tries, 30s apart) and records only the decisive attempt, so one slow +compile no longer fails every command behind it. + +Heavy operations are also kept off the same iteration: a `run-tests` due on the +same iteration as `compile --force-recompile` is deferred by one iteration +(except on the last iteration, where deferring would drop the run entirely). +Stacking them serialises a full rebuild in front of the test run and can leave +Unity compiling while the tests try to start. ## What one iteration does diff --git a/scripts/soak-loop.ps1 b/scripts/soak-loop.ps1 index 5a1bb8e39d..19aaeaff54 100644 --- a/scripts/soak-loop.ps1 +++ b/scripts/soak-loop.ps1 @@ -285,6 +285,17 @@ function Invoke-Uloop { # CSV stays the unfiltered record, the log and the summary stay signal. [hashtable]$ToleratedCounts = @{} +# uloop is single-flight: while Unity runs one tool, every other command is +# refused at dispatch with UNITY_SERVER_BUSY (Retryable: true). That is +# back-pressure from work the harness itself started - a compile that outlived +# the runner's own wait keeps the editor busy for minutes - not a defect, and +# counting it would fail a whole iteration's worth of commands over one slow +# compile. Busy attempts are waited out instead, and only the decisive attempt +# is recorded, so commands.csv keeps one row per intended invocation. +[string]$BusyErrorCode = '"ErrorCode": "UNITY_SERVER_BUSY"' +[int]$BusyRetryLimit = 20 +[int]$BusyRetryDelaySeconds = 30 + # Runs one uloop command, appends a CSV row, and returns the command result. # ToleratedPattern names the one documented outcome for this command that is # expected to fail without being a defect (see docs/soak-testing.md); a @@ -298,9 +309,29 @@ function Invoke-TimedUloop { [string]$ToleratedPattern = "" ) - [int64]$start = Get-EpochMilliseconds - [pscustomobject]$result = Invoke-Uloop -CommandArguments $CommandArguments - [int64]$end = Get-EpochMilliseconds + [int64]$start = 0 + [int64]$end = 0 + [pscustomobject]$result = $null + [bool]$waitedForEditor = $false + for ([int]$attempt = 1; $attempt -le $BusyRetryLimit; $attempt++) { + $start = Get-EpochMilliseconds + $result = Invoke-Uloop -CommandArguments $CommandArguments + $end = Get-EpochMilliseconds + + if ($result.ExitCode -eq 0 -or -not $result.Text.Contains($BusyErrorCode) -or $attempt -eq $BusyRetryLimit) { + break + } + + if (-not $waitedForEditor) { + $waitedForEditor = $true + Write-SoakLog -Message "iter=$Iteration $Label deferred: Unity is busy with an earlier command, retrying every ${BusyRetryDelaySeconds}s" + } + Start-Sleep -Seconds $BusyRetryDelaySeconds + } + + if ($waitedForEditor -and $result.ExitCode -eq 0) { + Write-SoakLog -Message "iter=$Iteration $Label ran once the editor was free" + } Add-TextLine -Path $CommandsCsv -Line ("{0},{1},{2},{3},{4},{5}" -f $start, $Iteration, $Label, $result.ExitCode, ($end - $start), $result.Bytes) @@ -741,8 +772,15 @@ function Invoke-PauseCycle { [bool]$failed = $false [pscustomobject]$sceneResult = Invoke-EnsureSoakScene -Iteration $Iteration - if ($sceneResult.ExitCode -ne 0 -or $sceneResult.Text.Contains("DIRTY_SCENE")) { - Write-SoakLog -Message "iter=$Iteration could not open the soak scene (unsaved changes?) - pause cycle failed" + # Told apart deliberately: the command failing is a defect signal whose + # payload the FAIL line above already carries, while DIRTY_SCENE is the + # guard refusing to discard someone's unsaved work. + if ($sceneResult.ExitCode -ne 0) { + Write-SoakLog -Message "iter=$Iteration soak scene could not be rebuilt - pause cycle failed" + return $true + } + if ($sceneResult.Text.Contains("DIRTY_SCENE")) { + Write-SoakLog -Message "iter=$Iteration the active scene has unsaved changes - pause cycle skipped to protect them" return $true } @@ -887,17 +925,19 @@ try { } [int]$consecutiveFails = 0 + [bool]$testsDeferred = $false for ([int]$i = 1; $i -le $Iterations; $i++) { Write-ScratchScript -Iteration $i [bool]$iterationFailed = $false + [bool]$forcedThisIteration = $ForceEvery -gt 0 -and ($i % $ForceEvery) -eq 0 # Forced recompiles rebuild every assembly - a heavier reload path # worth soaking, but far too slow to run on every iteration of a large # project. Unity may legitimately report an unknown forced result after # the domain reload (ForceCompileUnknownResult); the tool's own # guidance is to follow up with a plain compile, so only that follow-up # counts against the iteration and any other forced failure still does. - if ($ForceEvery -gt 0 -and ($i % $ForceEvery) -eq 0) { + if ($forcedThisIteration) { [pscustomobject]$forcedResult = Invoke-TimedUloop -Iteration $i -Label "compile-forced" -CommandArguments (@("compile") + $CompileWaitArguments + @("--force-recompile")) -ToleratedPattern "definitive result" if ($forcedResult.ExitCode -ne 0 -and -not $forcedResult.Tolerated) { $iterationFailed = $true @@ -928,7 +968,22 @@ try { } } - if ($TestsEvery -gt 0 -and ($i % $TestsEvery) -eq 0) { + # The default cadences share their multiples, so tests used to land on + # the same iteration as the forced recompile. Stacking them serialises + # a full project rebuild in front of the test run, and while that + # rebuild is still running inside Unity the test run cannot start at + # all. Testing one iteration later keeps both measurable on their own. + # The last iteration is the exception: deferring there would drop the + # test run entirely, which is worse than running it stacked. + [bool]$testsDue = $TestsEvery -gt 0 -and ((($i % $TestsEvery) -eq 0) -or $testsDeferred) + if ($testsDue -and $forcedThisIteration -and $i -lt $Iterations) { + $testsDeferred = $true + $testsDue = $false + Write-SoakLog -Message "iter=$i tests deferred one iteration to keep them apart from the forced recompile" + } + + if ($testsDue) { + $testsDeferred = $false # Red project tests are not a soak failure - the harness measures # whether uloop transported and completed the run, so only a # missing test report (no TestCount in the response) counts against From 4e0f4fdef3dab1a67f22d05da92398a6f1148925 Mon Sep 17 00:00:00 2001 From: hatayama Date: Tue, 28 Jul 2026 20:52:33 +0900 Subject: [PATCH 5/6] feat: let the soak raise the compile wait now that the runner allows it The parallel soak that produced issue #2032 lost an iteration because a forced recompile outlived the runner's fixed 10-minute compile wait. That wait is configurable as of #2036, so -CompileWaitTimeoutSeconds now forwards --compile-wait-timeout-seconds to every compile. Support is detected from compile --help, the same way the domain-reload flag already is, because the soak has to keep running against whichever runner a project pins; an older runner logs the request as ignored instead of failing on an unknown flag. Passing the value also lifts the kill watchdog above it, since a watchdog at or below the compile wait would kill the command before the CLI could report COMPILE_WAIT_TIMEOUT and turn a diagnosable timeout into a bare exit 124. Verified both branches against a stub runner (flag present and absent) and confirmed the real runner accepts the flag. Co-Authored-By: Claude Opus 5 (1M context) --- docs/soak-testing.md | 9 +++++++++ scripts/soak-loop.ps1 | 26 +++++++++++++++++++++++++- 2 files changed, 34 insertions(+), 1 deletion(-) diff --git a/docs/soak-testing.md b/docs/soak-testing.md index 3cb443a324..fc3f7dce45 100644 --- a/docs/soak-testing.md +++ b/docs/soak-testing.md @@ -68,6 +68,7 @@ PowerShell-only parameters: | Parameter | Default | Meaning | | --- | --- | --- | | `-CommandTimeoutSeconds` | 600 | Kill bound for one uloop call. Raise it for large projects and parallel soaks (see below) | +| `-CompileWaitTimeoutSeconds` | 0 (runner default) | Passed to every compile as `--compile-wait-timeout-seconds` when the pinned runner accepts it | | `-KeepCodeOptimization` | off | Leave the editor's code optimization mode alone (see below) | Environment: `ULOOP_BIN` selects the uloop binary (default: `uloop` from @@ -83,6 +84,14 @@ is not enough for every project: a forced full recompile of one large project took ~8 minutes on its own, and over 10 minutes with three editors compiling in parallel, so raise `-CommandTimeoutSeconds` for runs like that. +A compile that outlives the runner's own wait returns `COMPILE_WAIT_TIMEOUT` +while Unity keeps compiling. Runners from `--compile-wait-timeout-seconds` +onwards let that wait be raised: pass `-CompileWaitTimeoutSeconds` and the +harness appends the flag to every compile, lifting its kill watchdog above the +new wait so a timeout can still be reported rather than killed. Against an +older pinned runner the request is logged and ignored. Values above 1200 exceed +Unity's 20-minute result retention, which weakens the post-timeout recovery. + uloop is single-flight, so a command issued while Unity still runs an earlier one is refused at dispatch with `UNITY_SERVER_BUSY`. That is back-pressure from the harness's own previous command, not a defect: the PowerShell variant waits diff --git a/scripts/soak-loop.ps1 b/scripts/soak-loop.ps1 index 19aaeaff54..1b96105de9 100644 --- a/scripts/soak-loop.ps1 +++ b/scripts/soak-loop.ps1 @@ -61,6 +61,11 @@ param( # especially for parallel soaks: a full recompile of one large project took # over 10 minutes with three editors compiling at once. [int]$CommandTimeoutSeconds = 600, + # Passed to every compile as --compile-wait-timeout-seconds when the pinned + # runner accepts it (0 = leave the runner's own default alone). Raise it on + # a project whose forced recompile outlives the runner's 10-minute wait; + # above 1200 the runner warns that Unity may drop the retained result. + [int]$CompileWaitTimeoutSeconds = 0, # Pause between iterations. [int]$SleepSeconds = 0, # Results directory (default: .\uloop-soak-results\). @@ -85,6 +90,12 @@ if (-not (Test-Path -LiteralPath (Join-Path $ResolvedProjectPath "ProjectSetting if ($TestsEvery -gt 0 -and [string]::IsNullOrWhiteSpace($TestAssembly)) { throw "Error: -TestAssembly is required when tests are enabled (pass -TestsEvery 0 to skip tests; running the full suite of a large project is not a safe default)" } +# A kill watchdog at or below the compile wait would end the command before the +# CLI could report COMPILE_WAIT_TIMEOUT, turning a diagnosable timeout into a +# bare exit 124, so the watchdog is lifted over it instead of failing the run. +if ($CompileWaitTimeoutSeconds -gt 0 -and $CommandTimeoutSeconds -le $CompileWaitTimeoutSeconds) { + $CommandTimeoutSeconds = $CompileWaitTimeoutSeconds + 120 +} # Start-Process needs a real executable path, and resolving once keeps every # iteration from re-searching PATH. @@ -887,8 +898,9 @@ try { # explicit --wait-for-domain-reload (off by default), older ones wait by # default and only expose --no-wait-for-domain-reload. Detect which flavor # the pinned runner speaks. + [string]$compileHelp = (Invoke-Uloop -CommandArguments @("compile", "--help")).Text [string[]]$CompileWaitArguments = @() - if ((Invoke-Uloop -CommandArguments @("compile", "--help")).Text -match '(?m)^\s*--wait-for-domain-reload') { + if ($compileHelp -match '(?m)^\s*--wait-for-domain-reload') { $CompileWaitArguments = @("--wait-for-domain-reload") } if ($CompileWaitArguments.Count -gt 0) { @@ -898,6 +910,18 @@ try { Write-SoakLog -Message "compile wait flag: (runner waits by default)" } + # Runners predating the configurable wait reject the flag outright, and the + # soak has to keep working against whichever runner the project pins. + if ($CompileWaitTimeoutSeconds -gt 0) { + if ($compileHelp -match '(?m)^\s*--compile-wait-timeout-seconds') { + $CompileWaitArguments += @("--compile-wait-timeout-seconds", "$CompileWaitTimeoutSeconds") + Write-SoakLog -Message "compile wait timeout: ${CompileWaitTimeoutSeconds}s (watchdog ${CommandTimeoutSeconds}s)" + } + else { + Write-SoakLog -Message "compile wait timeout: ignored - the pinned runner has no --compile-wait-timeout-seconds" + } + } + [int]$TickerLine = 0 if ($PauseEvery -gt 0) { Write-TickerScripts From 0d964fd07b41029d492439e1f7d0fd7381ef96d7 Mon Sep 17 00:00:00 2001 From: hatayama Date: Tue, 28 Jul 2026 23:05:13 +0900 Subject: [PATCH 6/6] fix: re-apply Debug code optimization after every editor restart Three parallel soaks all failed to arm a pause point on iteration 10 while iteration 5 had succeeded, and the failure payload matched the shape of a Release-mode rejection even though the run had switched the editor to Debug at setup. Measured directly: Debug before `uloop launch -r`, Release after it. The setting does not survive the restart, so every pause cycle following the iteration-5 restart was arming against a Release editor. The forced recompile that immediately preceded the failure was not involved - an earlier run had already forced a recompile and armed successfully in the same iteration, with no restart in between. Debug is now re-applied after the scheduled and the recovery restart, beside the scene rebuild those paths already do, without disturbing the mode recorded for the final restore. Also let a command declare more than one tolerated outcome. A plain compile issued after a forced one that outlived the runner's wait now attaches to it and returns the forced compile's own unknown-result message; the harness only knew the collision message, so it counted that recovery as a failure. The matched pattern is reported back so the retry still fires for a collision and not for an attached result. Co-Authored-By: Claude Opus 5 (1M context) --- docs/soak-testing.md | 7 ++++- scripts/soak-loop.ps1 | 72 +++++++++++++++++++++++++++++++++++-------- 2 files changed, 65 insertions(+), 14 deletions(-) diff --git a/docs/soak-testing.md b/docs/soak-testing.md index fc3f7dce45..6b1534a6de 100644 --- a/docs/soak-testing.md +++ b/docs/soak-testing.md @@ -127,7 +127,12 @@ keeps under **Debug** code optimization. Against a Release editor every arm call fails on that precondition, so the whole PlayMode cycle would soak a guaranteed failure. When `-PauseEvery` > 0, `soak-loop.ps1` reads the editor's mode at setup, switches it to Debug if needed, and restores the original mode -when the run ends. Both switches trigger a full recompile — the setup compile +when the run ends. + +The mode does **not** survive `uloop launch -r`: an editor restarted mid-soak +comes back on the project's own setting, measured going from Debug to Release +across one restart. Debug is therefore re-applied after every scheduled and +recovery restart, the same way the soak scene is rebuilt there. Both switches trigger a full recompile — the setup compile absorbs the first one by retrying past `Compilation is already in progress`, and the restoring recompile runs in the background after the summary. Pass `-KeepCodeOptimization` to leave the setting alone — expect every pause-point diff --git a/scripts/soak-loop.ps1 b/scripts/soak-loop.ps1 index 1b96105de9..0e06274d54 100644 --- a/scripts/soak-loop.ps1 +++ b/scripts/soak-loop.ps1 @@ -307,17 +307,25 @@ function Invoke-Uloop { [int]$BusyRetryLimit = 20 [int]$BusyRetryDelaySeconds = 30 +# Documented outcomes that are expected to fail without being a defect. +# CompileCollisionPattern is the only one worth retrying - the others describe +# a finished command whose result is simply not a clean success. +[string]$CompileCollisionPattern = "Compilation is already in progress" +[string]$ForcedUnknownResultPattern = "definitive result" + # Runs one uloop command, appends a CSV row, and returns the command result. -# ToleratedPattern names the one documented outcome for this command that is +# ToleratedPatterns names the documented outcomes for this command that are # expected to fail without being a defect (see docs/soak-testing.md); a -# non-zero exit whose payload contains it is reported as TOLERATED, and the +# non-zero exit whose payload contains one is reported as TOLERATED, and the # returned Tolerated flag tells the caller not to fail the iteration. +# ToleratedPattern reports which one matched, so a caller can react to a +# specific outcome rather than to tolerance in general. function Invoke-TimedUloop { param( [int]$Iteration, [string]$Label, [string[]]$CommandArguments, - [string]$ToleratedPattern = "" + [string[]]$ToleratedPatterns = @() ) [int64]$start = 0 @@ -347,8 +355,16 @@ function Invoke-TimedUloop { Add-TextLine -Path $CommandsCsv -Line ("{0},{1},{2},{3},{4},{5}" -f $start, $Iteration, $Label, $result.ExitCode, ($end - $start), $result.Bytes) [bool]$tolerated = $false + [string]$matchedPattern = "" if ($result.ExitCode -ne 0) { - $tolerated = (-not [string]::IsNullOrEmpty($ToleratedPattern)) -and $result.Text.Contains($ToleratedPattern) + foreach ($pattern in $ToleratedPatterns) { + if ((-not [string]::IsNullOrEmpty($pattern)) -and $result.Text.Contains($pattern)) { + $tolerated = $true + $matchedPattern = $pattern + break + } + } + [string]$excerpt = $result.Text if ($excerpt.Length -gt 200) { $excerpt = $excerpt.Substring(0, 200) @@ -373,6 +389,7 @@ function Invoke-TimedUloop { Text = $result.Text Bytes = $result.Bytes Tolerated = $tolerated + ToleratedPattern = $matchedPattern } } @@ -398,8 +415,12 @@ function Invoke-CompileWithRetry { $attemptLabel = "$Label-retry" } - $result = Invoke-TimedUloop -Iteration $Iteration -Label $attemptLabel -CommandArguments $CompileArguments -ToleratedPattern "Compilation is already in progress" - if ($result.ExitCode -eq 0 -or -not $result.Tolerated) { + # A plain compile issued after a forced one that outlived the runner's + # wait attaches to it and returns the forced compile's own unknown + # result. That is the recovery working, not a collision, so it is + # tolerated but must not be retried. + $result = Invoke-TimedUloop -Iteration $Iteration -Label $attemptLabel -CommandArguments $CompileArguments -ToleratedPatterns @($CompileCollisionPattern, $ForcedUnknownResultPattern) + if ($result.ExitCode -eq 0 -or $result.ToleratedPattern -ne $CompileCollisionPattern) { return $result } @@ -622,18 +643,39 @@ function Wait-Editor { # mode is remembered here and restored when the run ends. [string]$PreviousCodeOptimization = "" -function Initialize-CodeOptimization { - if ($KeepCodeOptimization) { +# Re-applied after every editor restart, not just at setup: the mode does not +# survive `uloop launch -r`. An editor that comes back on the project's own +# Release setting cannot arm pause points at all, which silently turned every +# post-restart pause cycle into a failure until this was found. +function Set-DebugCodeOptimization { + param( + [int]$Iteration + ) + + if ($KeepCodeOptimization -or $PauseEvery -le 0) { return } - [pscustomobject]$result = Invoke-TimedUloop -Iteration 0 -Label "code-optimization" -CommandArguments @( + [pscustomobject]$result = Invoke-TimedUloop -Iteration $Iteration -Label "code-optimization" -CommandArguments @( "execute-dynamic-code", "--code", 'UnityEditor.Compilation.CodeOptimization previous = UnityEditor.Compilation.CompilationPipeline.codeOptimization; if (previous != UnityEditor.Compilation.CodeOptimization.Debug) { UnityEditor.Compilation.CompilationPipeline.codeOptimization = UnityEditor.Compilation.CodeOptimization.Debug; } return previous.ToString();' ) if ($result.ExitCode -ne 0) { - Write-SoakLog -Message "Could not set Debug code optimization - pause points will fail while the editor stays on Release." + Write-SoakLog -Message "iter=$Iteration could not set Debug code optimization - pause points will fail while the editor stays on Release." + return $null + } + + return $result +} + +function Initialize-CodeOptimization { + if ($KeepCodeOptimization) { + return + } + + [pscustomobject]$result = Set-DebugCodeOptimization -Iteration 0 + if ($null -eq $result) { return } @@ -962,7 +1004,7 @@ try { # guidance is to follow up with a plain compile, so only that follow-up # counts against the iteration and any other forced failure still does. if ($forcedThisIteration) { - [pscustomobject]$forcedResult = Invoke-TimedUloop -Iteration $i -Label "compile-forced" -CommandArguments (@("compile") + $CompileWaitArguments + @("--force-recompile")) -ToleratedPattern "definitive result" + [pscustomobject]$forcedResult = Invoke-TimedUloop -Iteration $i -Label "compile-forced" -CommandArguments (@("compile") + $CompileWaitArguments + @("--force-recompile")) -ToleratedPatterns @($ForcedUnknownResultPattern) if ($forcedResult.ExitCode -ne 0 -and -not $forcedResult.Tolerated) { $iterationFailed = $true } @@ -1012,7 +1054,7 @@ try { # whether uloop transported and completed the run, so only a # missing test report (no TestCount in the response) counts against # the iteration. - [pscustomobject]$testsResult = Invoke-TimedUloop -Iteration $i -Label "run-tests" -CommandArguments @("run-tests", "--test-mode", "EditMode", "--filter-type", "assembly", "--filter-value", $TestAssembly) -ToleratedPattern '"TestCount"' + [pscustomobject]$testsResult = Invoke-TimedUloop -Iteration $i -Label "run-tests" -CommandArguments @("run-tests", "--test-mode", "EditMode", "--filter-type", "assembly", "--filter-value", $TestAssembly) -ToleratedPatterns @('"TestCount"') if ($testsResult.ExitCode -ne 0 -and -not $testsResult.Tolerated) { $iterationFailed = $true } @@ -1026,6 +1068,9 @@ try { exit 1 } + # The editor comes back on the project's own code optimization mode. + $null = Set-DebugCodeOptimization -Iteration $i + # The reopened startup scene may be auto-dirtied by project # tooling, which would trip the DIRTY_SCENE guard on the next pause # cycle. Right after our own restart that dirt cannot be user work, @@ -1054,7 +1099,8 @@ try { exit 1 } - # Same post-restart scene restore as the scheduled restart path. + # Same post-restart repair as the scheduled restart path. + $null = Set-DebugCodeOptimization -Iteration $i if ($PauseEvery -gt 0) { if ((Invoke-TimedUloop -Iteration $i -Label "scene-restore" -CommandArguments @("execute-dynamic-code", "--code-file", $SceneSetupForceFile)).ExitCode -ne 0) { Write-SoakLog -Message "iter=$i post-recovery scene restore failed"