From a6042cf6800d2a4090759eea2fdda0ddbf515f0a Mon Sep 17 00:00:00 2001 From: San Lee <295248956+sanlee-ys@users.noreply.github.com> Date: Tue, 18 Aug 2026 08:57:35 -0400 Subject: [PATCH] soak: what the long-running modes cost after the first minute, measured Everything the harness measured before this commit was one call. The listener modes and the council room do not stop after one call, and no gate measured whether an idle process holds a constant amount of memory across a day. tools/soak.ps1 is the instrument. Residency mode samples one process tree at an interval and records the working set, the private bytes, the handle count, the live CPU and the child count. Per-fire mode starts a short-lived process many times, because the statusline has no residency to sample. Summary mode renders a finished JSONL file again, so the samples stay the artifact. The script uses Win32_Process rather than Get-Counter, because the counter set names of Get-Counter are localized and its instances carry process names instead of pids. It guards against pid reuse on every sample. It prints a median-based drift beside the least-squares slope, and it prints an absent figure as `--` rather than as 0. The first measurement is recorded in design.md, in the section 5 area. Both idle listeners held 128 handles and 1 process across 210 samples over 34.8 min, with a robust drift of 0.00 MiB and idle CPU under the measurement floor. The statusline ran 1000 fires at a median of 20.9 ms with no drift. Its tail is the finding: 6 fires of 1000 blocked for about 2.03 s while their CPU stayed normal, so the process waited and did not compute. The arm records that result and does not name a cause. The council arm is owed. A room needs a real terminal, and its seats read credentials from the real home directory, so it cannot run headlessly. The amendment states the operator command. Co-Authored-By: Claude Fable 5 --- docs/design.md | 147 +++++++++ tools/soak.ps1 | 812 +++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 959 insertions(+) create mode 100644 tools/soak.ps1 diff --git a/docs/design.md b/docs/design.md index 6d123b8..51ff2e1 100644 --- a/docs/design.md +++ b/docs/design.md @@ -2518,6 +2518,153 @@ it with more than it does: - **Not the other two gauges.** `internal/hud` and `internal/council` are TUI surfaces; the rule does not apply to them and the gate does not look at them. +**Amendment, 2026-08-18: what the long-running modes cost after the first minute, measured.** +Everything above measures one call, and the 2026-08-16 timing step measures 15 of them. +Three modes do not stop after one call. `telltale events` and `telltale otel grok` are +listeners that an operator starts once and leaves. `telltale council` holds a room and one +long-lived child for each seat. A benchmark cannot answer the question these modes raise: +does an idle process hold a constant amount of memory across a day? Nothing in this +repository measured that. This amendment records the instrument and the first measurement. + +**The instrument is `tools/soak.ps1`, and it is not a gate.** It has three modes. Residency +mode samples one process tree at an interval, and it records the working set, the private +bytes, the handle count, the live CPU and the child count. Per-fire mode starts a +short-lived process many times and records each run, because `telltale statusline` has no +residency to sample. Summary mode renders a finished JSONL file again, so a later reader +re-reads an arm without a second soak. The samples are the artifact, and a table is one +view of them. Re-read a finished arm with +`.\tools\soak.ps1 -Summarize "$env:TEMP\soak-events.jsonl"`. + +Three decisions in that script are load-bearing, and each one comes from a measured +failure: + +- **`Win32_Process`, and never `Get-Counter`.** The counter set names of `Get-Counter` are + localized, so `\Process(*)\Working Set` does not resolve on a Windows installation in + another language. Its instances also carry process names, so three `telltale.exe` + processes arrive as `telltale`, `telltale#1` and `telltale#2`, with no stable relation to + a pid and no parent data. A tree soak needs the parent data. One CIM query also serves a + whole sample at any tree size. +- **The summary prints a median-based drift beside the least-squares slope.** One outlier + moves a slope, and no outlier moves a median. Arm C below proves why that matters: its + slope and its drift disagree, and the drift is the honest figure. +- **An absent figure prints `--`, and never `0`.** `PeakWorkingSet64` reads 0 after a + process exits, and PowerShell evaluates `$null / 1MB` as 0. Both defects produced a + measured-looking zero in the first smoke arms. That is the zero-vs-absent collapse + ADR-001 forbids, inside the instrument that exists to find drift. + +**Conditions.** The reference workstation: Intel i7-7700K (4 cores, 8 logical threads), +Windows 11, Windows PowerShell 5.1.26100.9168, Go 1.26.5. The binary came from `d024f03`. +Both listeners bound non-default loopback ports (14519 and 14318), and every arm ran with +`USERPROFILE` redirected to a scratch directory. The redirect is verified in both +directions: the listeners wrote their stores under the scratch home, and +`~/.telltale` held no file newer than the previous day when the arms ended. No arm read or +wrote a real store. Arms A and B ran concurrently, and arm C ran on the same machine while +they sampled. + +**Arm A — `telltale events`, idle, 34.8 min, 210 samples at 10 s.** + +| metric | min | median | p95 | max | slope/hour | +|---|---|---|---|---|---| +| working set | 9.14 MiB | 9.23 MiB | 9.23 MiB | 9.25 MiB | +0.11 MiB | +| private bytes | 45.32 MiB | 45.32 MiB | 45.35 MiB | 45.36 MiB | -0.02 MiB | +| handles | 128 | 128 | 128 | 128 | 0.0 | +| processes | 1 | 1 | 1 | 1 | 0.0 | + +Robust drift: working set 0.00 MiB, private bytes 0.00 MiB, handles 0.0, processes 0.0. +CPU over 209 comparable intervals, 0 dropped: min, median and max all 0.000%, total 0.02 s. + +**Arm B — `telltale otel grok`, idle, 34.8 min, 210 samples at 10 s.** + +| metric | min | median | p95 | max | slope/hour | +|---|---|---|---|---|---| +| working set | 9.02 MiB | 9.11 MiB | 9.11 MiB | 9.13 MiB | +0.11 MiB | +| private bytes | 45.15 MiB | 45.15 MiB | 45.18 MiB | 45.20 MiB | -0.02 MiB | +| handles | 128 | 128 | 128 | 128 | 0.0 | +| processes | 1 | 1 | 1 | 1 | 0.0 | + +Robust drift: working set 0.00 MiB, private bytes 0.00 MiB, handles 0.0, processes 0.0. +CPU over 209 comparable intervals, 0 dropped: min, median and max all 0.000%, total 0.00 s. + +**Arm C — `telltale statusline`, 1000 fires.** Every fire exited 0, and every fire rendered +the `Opus` marker that `ci.yml` asserts on its own 15 samples. + +| metric | min | median | p95 | max | slope/1k fires | +|---|---|---|---|---|---| +| wall ms | 20.0 | 20.9 | 26.0 | 2035.7 | -41.2 | +| cpu ms | 0.0 | 15.6 | 31.3 | 93.8 | 0.0 | +| peak working set | 9.32 MiB | 9.43 MiB | 9.61 MiB | 9.63 MiB | -0.01 MiB | +| peak private | 44.90 MiB | 45.24 MiB | 45.44 MiB | 46.25 MiB | -0.01 MiB | + +Robust drift: wall -0.2 ms, cpu 0.0 ms, peak working set 0.00 MiB, peak private 0.00 MiB. +p99 is 55.23 ms. 11 fires passed 50 ms, and 6 of those passed 100 ms. The cpu figure is +quantized to the 15.625 ms scheduler tick, so only its distribution carries information. + +**What the three arms found.** + +1. **Neither listener leaks.** The handle count and the process count held exactly constant + across 210 samples of each arm. Both working-set slopes read +0.11 MiB/hour, and that + figure is smaller than the 0.11 MiB total spread of the same arm. The robust drift is + 0.00 MiB on every metric. The slope is therefore the noise of the arm, and it is not a + trend. Each arm ran 34.8 min, so every hourly slope above is a 1.7x extrapolation. +2. **Idle CPU is under the measurement floor.** Every comparable interval read 0.000%, and + no interval was dropped. The two listeners spent 0.02 s and 0.00 s of CPU across 35 + minutes. An idle listener costs nothing this instrument can measure. +3. **The statusline cost does not drift, and its tail is the finding.** 6 fires of 1000 + blocked for 2019-2036 ms, while their CPU stayed at the usual 15-31 ms. The process + waited; it did not compute. The -41.2 ms per 1000 fires slope comes from those 6 samples + alone, and the median-based drift reads -0.2 ms across the same run. This is the + disagreement the drift figure exists to expose, and the drift is the honest one. **This + arm does not name a cause.** Two residency arms polled `Win32_Process` on the same + machine throughout, so the condition is recorded and the cause is not claimed. A + statusline fires on every prompt, so a 2 s stall earns a later arm on an idle machine. + +**What this measurement does NOT assert**, stated so a later reader does not credit it with +more than it did: + +- **Not a CI gate.** `tools/soak.ps1` is an operator instrument. No workflow runs it, and a + leak introduced tomorrow turns nothing red. +- **Not a multi-hour figure.** 35 minutes is the arm. A leak under this arm's noise floor + stays invisible, and every hourly slope is an extrapolation. +- **Not a loaded listener.** Both listeners sat idle, and no hook posted to either port. A + listener under traffic is a different measurement. +- **Not the council room.** That arm is owed, and the next paragraph states it. +- **Not macOS.** The instrument uses PowerShell and `Win32_Process`, so it is Windows-only. + +**Owed: the council arm, which an operator must run.** The room cannot be soaked +headlessly, for two reasons that belong to the mode rather than to the script. The room is +a TUI, so it needs a real terminal. Its seats are live vendor CLIs that read their +credentials from the real home directory, so this arm cannot use the redirected +`USERPROFILE` that isolated the other three arms. The room is also the arm that matters +most, because it is the only mode whose process count can move: each persistent seat is a +long-lived child, and residency mode counts the whole tree. + +Terminal 1 opens the room and leaves it idle. `--read` seats every vendor and forbids every +write, which is what an unattended 35-minute arm needs: + +```powershell +cd C:\Users\sanle\code\telltale +.\telltale.exe council --read +``` + +Terminal 2 resolves the room's pid, then samples the tree. `-Name telltale` is wrong here, +because it fails whenever more than one `telltale.exe` runs: + +```powershell +cd C:\Users\sanle\code\telltale +$room = @(Get-CimInstance Win32_Process -Filter "Name='telltale.exe'" | + Where-Object { $_.CommandLine -match '\bcouncil\b' }) +$room.Count # must print 1 before the next command runs +powershell.exe -NoProfile -ExecutionPolicy Bypass -File .\tools\soak.ps1 ` + -Id $room[0].ProcessId -Label council-idle ` + -Out "$env:TEMP\soak-council.jsonl" -IntervalSeconds 10 -DurationMinutes 35 +``` + +The arm prints its own table when it ends. Read the same file again at any later time with: + +```powershell +powershell.exe -NoProfile -ExecutionPolicy Bypass -File .\tools\soak.ps1 -Summarize "$env:TEMP\soak-council.jsonl" +``` + ## 6. Open design questions diff --git a/tools/soak.ps1 b/tools/soak.ps1 new file mode 100644 index 0000000..3fc1f39 --- /dev/null +++ b/tools/soak.ps1 @@ -0,0 +1,812 @@ +<# +.SYNOPSIS + Sample a process tree for hours, and report whether the tree drifted. + +.DESCRIPTION + This script is the instrument behind design.md §5.1. `telltale council` holds a + process tree, which is the room plus one long-lived child for each persistent + seat. `telltale events` and `telltale otel grok` are foreground listeners that + an operator starts once and leaves. No gate in this repository measures what + these modes cost after the first minute. A benchmark measures one call. It + cannot measure whether an idle room increases its memory across a day. This + script measures the second property. + + The script has three modes, because a soak has three shapes: + + - RESIDENCY (`-Id` or `-Name`) samples one process tree at an interval. It + records working set, private bytes, handle count, live CPU and child count. + Use this mode for a long-lived process. + - PER-FIRE (`-FireCommand`) starts a short-lived process many times and + records each run. `telltale statusline` starts one process for each prompt, + so it has no residency to sample. Two properties can change: the cost of one + fire, and the STABILITY of that cost across many fires. A sample of a + process that lives 30 ms shows one arbitrary state. + - SUMMARY (`-Summarize`) renders a finished JSONL file again. The samples are + the artifact and the table is one view of them, so a later reader can plot + the file or read a new table without a second soak. + + WHAT THE OUTPUT IS FOR. One memory figure proves nothing. At a single sample, + an allocator that keeps its pages looks the same as a leak. The summary + therefore prints min, median, p95 and max, and it also prints two trend + figures across the arm. A constant workload with an increasing trend is the + condition this script must find. A large but constant figure is a size, and it + is not a leak. The script measures and does not judge: a verdict belongs in + design.md, beside the conditions of the measurement. + + ONE CIM QUERY FOR EACH SAMPLE. `Get-CimInstance Win32_Process` returns every + process with the five fields this script needs, and with the parent id that + builds the tree. One sample therefore costs one query at any tree size. One + `Get-Process` call for each pid would cost one call for each process, and it + would still need the CIM query for the parent data. + + THE SCRIPT DOES NOT USE `Get-Counter`, which is the obvious tool. Two measured + properties disqualify it. Its counter set names are LOCALIZED, so + `\Process(*)\Working Set` does not resolve on a Windows installation in + another language, and an instrument that fails on the operator's machine has + no value. Its instances also carry process NAMES, so several `telltale.exe` + processes arrive as `telltale`, `telltale#1` and `telltale#2`, with no stable + relation to a pid and no parent data. A tree soak needs the parent data. + `Win32_Process` is keyed on the pid, it reports the parent, and it is + independent of the language. + + PID REUSE. Windows uses a process id again after a process exits, and a soak + runs long enough to meet that condition. Each sample builds the tree again + from the parent data, and it accepts a child only when the creation time of + the child is not earlier than the creation time of the parent. The script + checks the root more strictly. It records the creation time of the root at the + start. If that creation time changes, the arm stops. The alternative is a + silent measurement of a different process that received the same pid. + + CPU BELONGS TO THE LIVE SET, AND NOT TO THE LIFETIME OF THE TREE. `cpu_s` adds + the kernel time and the user time of the processes that are alive AT THAT + SAMPLE. When a child exits, its time leaves the total. `cpu_s` can therefore + decrease, and a simple delta can become negative. Each sample carries + `set_changed`, which is true when the pid set is different from the pid set of + the previous sample. The summary excludes those intervals from the idle-CPU + figure. It does not report a negative value, and it does not report an + invented zero. A vendor process that starts for each turn makes this condition + usual, and not exceptional. + + Windows PowerShell 5.1 is the target (ADR-002: Windows is the primary + platform, and 5.1 is what a Windows 11 box has before anyone installs + anything). No ternary, no null-coalescing, no `-AsHashtable`, and `-Depth` is + passed to every `ConvertTo-Json` because 5.1 defaults it to 2 and silently + truncates deeper objects. It runs unchanged on PowerShell 7. + +.PARAMETER Id + Process id to root the tree at. Residency mode. + +.PARAMETER Name + Process name to root the tree at, without `.exe`. Residency mode. It must + match exactly one running process; several matches is an error rather than a + guess, because picking one would produce a labelled measurement of an + arbitrary process. + +.PARAMETER FireCommand + Executable to run repeatedly. Per-fire mode. + +.PARAMETER FireArgs + Arguments passed to `-FireCommand` on every fire. + +.PARAMETER FireStdin + File piped to the fire's stdin. `telltale statusline` reads its payload there. + +.PARAMETER FireExpect + Regex every fire's stdout must match. A crash is fast, so an arm with no such + assertion reports a binary that broke halfway as an improvement. `ci.yml` + makes the same check on its 15 samples. + +.PARAMETER Fires + How many times to fire. Per-fire mode. + +.PARAMETER Summarize + Re-render a finished JSONL and exit. Summary mode. + +.PARAMETER Out + JSONL path the samples append to. One JSON object per line, `schema_version` + 1. Both modes write to the same file shape with a different `kind`. + +.PARAMETER Label + Arm name recorded on every sample, so several arms can share a plot. + +.PARAMETER IntervalSeconds + Seconds between residency samples. Default 10. + +.PARAMETER DurationMinutes + How long the residency arm runs. Default 35. + +.EXAMPLE + # the idle event sink, on a non-default port and a redirected home + $env:USERPROFILE = 'C:\soak\home' + $p = Start-Process .\telltale.exe -ArgumentList 'events','-addr','127.0.0.1:14519' -PassThru + .\tools\soak.ps1 -Id $p.Id -Label events-idle -Out soak-events.jsonl -DurationMinutes 35 + +.EXAMPLE + # the statusline, which has no residency to sample. -FireExpect is not + # optional in practice: it is the assertion that separates a fast render from + # a fast crash, and `Opus` is the same marker ci.yml's 15-sample step asserts. + .\tools\soak.ps1 -FireCommand .\telltale.exe -FireArgs 'statusline' ` + -FireStdin internal\statusline\testdata\full.json -FireExpect Opus ` + -Fires 1000 -Label statusline-fire -Out soak-statusline.jsonl + +.EXAMPLE + .\tools\soak.ps1 -Summarize soak-events.jsonl +#> + +[CmdletBinding(DefaultParameterSetName = 'Residency')] +param( + [Parameter(ParameterSetName = 'Residency')] + [int] $Id, + + [Parameter(ParameterSetName = 'Residency')] + [string] $Name, + + [Parameter(ParameterSetName = 'Fire', Mandatory = $true)] + [string] $FireCommand, + + [Parameter(ParameterSetName = 'Fire')] + [string[]] $FireArgs = @(), + + [Parameter(ParameterSetName = 'Fire')] + [string] $FireStdin, + + [Parameter(ParameterSetName = 'Fire')] + [string] $FireExpect, + + [Parameter(ParameterSetName = 'Fire')] + [int] $Fires = 100, + + [Parameter(ParameterSetName = 'Summary', Mandatory = $true)] + [string] $Summarize, + + [Parameter(ParameterSetName = 'Residency')] + [Parameter(ParameterSetName = 'Fire')] + [string] $Out, + + [Parameter(ParameterSetName = 'Residency')] + [Parameter(ParameterSetName = 'Fire')] + [string] $Label = 'arm', + + [Parameter(ParameterSetName = 'Residency')] + [int] $IntervalSeconds = 10, + + [Parameter(ParameterSetName = 'Residency')] + [int] $DurationMinutes = 35 +) + +$ErrorActionPreference = 'Stop' +$SchemaVersion = 1 + +# ---------------------------------------------------------------- writing + +$script:Utf8NoBom = New-Object System.Text.UTF8Encoding($false) + +function Write-Sample { + param([string] $Path, $Record) + + $line = $Record | ConvertTo-Json -Depth 5 -Compress + if ($Path) { + [System.IO.File]::AppendAllText($Path, $line + "`r`n", $script:Utf8NoBom) + } else { + Write-Output $line + } +} + +# ---------------------------------------------------------------- statistics + +function Get-Median { + param([double[]] $Values) + + if ($Values.Count -eq 0) { return $null } + $sorted = $Values | Sort-Object + $mid = [int][math]::Floor($sorted.Count / 2) + if ($sorted.Count % 2 -eq 1) { return $sorted[$mid] } + return ($sorted[$mid - 1] + $sorted[$mid]) / 2 +} + +function Get-Percentile { + <# + Nearest-rank percentile. The distribution tail carries the information in + a soak: one fire in 1000 took 3.6 s against a median of 31 ms. A maximum + alone cannot show whether that was one sample or 100 samples. §7.18 + reports p50 and p95 for the same reason, so this summary matches it. + #> + param([double[]] $Values, [double] $P) + + if ($Values.Count -eq 0) { return $null } + $sorted = $Values | Sort-Object + $rank = [int][math]::Ceiling(($P / 100) * $sorted.Count) - 1 + if ($rank -lt 0) { $rank = 0 } + if ($rank -ge $sorted.Count) { $rank = $sorted.Count - 1 } + return $sorted[$rank] +} + +function Get-HalfDrift { + <# + Median of the second half minus median of the first half. + + The least-squares slope beside it is the usual unit for a leak, and it has + one bad property on this data: one outlier moves it. The first statusline + arm fitted +32.4 ms for each 1000 fires, and ONE fire in 1000 that took + 3.6 s caused almost all of that figure. A reader would report a binary that + drifts, from one delay in the scheduler. An outlier cannot move a median. + When the two figures disagree, the distribution tail causes the slope, and + not a trend. The script reports this figure with the slope, and never + instead of the slope. + #> + param([double[]] $Values) + + if ($Values.Count -lt 6) { return $null } + $half = [int][math]::Floor($Values.Count / 2) + $first = Get-Median -Values ([double[]]$Values[0..($half - 1)]) + $second = Get-Median -Values ([double[]]$Values[$half..($Values.Count - 1)]) + return $second - $first +} + +function Get-Slope { + <# + Least-squares slope of y over x, in y-units for each x-unit. The function + returns $null for fewer than three points, and for a degenerate x span. A + line through two samples shows no trend, and a report of one would be the + estimate presented as a measurement that this repository refuses. + #> + param([double[]] $X, [double[]] $Y) + + $n = $X.Count + if ($n -lt 3 -or $n -ne $Y.Count) { return $null } + + $meanX = ($X | Measure-Object -Average).Average + $meanY = ($Y | Measure-Object -Average).Average + $num = 0.0 + $den = 0.0 + for ($i = 0; $i -lt $n; $i++) { + $dx = $X[$i] - $meanX + $num += $dx * ($Y[$i] - $meanY) + $den += $dx * $dx + } + if ($den -eq 0) { return $null } + return $num / $den +} + +function Format-Bytes { + param($Bytes) + + if ($null -eq $Bytes) { return '--' } + return '{0:0.00} MiB' -f ($Bytes / 1MB) +} + +function Format-Drift { + <# + A drift figure with its label, or `--` when the arm had too few samples. + + `Get-HalfDrift` returns $null under six samples, and PowerShell evaluates + `$null / 1MB` as 0. The first smoke arm therefore printed + `peak ws 0.00 MiB` for a drift it never measured. That 0 is not a small + drift. It is an absent figure wearing the appearance of a measured one, + which is the zero-vs-absent collapse ADR-001 forbids, in the summary of + the instrument that exists to find drift. The null test must happen BEFORE + the arithmetic, so it happens here once and the four call sites cannot + each get it wrong. + #> + param($Value, [string] $Label, [bool] $Bytes) + + if ($null -eq $Value) { return "$Label --" } + if ($Bytes) { return '{0} {1:+0.00;-0.00;0.00} MiB' -f $Label, ($Value / 1MB) } + return '{0} {1:+0.0;-0.0;0.0}' -f $Label, $Value +} + +# ---------------------------------------------------------------- peak memory + +function Initialize-PeakReader { + <# + A fire's peak working set, read from the handle after the process exits. + + `System.Diagnostics.Process.PeakWorkingSet64` is the obvious call, and it + does not work here. After the process exits, that property reads a + snapshot that no longer exists, and it returns 0. This is measured: the + first per-fire arm reported `peak ws 0.00 MiB` for all six fires. That 0 + is not a small measurement. It is an absent measurement in the form of a + number, which is the zero-vs-absent collapse that ADR-001 forbids. + + `GetProcessMemoryInfo` in psapi reads from the process HANDLE, which stays + valid while this script holds it. It therefore reports the true peak of the + run that just ended. When the call fails, the script records null, and the + summary prints `--`. The script never substitutes 0. + #> + if ('TelltaleSoak.Mem' -as [type]) { return $true } + try { + # No -UsingNamespace: Add-Type already emits `using + # System.Runtime.InteropServices;` for -MemberDefinition, and a second + # one is a duplicate-using warning that its warnings-as-errors compile + # turns into a hard failure. + Add-Type -Namespace TelltaleSoak -Name Mem -MemberDefinition @' +[StructLayout(LayoutKind.Sequential)] +public struct COUNTERS { + public uint cb; + public uint PageFaultCount; + public UIntPtr PeakWorkingSetSize; + public UIntPtr WorkingSetSize; + public UIntPtr QuotaPeakPagedPoolUsage; + public UIntPtr QuotaPagedPoolUsage; + public UIntPtr QuotaPeakNonPagedPoolUsage; + public UIntPtr QuotaNonPagedPoolUsage; + public UIntPtr PagefileUsage; + public UIntPtr PeakPagefileUsage; +} +[DllImport("psapi.dll", SetLastError=true)] +public static extern bool GetProcessMemoryInfo(IntPtr handle, out COUNTERS counters, uint size); +'@ + return $true + } catch { + Write-Warning ("peak memory per fire is unavailable: {0}" -f $_.Exception.Message) + return $false + } +} + +function Get-PeakMemory { + param($Proc) + + $result = [pscustomobject]@{ ws = $null; priv = $null } + if (-not ('TelltaleSoak.Mem' -as [type])) { return $result } + try { + $counters = New-Object 'TelltaleSoak.Mem+COUNTERS' + $size = [System.Runtime.InteropServices.Marshal]::SizeOf($counters) + if ([TelltaleSoak.Mem]::GetProcessMemoryInfo($Proc.Handle, [ref]$counters, $size)) { + $result.ws = [long]$counters.PeakWorkingSetSize.ToUInt64() + $result.priv = [long]$counters.PeakPagefileUsage.ToUInt64() + } + } catch { + # Left null on purpose. See Initialize-PeakReader. + } + return $result +} + +# ---------------------------------------------------------------- the tree + +function Get-ProcessTable { + <# + Every process on the machine, keyed by pid. One query serves the whole + sample: parentage, memory, handles and cpu all come from the same class. + #> + $table = @{} + $all = Get-CimInstance -ClassName Win32_Process -Property ` + ProcessId, ParentProcessId, Name, WorkingSetSize, PrivatePageCount, HandleCount, ` + KernelModeTime, UserModeTime, CreationDate + foreach ($p in $all) { $table[[int]$p.ProcessId] = $p } + return $table +} + +function Get-Tree { + <# + The root and every descendant, breadth first. A child counts only when its + creation time is not earlier than its parent's -- the pid-reuse guard the + header describes. An unreadable creation time is treated as failing the + guard, because a child this cannot date is a child this cannot vouch for. + #> + param([hashtable] $Table, [int] $RootPid) + + if (-not $Table.ContainsKey($RootPid)) { return @() } + + $byParent = @{} + foreach ($p in $Table.Values) { + $parent = [int]$p.ParentProcessId + if (-not $byParent.ContainsKey($parent)) { $byParent[$parent] = New-Object System.Collections.ArrayList } + [void]$byParent[$parent].Add($p) + } + + $tree = New-Object System.Collections.ArrayList + $queue = New-Object System.Collections.Queue + $queue.Enqueue($Table[$RootPid]) + while ($queue.Count -gt 0) { + $current = $queue.Dequeue() + [void]$tree.Add($current) + $currentPid = [int]$current.ProcessId + if (-not $byParent.ContainsKey($currentPid)) { continue } + foreach ($child in $byParent[$currentPid]) { + if ([int]$child.ProcessId -eq $currentPid) { continue } + if ($null -eq $child.CreationDate -or $null -eq $current.CreationDate) { continue } + if ($child.CreationDate -lt $current.CreationDate) { continue } + $queue.Enqueue($child) + } + } + return $tree.ToArray() +} + +function Measure-Tree { + param($Tree) + + # The loop counts the processes, and the function does not read + # `$Tree.Count`. PowerShell converts a one-element array to a scalar on + # return, and a tree of one process reported a count of 0. In the summary a + # reader would read that 0 as an exit of the root process. + $ws = 0; $priv = 0; $handles = 0; $cpu100ns = 0; $n = 0 + $procs = New-Object System.Collections.ArrayList + foreach ($p in $Tree) { + $n++ + $ws += [long]$p.WorkingSetSize + $priv += [long]$p.PrivatePageCount + $handles += [int]$p.HandleCount + $t = [long]$p.KernelModeTime + [long]$p.UserModeTime + $cpu100ns += $t + [void]$procs.Add([pscustomobject]@{ + pid = [int]$p.ProcessId + name = [string]$p.Name + ws = [long]$p.WorkingSetSize + priv = [long]$p.PrivatePageCount + handles = [int]$p.HandleCount + cpu_s = [math]::Round($t / 1e7, 3) + }) + } + return [pscustomobject]@{ + procs = $procs.ToArray() + count = $n + ws = $ws + priv = $priv + handles = $handles + cpu_s = [math]::Round($cpu100ns / 1e7, 3) + } +} + +# ---------------------------------------------------------------- summary + +function Show-Summary { + param([string] $Path) + + $lines = Get-Content -Path $Path | Where-Object { $_.Trim().Length -gt 0 } + if ($lines.Count -eq 0) { Write-Host "no samples in $Path"; return } + + $records = $lines | ForEach-Object { $_ | ConvertFrom-Json } + $samples = @($records | Where-Object { $_.kind -eq 'sample' }) + $fires = @($records | Where-Object { $_.kind -eq 'fire' }) + $meta = @($records | Where-Object { $_.kind -eq 'meta' }) + + foreach ($m in $meta) { + Write-Host '' + Write-Host ("arm {0} -- {1}" -f $m.label, $m.note) + Write-Host (" started {0} host {1} cpus {2}" -f $m.started, $m.host, $m.cpus) + } + + if ($samples.Count -gt 0) { + $elapsed = [double[]]@($samples | ForEach-Object { [double]$_.elapsed_s }) + $span = $elapsed[$elapsed.Count - 1] - $elapsed[0] + Write-Host '' + Write-Host ("residency: {0} samples over {1:0.0} min" -f $samples.Count, ($span / 60)) + # A slope for each hour, from an arm shorter than one hour, is an + # extrapolation. A shorter arm amplifies the usual variation more. The + # summary therefore prints the factor. Without it, a reader can read a + # 65x amplification of a 0.03 MiB variation as a measured hourly leak. + if ($span -gt 0 -and $span -lt 3600) { + Write-Host (" note: the arm ran {0:0.0} min, so every slope/hour below is a {1:0.0}x extrapolation, not a measured hourly figure" -f ` + ($span / 60), (3600 / $span)) + } + Write-Host '' + Write-Host (' {0,-16} {1,12} {2,12} {3,12} {4,12} {5,16}' -f 'metric', 'min', 'median', 'p95', 'max', 'slope/hour') + Write-Host (' ' + ('-' * 88)) + + $drifts = New-Object System.Collections.ArrayList + $metrics = @( + @{ key = 'ws'; label = 'working set'; bytes = $true }, + @{ key = 'priv'; label = 'private bytes'; bytes = $true }, + @{ key = 'handles'; label = 'handles'; bytes = $false }, + @{ key = 'count'; label = 'processes'; bytes = $false } + ) + $hours = [double[]]@($elapsed | ForEach-Object { $_ / 3600 }) + foreach ($metric in $metrics) { + $values = [double[]]@($samples | ForEach-Object { [double]$_.($metric.key) }) + $stats = $values | Measure-Object -Minimum -Maximum + $median = Get-Median -Values $values + $p95 = Get-Percentile -Values $values -P 95 + $slope = Get-Slope -X $hours -Y $values + if ($metric.bytes) { + $min = Format-Bytes $stats.Minimum + $mid = Format-Bytes $median + $hi = Format-Bytes $p95 + $max = Format-Bytes $stats.Maximum + if ($null -eq $slope) { $trend = '--' } else { $trend = '{0:+0.00;-0.00;0.00} MiB' -f ($slope / 1MB) } + [void]$drifts.Add((Format-Drift -Value (Get-HalfDrift -Values $values) -Label $metric.label -Bytes $true)) + } else { + $min = '{0:0}' -f $stats.Minimum + $mid = '{0:0.#}' -f $median + $hi = '{0:0}' -f $p95 + $max = '{0:0}' -f $stats.Maximum + if ($null -eq $slope) { $trend = '--' } else { $trend = '{0:+0.0;-0.0;0.0}' -f $slope } + [void]$drifts.Add((Format-Drift -Value (Get-HalfDrift -Values $values) -Label $metric.label -Bytes $false)) + } + Write-Host (' {0,-16} {1,12} {2,12} {3,12} {4,12} {5,16}' -f $metric.label, $min, $mid, $hi, $max, $trend) + } + Write-Host '' + Write-Host ' robust drift, median of the second half minus the first, which one outlier cannot move:' + Write-Host (' ' + ($drifts -join ' ')) + + # Idle CPU, over intervals whose pid set did not change. A membership + # change makes the delta incomparable (see the header); those intervals + # are dropped and counted rather than reported. + $cpuPcts = New-Object System.Collections.ArrayList + $skipped = 0 + $cpus = 1 + if ($meta.Count -gt 0 -and $meta[0].cpus) { $cpus = [int]$meta[0].cpus } + for ($i = 1; $i -lt $samples.Count; $i++) { + if ($samples[$i].set_changed) { $skipped++; continue } + $dt = [double]$samples[$i].elapsed_s - [double]$samples[$i - 1].elapsed_s + $dcpu = [double]$samples[$i].cpu_s - [double]$samples[$i - 1].cpu_s + if ($dt -le 0 -or $dcpu -lt 0) { $skipped++; continue } + [void]$cpuPcts.Add(100 * $dcpu / ($dt * $cpus)) + } + Write-Host '' + if ($cpuPcts.Count -gt 0) { + $arr = [double[]]$cpuPcts.ToArray() + $stats = $arr | Measure-Object -Minimum -Maximum + Write-Host (' cpu over {0} comparable intervals ({1} dropped): min {2:0.000}% median {3:0.000}% max {4:0.000}% total {5:0.00} s' -f ` + $arr.Count, $skipped, $stats.Minimum, (Get-Median -Values $arr), $stats.Maximum, ` + ([double]$samples[$samples.Count - 1].cpu_s)) + } else { + Write-Host (' cpu: no comparable interval ({0} dropped) -- the pid set changed on every sample' -f $skipped) + } + } + + if ($fires.Count -gt 0) { + $ok = @($fires | Where-Object { $_.exit -eq 0 }) + Write-Host '' + Write-Host ("per-fire: {0} fires, {1} exited 0" -f $fires.Count, $ok.Count) + # Windows accounts process CPU time in scheduler ticks of 15.625 ms, so + # a single fire's cpu ms is quantized to a multiple of that and a lone + # 0.0 means "under one tick", not "no CPU". Only the distribution over + # many fires carries information here; one reading carries +/- one tick. + Write-Host ' note: cpu ms is quantized to the 15.625 ms scheduler tick, so read the distribution and never one fire' + Write-Host '' + Write-Host (' {0,-16} {1,12} {2,12} {3,12} {4,12} {5,16}' -f 'metric', 'min', 'median', 'p95', 'max', 'slope/1k fires') + Write-Host (' ' + ('-' * 88)) + $drifts = New-Object System.Collections.ArrayList + $fireMetrics = @( + @{ key = 'wall_ms'; label = 'wall ms'; bytes = $false }, + @{ key = 'cpu_ms'; label = 'cpu ms'; bytes = $false }, + @{ key = 'peak_ws'; label = 'peak ws'; bytes = $true }, + @{ key = 'peak_priv'; label = 'peak private'; bytes = $true } + ) + foreach ($metric in $fireMetrics) { + # A null is dropped, never read as 0. A metric this arm could not + # measure prints as absent rather than as a very good result. + $present = @($fires | Where-Object { $null -ne $_.($metric.key) }) + if ($present.Count -eq 0) { + Write-Host (' {0,-16} {1,12} {2,12} {3,12} {4,12} {5,16}' -f $metric.label, '--', '--', '--', '--', '--') + continue + } + $values = [double[]]@($present | ForEach-Object { [double]$_.($metric.key) }) + # x is the fire's own ordinal in thousands, so the slope reads as + # "per 1000 fires" and stays right when some fires lack the metric. + $index = [double[]]@($present | ForEach-Object { [double]$_.n / 1000 }) + $stats = $values | Measure-Object -Minimum -Maximum + $median = Get-Median -Values $values + $p95 = Get-Percentile -Values $values -P 95 + $slope = Get-Slope -X $index -Y $values + if ($metric.bytes) { + $min = Format-Bytes $stats.Minimum + $mid = Format-Bytes $median + $hi = Format-Bytes $p95 + $max = Format-Bytes $stats.Maximum + if ($null -eq $slope) { $trend = '--' } else { $trend = '{0:+0.00;-0.00;0.00} MiB' -f ($slope / 1MB) } + } else { + $min = '{0:0.0}' -f $stats.Minimum + $mid = '{0:0.0}' -f $median + $hi = '{0:0.0}' -f $p95 + $max = '{0:0.0}' -f $stats.Maximum + if ($null -eq $slope) { $trend = '--' } else { $trend = '{0:+0.0;-0.0;0.0}' -f $slope } + } + Write-Host (' {0,-16} {1,12} {2,12} {3,12} {4,12} {5,16}' -f $metric.label, $min, $mid, $hi, $max, $trend) + if ($metric.bytes) { + [void]$drifts.Add((Format-Drift -Value (Get-HalfDrift -Values $values) -Label $metric.label -Bytes $true)) + } else { + [void]$drifts.Add((Format-Drift -Value (Get-HalfDrift -Values $values) -Label $metric.label -Bytes $false)) + } + } + Write-Host '' + Write-Host ' robust drift, median of the second half minus the first, which one outlier cannot move:' + Write-Host (' ' + ($drifts -join ' ')) + } + Write-Host '' +} + +# ---------------------------------------------------------------- modes + +if ($PSCmdlet.ParameterSetName -eq 'Summary') { + Show-Summary -Path $Summarize + return +} + +$startedAt = Get-Date +$cpuCount = [int]$env:NUMBER_OF_PROCESSORS +if ($cpuCount -lt 1) { $cpuCount = 1 } + +if ($PSCmdlet.ParameterSetName -eq 'Fire') { + $note = 'per-fire: {0} {1}' -f $FireCommand, ($FireArgs -join ' ') + Write-Sample -Path $Out -Record ([pscustomobject]@{ + schema_version = $SchemaVersion + kind = 'meta' + label = $Label + note = $note + started = $startedAt.ToString('o') + host = $env:COMPUTERNAME + cpus = $cpuCount + fires = $Fires + }) + + # ProcessStartInfo rather than Start-Process, and stdin written rather than + # redirected from a path, because this is the shape ci.yml's own 15-sample + # timing step uses (design.md §5's 2026-08-16 amendment). Two instruments + # timing the same binary two different ways produce two numbers nobody can + # compare; this arm is the long version of that step, not a rival to it. + [void](Initialize-PeakReader) + $exe = (Resolve-Path $FireCommand).Path + $payloadBytes = New-Object byte[] 0 + if ($FireStdin) { + $payloadBytes = [System.Text.Encoding]::UTF8.GetBytes((Get-Content -Path $FireStdin -Raw)) + } + + # THE BOM TRAP. This instrument met it on the first smoke run, and the note + # is here because a second diagnosis costs an hour. On a console at code + # page 65001, which is this machine's console, `[Console]::InputEncoding` is + # a UTF8Encoding WITH a 3-byte preamble. .NET builds the child's stdin + # writer from that encoding and sets AutoFlush. The flush writes the + # preamble when the script first reads `$proc.StandardInput`. The BOM + # therefore arrives BEFORE the payload, even when the script writes the + # payload to `BaseStream` as raw bytes. `telltale statusline` then refuses + # the input: "invalid character 'ï' looking for beginning of value". A BOM + # is not JSON. + # + # The fixture on disk carries no BOM (`7B 0D 0A`, which is `{`). The + # 15-sample step in ci.yml never meets this condition, because PowerShell 7 + # gives it an encoding without a preamble. This is therefore an artifact of + # the 5.1 harness, and it is NOT a telltale defect. The arm must not record + # it as one. `$psi.StandardInputEncoding` is the direct fix, and 5.1's .NET + # Framework does not have that property. The script therefore replaces the + # console encoding for the duration of the arm, and restores it in + # `finally`. + $priorInputEncoding = $null + try { + $priorInputEncoding = [Console]::InputEncoding + [Console]::InputEncoding = New-Object System.Text.UTF8Encoding($false) + } catch { + # No console attached (a scheduled task, a redirected host). Nothing to + # swap and nothing to restore; the writer inherits a preamble-free + # encoding in that case anyway. + $priorInputEncoding = $null + } + + try { + for ($i = 0; $i -lt $Fires; $i++) { + $psi = New-Object System.Diagnostics.ProcessStartInfo + $psi.FileName = $exe + $psi.Arguments = ($FireArgs -join ' ') + $psi.RedirectStandardInput = $true + $psi.RedirectStandardOutput = $true + $psi.UseShellExecute = $false + + $watch = [System.Diagnostics.Stopwatch]::StartNew() + $proc = [System.Diagnostics.Process]::Start($psi) + $proc.StandardInput.BaseStream.Write($payloadBytes, 0, $payloadBytes.Length) + $proc.StandardInput.BaseStream.Flush() + $proc.StandardInput.Close() + $stdout = $proc.StandardOutput.ReadToEnd() + $proc.WaitForExit() + $watch.Stop() + + # A crash is fast. ci.yml asserts the line rendered on every sample for + # exactly this reason, and a soak that ran 300 times would otherwise + # report a binary that broke at fire 40 as a large improvement. + if ($FireExpect -and $stdout -notmatch $FireExpect) { + throw "fire $i rendered nothing matching /$FireExpect/: $stdout" + } + + # Both figures come off the still-open handle, so they describe the run + # that just ended rather than a sample caught at some arbitrary moment + # inside a process that lives about 25 ms. TotalProcessorTime reads + # correctly after exit; the peak does not, which is what Get-PeakMemory + # is for. + $peak = Get-PeakMemory -Proc $proc + $cpuMs = $null + try { $cpuMs = [math]::Round($proc.TotalProcessorTime.TotalMilliseconds, 2) } catch { $cpuMs = $null } + + Write-Sample -Path $Out -Record ([pscustomobject]@{ + schema_version = $SchemaVersion + kind = 'fire' + label = $Label + n = $i + ts = (Get-Date).ToString('o') + wall_ms = [math]::Round($watch.Elapsed.TotalMilliseconds, 2) + cpu_ms = $cpuMs + peak_ws = $peak.ws + peak_priv = $peak.priv + exit = $proc.ExitCode + out_bytes = $stdout.Length + }) + $proc.Dispose() + } + } finally { + if ($null -ne $priorInputEncoding) { + try { [Console]::InputEncoding = $priorInputEncoding } catch { } + } + } + + if ($Out) { Show-Summary -Path $Out } + return +} + +# Residency. +if ($Id -le 0) { + if (-not $Name) { throw 'residency mode needs -Id or -Name' } + $matched = @(Get-Process -Name $Name -ErrorAction SilentlyContinue) + if ($matched.Count -eq 0) { throw "no running process named $Name" } + if ($matched.Count -gt 1) { + throw ("$Name matches {0} processes ({1}) -- pass -Id, because picking one would label a measurement of an arbitrary process" -f ` + $matched.Count, (($matched | ForEach-Object { $_.Id }) -join ', ')) + } + $Id = $matched[0].Id +} + +$table = Get-ProcessTable +if (-not $table.ContainsKey($Id)) { throw "no process with pid $Id" } +$rootBirth = $table[$Id].CreationDate +$rootName = $table[$Id].Name + +Write-Sample -Path $Out -Record ([pscustomobject]@{ + schema_version = $SchemaVersion + kind = 'meta' + label = $Label + note = 'residency: pid {0} ({1}), every {2}s for {3} min' -f $Id, $rootName, $IntervalSeconds, $DurationMinutes + started = $startedAt.ToString('o') + host = $env:COMPUTERNAME + cpus = $cpuCount + root_pid = $Id + root_name = $rootName + interval_s = $IntervalSeconds +}) + +Write-Host ("soak: watching pid {0} ({1}) every {2}s for {3} min -> {4}" -f $Id, $rootName, $IntervalSeconds, $DurationMinutes, $Out) + +$deadline = $startedAt.AddMinutes($DurationMinutes) +$clock = [System.Diagnostics.Stopwatch]::StartNew() +$previousSet = $null +$ended = 'deadline' + +while ((Get-Date) -lt $deadline) { + $table = Get-ProcessTable + if (-not $table.ContainsKey($Id)) { $ended = 'root exited'; break } + if ($table[$Id].CreationDate -ne $rootBirth) { $ended = 'pid reused by another process'; break } + + $tree = @(Get-Tree -Table $table -RootPid $Id) + $m = Measure-Tree -Tree $tree + $set = (($m.procs | ForEach-Object { $_.pid } | Sort-Object) -join ',') + + Write-Sample -Path $Out -Record ([pscustomobject]@{ + schema_version = $SchemaVersion + kind = 'sample' + label = $Label + ts = (Get-Date).ToString('o') + elapsed_s = [math]::Round($clock.Elapsed.TotalSeconds, 2) + count = $m.count + ws = $m.ws + priv = $m.priv + handles = $m.handles + cpu_s = $m.cpu_s + set_changed = ($null -ne $previousSet -and $set -ne $previousSet) + procs = $m.procs + }) + $previousSet = $set + + # Sleep until the next tick, and not for a constant interval. A slow sample + # would otherwise delay every later sample across an arm of several hours. + $next = $IntervalSeconds - ($clock.Elapsed.TotalSeconds % $IntervalSeconds) + Start-Sleep -Milliseconds ([int]($next * 1000)) +} + +Write-Sample -Path $Out -Record ([pscustomobject]@{ + schema_version = $SchemaVersion + kind = 'end' + label = $Label + ts = (Get-Date).ToString('o') + elapsed_s = [math]::Round($clock.Elapsed.TotalSeconds, 2) + reason = $ended +}) + +Write-Host ("soak: {0} after {1:0.0} min" -f $ended, ($clock.Elapsed.TotalMinutes)) +if ($Out) { Show-Summary -Path $Out }