From e09bd6ea7136458832c3e527f53a5185a23de404 Mon Sep 17 00:00:00 2001 From: Kamron Batman <3953314+kamronbatman@users.noreply.github.com> Date: Sun, 9 Aug 2026 13:35:41 -0700 Subject: [PATCH] tools: event-loop measurement harness The A/B harness used to measure the idle-sleep work that shipped in main (#2559): Measure-EventLoop.ps1 and measure-event-loop.sh drive CPU/lag comparisons across server.eventLoopIdleWaitMs settings, and HostLatencyProbe.cs measures what basic operations cost on a host. dev-docs/measuring-event-loop.md explains the method, the numbers that matter, and how to re-vendor IORingGroup for ring experiments. This branch is main plus this commit, rebased forward as main moves. Co-Authored-By: Claude Fable 5 --- .gitignore | 3 + CLAUDE.md | 1 + dev-docs/measuring-event-loop.md | 263 +++++++++++++++++++++++++++++++ tools/HostLatencyProbe.cs | 87 ++++++++++ tools/Measure-EventLoop.ps1 | 96 +++++++++++ tools/measure-event-loop.sh | 131 +++++++++++++++ 6 files changed, 581 insertions(+) create mode 100644 dev-docs/measuring-event-loop.md create mode 100644 tools/HostLatencyProbe.cs create mode 100644 tools/Measure-EventLoop.ps1 create mode 100755 tools/measure-event-loop.sh diff --git a/.gitignore b/.gitignore index d5b26e268..3d4f21d7b 100644 --- a/.gitignore +++ b/.gitignore @@ -64,3 +64,6 @@ # Ignore everything under tools/ except the operator scripts checked in below. /tools/* !/tools/Export-IpBlocklist.ps1 +!/tools/Measure-EventLoop.ps1 +!/tools/HostLatencyProbe.cs +!/tools/measure-event-loop.sh diff --git a/CLAUDE.md b/CLAUDE.md index 849ff3175..07c22371c 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -48,6 +48,7 @@ Apply these when writing or reviewing `.cs` files under `Projects/`. | Threading model | `dev-docs/threading-model.md` | | Server hardware requirements | `dev-docs/server-requirements.md` | | Debugging event-loop performance (profiling build, decomposition, GC/RAM) | `dev-docs/debugging-event-loop.md` | +| A/B measurement harness (this branch only) | `dev-docs/measuring-event-loop.md` | | Tick-count overflow rules (subtraction comparisons; GCP pass-through counters) | `dev-docs/tick-counts.md` | | Server lifecycle & bootstrap phases (Configure/ConfigurePrompts/Initialize) | `dev-docs/server-lifecycle.md` | | Platform prerequisites (ICU, tzdata, native libs per distro) | `dev-docs/platform-prerequisites.md` | diff --git a/dev-docs/measuring-event-loop.md b/dev-docs/measuring-event-loop.md new file mode 100644 index 000000000..18d92544e --- /dev/null +++ b/dev-docs/measuring-event-loop.md @@ -0,0 +1,263 @@ +# Measuring the Event Loop + +> **This is the perennial `measure/event-loop` branch** — main plus the measurement harness, kept +> for future loop work and periodically rebased onto main. The idle-sleep design and the +> `EVENT_LOOP_PROFILING` diagnostics tier shipped in main (see +> `dev-docs/debugging-event-loop.md` for day-to-day diagnosis); this branch adds the A/B +> measurement scripts below (`tools/Measure-EventLoop.ps1`, `tools/measure-event-loop.sh`, +> `tools/HostLatencyProbe.cs`). +> +> When a future experiment needs to iterate on IORingGroup itself without burning published +> package versions, re-vendor it here: copy the ring branch's `IORingGroup/*.cs` byte-identical +> into `Projects/IORingGroup/`, give it a minimal csproj that inherits `Directory.Build.props` +> (needs `LangVersion` `Preview` and `NoWarn` `CS8981;CS0649` under `TreatWarningsAsErrors`), +> swap Server.csproj's `PackageReference` for a `ProjectReference`, and add the project to +> `ModernUO.slnx`. Revert = delete the directory and restore the `PackageReference`. + +The game loop sleeps when it has nothing to do, and runs flat out when it does. This page covers the +one setting that controls it, the metric that tells you whether it is healthy, and how to measure +both on your own hardware. + +## The lever + +`server.eventLoopIdleWaitMs` is the longest the loop will block when every queue is empty. It wakes +on the next timer tick or the instant work arrives, whichever comes first, so this only caps how +long a *quiet* loop stays blocked. + +Measured on an idle shard with a real world loaded (190,728 items, 33,158 mobiles): + +| Setting | CPU | Skipped slots / 1875 | Peak lag (avg over windows) | +|---|---|---|---| +| `0` | **98.5%** of one core | **0** | **0 ms** | +| `1` | 0.81% | 0–1 | 7.8 ms | +| `2` (default) | ~0.8% | 0–1 | 11.2 ms | +| `4` | 0.57% | 0–1 | 7.0 ms | +| `8` | 0.16% | ~1 | 9.8 ms | + +**The trade-off is not a smooth slope.** `0` is qualitatively different — never sleeping means +never waking late, so zero skipped slots and zero lag. Everything from `1` to `8` sits in the same +band: peaks of 7–11 ms with no trend, and roughly one lost slot in several thousand. The differences +across that range are measurement noise, not a dial. Pick `0` or pick a sleep value; the specific +sleep value barely matters for latency and matters a lot for CPU. + +**`0` is the way out of this entire apparatus** — no sleeping, no wake signals, no backoff — for the +price of a core. A large shard on dedicated CPU that would rather spend the core than ever risk a +late wake should set it and stop reading here. + +**`2` is the default** because it is the conservative end of that band while still costing almost +nothing. On an idle shard it loses about one slot in 7,500 — and so does pure spinning, because that +floor is the operating system, not the scheduler. + +## The metric that matters: skipped slots + +The timer wheel advances one slot per 8 ms of elapsed time. A **skipped slot** is one that came due +while the loop was elsewhere, counted as turns beyond the first in a single pass. + +That distinction is the point. A wake can never land exactly on an 8 ms boundary, so the wheel is +always a fraction late and "lag" is always non-zero. Losing a *slot* is different: the wheel took a +step it should have taken earlier. Read as a rate it is directly meaningful — 125 slots per second +at an 8 ms tick, so a handful per minute is jitter and hundreds per minute is a server that cannot +keep up. + +**Peak tick lag is reported but is a weak signal.** It is a single worst case over the whole window, +so one hiccup pins it and it reads identically whether the server stumbled once or is permanently +behind. Use it to size an outlier, not to judge health. + +### Wheel lag is not network latency + +These are separate paths, and conflating them is the easiest mistake to make here. + +A player's action arrives as a packet. The receive completion is in the loop's wait set, so it wakes +the loop **immediately** — not after `eventLoopIdleWaitMs` elapses — and the packet is handled inline +by `NetState.Slice` → `HandleReceive` → `HandlePacket`. Sleeping longer does not add round-trip +latency, because a sleeping loop is woken by the thing it was waiting for. + +Wheel lag only delays **timer-driven** logic: combat swings, spell timers, AI ticks, spawners. Those +are built around 100 ms to multi-second intervals, so 8–23 ms of wheel lag is well inside their +noise floor and is not something a player can perceive. + +The one path that genuinely waits out the sleep is a **new connection**, because AcceptEx +completions are polled rather than signalled. That adds up to `eventLoopIdleWaitMs` to connection +setup — single-digit milliseconds on a handshake that takes far longer. + +Round-trip latency under real player load has not been measured end to end here; the above is read +off the code paths, not off a wire capture. + +**Cycles per second is not a health signal at all.** It counts loop iterations, so once the loop +sleeps it is paced by `eventLoopIdleWaitMs` rather than by anything about your shard: roughly 400 at +the default, whether the world is empty or busy but keeping up. It is retained because existing +tooling reads it. Do not build alerts on it. + +### The first time any code path runs, it will probably miss + +A freshly started shard misses the budget on paths it has never executed: the first login, the +first character creation, the first time a particular gump is opened. That is tier-0 JIT and +first-touch static initialisation, not the cost of the operation. + +Profiling caught this directly. A 113 ms stall in a house-placement gump was two thirds +`InitClassSlow` and `GetGCStaticBaseSlow` — running static constructors — and only a third the gump +logic itself. Character creation on an M1 shows the same shape: a few missed deadlines the first +time, from a workload that is nowhere near 24 ms of actual work. + +To tell them apart, run the same operation two or three times in one session. Cold-path cost +disappears on the second run; real cost does not. You do not need to reach tiered-compilation +maturity to see the difference, just the cold-to-warm transition. + +### The 16 ms bar is stricter than the game needs + +This measures **timer accuracy, not network latency**. A missed budget means whatever timers were +sitting in those wheel slots fired late — it does not mean a packet was delayed, since packets are +handled inline and wake a sleeping loop immediately. + +UO systems run on 100 ms to multi-second cadences: combat swings, AI ticks, spawners, decay. A 24 ms +wheel stall is inside their noise floor, and invisible next to a typical 50 ms ping. The bar is set +where it is because it makes a sensitive detector that catches problems long before players would, +not because 16 ms is a threshold players can perceive. + +So an occasional missed budget is not a defect. What matters is the **rate**, and whether the +misses coincide with sleeps that returned late. Sustained misses are worth chasing; a handful on a +cold path is the metric working. + +### Self-inflicted stalls are expected, and are not the scheduler's fault + +A world save can block the loop for a second or more on a large shard. A staff command like +advanced search is knowingly expensive. Both blow the 16 ms budget, sometimes badly — the wheel +then catches up by turning many times in one pass, because ModernUO does **not** drift timers and +should not start. + +Those misses are real. What they are not is a reason to stop sleeping — and the backoff cannot be +tripped by them **by construction**: a sleep is bounded by the time to the next wheel turn, so a +correctly honoured sleep can never miss a deadline. The only thing the backoff watches is the +sleep itself returning late (`elapsed - requested >= tick rate`), which is measured around each +`WaitForCompletion` call and can only be caused by the host descheduling the process. + +## Automatic backoff + +If the host returns more than `server.lateWakeThreshold` waits late (default 1) per second, across +**two consecutive** samples, idle sleeping suspends with escalating duration (5s doubling to 2min) +and the loop spins instead. It logs: + +``` +This host returned a 2ms idle wait at least 8ms late N time(s) in the last second; idle sleeping suspended for 5000ms +``` + +Under sustained load the backoff is inert, because the queues are never empty and the loop was not +sleeping anyway. At the escalation ceiling it logs an error telling the operator to set +`server.eventLoopIdleWaitMs=0`. + +## Turn on reporting + +Build with the profiling flag and use the in-game command: + +``` +dotnet build -p:EventLoopProfiling=true +[LoopStats +``` + +`[LoopStats` prints the last minute's wall-time decomposition — sleep / GC / stolen percentages +and per-phase work with worst-second peaks — and writes the full ~15-minute per-second history to +a CSV for comparison. Normal builds compile all of this out (`[Conditional]` hooks), so there is +nothing to disable in production. See `dev-docs/debugging-event-loop.md` for how to read it. + +**Do not** build a probe that calls `Process.Threads` or `Process.GetProcesses` on a timer — that +enumerates every process and thread on the machine, and has been measured costing several percent +of the main thread and causing the very stalls it was added to diagnose. + +## Will a busy shard regress? + +**Constant networking generates no wakes at all.** Packet handling runs inline on the loop thread +(`NetState.Slice` → `HandleReceive` → `HandlePacket`), as do timers (`Timer.Slice` → `Turn` → +`OnTick`). Neither goes through `LoopContext.Post`, so traffic volume is not connected to wake +volume. Wakes come only from cross-thread work — async continuations and a handful of explicit +posts such as world-save boundaries. Posts originating *on* the loop thread are elided outright, +which is exact rather than heuristic: the loop is executing that call, so it cannot be blocked. + +**Under sustained load the loop stops sleeping**, because the queues are never all empty at once. +At that point it runs exactly as it did before, and the only added per-iteration work is the idle +check plus one timestamp read per (rare) sleep. + +To confirm on your own shard, at peak population, with the profiling build: + +1. Check sleeps/second in `[LoopStats` — near 0 means idle sleeping is dormant and cannot be + costing you anything. +2. Check `lateWakes` and worst wheel lag — the regression signals, not CPU. +3. Repeated backoff warnings in the log mean the host keeps returning waits late, which is worth + reporting. +4. If you want certainty, set `eventLoopIdleWaitMs=0` and compare wheel lag. Equal means the + scheduler costs you nothing at that load. + +## Measuring on your hardware + +For a clean comparison, hold everything else constant: `"autosave.enabled": "False"`, +`"pathfinding.prebakeMaps": "False"`, same world, same population, back to back. + +### Before you start, on Linux + +Two native libraries are needed, and their absence looks alarming — the build succeeds and the +tests then fail with `DllNotFoundException`, which reads like a broken branch rather than a missing +package. The resolver wants the unversioned `.so`, so the `-dev` packages are the ones that matter: + +```bash +sudo apt-get install -y libdeflate-dev libargon2-dev # Debian/Ubuntu +``` + +Also **clone with full history**. A `--depth 1` clone fails the build in Nerdbank.GitVersioning, +which needs the commit history to compute a version, and the error points at MSBuild internals +rather than at the clone. + +Verified in a clean container: with those two packages and a full clone, this branch builds and +passes 826 Server.Tests and 642 UOContent.Tests on Linux, matching Windows. + +### Windows + +```powershell +pwsh tools/Measure-EventLoop.ps1 -WarmupSeconds 45 -SampleSeconds 60 +``` + +Boots the shard twice, samples `TotalProcessorTime` over the window, and prints both results. + +### macOS and Linux + +```bash +./tools/measure-event-loop.sh 45 60 +``` + +Same procedure as the Windows script: boots the shard twice, samples process CPU over the window, +and prints the `loop:` lines from both runs so the CPU figures can be read against what they cost +in timer accuracy. Needs `python3`, which ships with the macOS developer tools. + +To sample a shard that is already running instead: + +```bash +pid=$(pgrep -f ModernUO) +ps -o time= -p "$pid"; sleep 60; ps -o time= -p "$pid" +``` + +or watch it with `top -pid "$pid"` (macOS) / `top -p "$pid"` (Linux). + +**Run these rather than assuming the Windows result carries over.** The wake path is different code +on every backend — `EVFILT_USER` on kqueue, an eventfd on io_uring and epoll, an event object on +Windows — and so is the cost structure the loop sits on. Windows pays a syscall per iteration in the +accept scan that the others do not, and the timer-resolution problem that shapes the Windows +implementation has no equivalent elsewhere. + +Before measuring on a platform for the first time, run the ring's own tests, which exercise the wake +contract natively: + +```bash +dotnet test IORingGroup.Tests/IORingGroup.Tests.csproj +``` + +`WakeBeforeWaitIsNotLost` and `WakeFromAnotherThreadUnblocksWait` are the ones that matter. If the +platform's wake primitive is broken, those fail and the loop would otherwise appear merely +"slow to notice work" for no visible reason. + +## If skipped slots are high regardless of setting + +The loop is not your problem. In rough order: + +1. **The host is not scheduling you.** Common on burstable/shared vCPU. Check steal time (`%st`). +2. **A custom system is blocking the loop** — file or network I/O, large scans, or `Process` + enumeration inside a timer tick or command handler. +3. **Saves.** Re-enable `autosave.enabled` and see whether spikes line up with save intervals. +4. **You are undersized.** See [server-requirements.md](server-requirements.md). diff --git a/tools/HostLatencyProbe.cs b/tools/HostLatencyProbe.cs new file mode 100644 index 000000000..5470b7f16 --- /dev/null +++ b/tools/HostLatencyProbe.cs @@ -0,0 +1,87 @@ +#:property TreatWarningsAsErrors=false +// Host operation-cost probe. +// +// The ModernUO event loop reads the clock every iteration and, on Windows, polls pending accept +// slots with a syscall. On bare metal those cost tens of nanoseconds and vanish. On a virtualised +// host without invariant-TSC passthrough they can trap to the hypervisor and cost microseconds, +// which is the difference between a loop running 1,200,000 cycles/sec and one running 20,000. +// +// This measures the primitives directly so a slow shard can be attributed to the host rather than +// guessed at. It touches nothing in ModernUO and needs no shard running. +// +// Run: dotnet run tools/HostLatencyProbe.cs +// +// Reference (Windows desktop, dedicated cores) is printed alongside each result. + +using System.Diagnostics; +using System.Runtime.InteropServices; + +const int Warmup = 100_000; +const int Iterations = 2_000_000; + +Console.WriteLine($"OS : {RuntimeInformation.OSDescription}"); +Console.WriteLine($"Arch : {RuntimeInformation.ProcessArchitecture}"); +Console.WriteLine($"Processors : {Environment.ProcessorCount}"); +Console.WriteLine($"QPC freq : {Stopwatch.Frequency:N0} Hz"); +Console.WriteLine($"HighRes : {Stopwatch.IsHighResolution}"); +Console.WriteLine(); +Console.WriteLine($"{"operation",-34}{"ns/op",12} {"desktop ref",-14} verdict"); +Console.WriteLine(new string('-', 86)); + +Measure("Stopwatch.GetTimestamp()", 20, () => Stopwatch.GetTimestamp()); +Measure("DateTime.UtcNow", 25, () => DateTime.UtcNow.Ticks); + +if (OperatingSystem.IsWindows()) +{ + // Mirrors CheckAcceptExCompletions, which polls each pending accept slot this way. An + // already-signalled event is the cheapest possible case, so this is a floor, not a typical cost. + var evt = CreateEventW(0, 1, 1, 0); + if (evt != 0) + { + Measure("WaitForSingleObject(signalled, 0)", 250, () => (long)WaitForSingleObject(evt, 0)); + CloseHandle(evt); + } +} + +Console.WriteLine(); +Console.WriteLine("A host whose clock reads cost microseconds rather than nanoseconds is trapping to"); +Console.WriteLine("the hypervisor. That penalises every loop iteration and cannot be tuned away in"); +Console.WriteLine("the server -- it is a host or VM-configuration problem (TSC passthrough)."); + +static void Measure(string name, double desktopNs, Func op) +{ + long sink = 0; + for (var i = 0; i < Warmup; i++) + { + sink += op(); + } + + var sw = Stopwatch.StartNew(); + for (var i = 0; i < Iterations; i++) + { + sink += op(); + } + + sw.Stop(); + GC.KeepAlive(sink); + + var ns = sw.Elapsed.TotalNanoseconds / Iterations; + var ratio = ns / desktopNs; + var verdict = ratio switch + { + < 3 => "normal", + < 10 => "SLOW (~" + ratio.ToString("F0") + "x)", + _ => "TRAPPING (~" + ratio.ToString("F0") + "x)" + }; + + Console.WriteLine($"{name,-34}{ns,12:F1} {desktopNs + " ns",-14} {verdict}"); +} + +[DllImport("kernel32.dll")] +static extern nint CreateEventW(nint attrs, int manualReset, int initialState, nint name); + +[DllImport("kernel32.dll")] +static extern uint WaitForSingleObject(nint handle, uint ms); + +[DllImport("kernel32.dll")] +static extern int CloseHandle(nint handle); diff --git a/tools/Measure-EventLoop.ps1 b/tools/Measure-EventLoop.ps1 new file mode 100644 index 000000000..e7d34adba --- /dev/null +++ b/tools/Measure-EventLoop.ps1 @@ -0,0 +1,96 @@ +# A/B measurement for the event loop scheduler. +# +# Boots the shard twice against identical binaries -- once with idle sleeping disabled +# (server.eventLoopIdleWaitMs = 0) and once with idle sleeping (= 2) -- and samples process CPU +# time over a fixed window. Everything else is held constant, so the delta is the scheduler. +# +# Usage: pwsh tools/Measure-EventLoop.ps1 [-WarmupSeconds 45] [-SampleSeconds 60] + +param( + [int]$WarmupSeconds = 45, + [int]$SampleSeconds = 60 +) + +$ErrorActionPreference = 'Stop' + +$root = Split-Path -Parent $PSScriptRoot +$dist = Join-Path $root 'Distribution' +$exe = Join-Path $dist 'ModernUO.exe' +$configPath = Join-Path $dist 'Configuration\modernuo.json' + +if (-not (Test-Path $exe)) { + throw "ModernUO.exe not found at $exe. Build with: dotnet build -c Release" +} + +function Set-IdleWait([int]$value) { + $json = Get-Content $configPath -Raw | ConvertFrom-Json + $json.settings.'server.eventLoopIdleWaitMs' = "$value" + $json | ConvertTo-Json -Depth 20 | Set-Content $configPath -Encoding UTF8 +} + +function Measure-Loop([int]$idleWait, [string]$label) { + Set-IdleWait $idleWait + + Write-Host "" + Write-Host "=== $label (server.eventLoopIdleWaitMs = $idleWait) ===" -ForegroundColor Cyan + + # Redirect stdin from an empty file so the server runs headless and never blocks on console + # input. PowerShell cannot redirect from NUL, so an actual empty file stands in for it. + $stdin = Join-Path $dist 'empty.in' + if (-not (Test-Path $stdin)) { + Set-Content -Path $stdin -Value '' -NoNewline + } + + $proc = Start-Process -FilePath $exe -WorkingDirectory $dist -PassThru ` + -RedirectStandardInput $stdin ` + -RedirectStandardOutput (Join-Path $dist "Logs\measure-$idleWait.out") ` + -RedirectStandardError (Join-Path $dist "Logs\measure-$idleWait.err") + + try { + Write-Host " pid $($proc.Id); warming up for ${WarmupSeconds}s..." + Start-Sleep -Seconds $WarmupSeconds + + if ($proc.HasExited) { + throw "Server exited during warmup (code $($proc.ExitCode)). See Logs\measure-$idleWait.err" + } + + $proc.Refresh() + $cpuBefore = $proc.TotalProcessorTime + $wallBefore = Get-Date + + Write-Host " sampling for ${SampleSeconds}s..." + Start-Sleep -Seconds $SampleSeconds + + $proc.Refresh() + $cpuAfter = $proc.TotalProcessorTime + $wallAfter = Get-Date + + $cpuMs = ($cpuAfter - $cpuBefore).TotalMilliseconds + $wallMs = ($wallAfter - $wallBefore).TotalMilliseconds + $pct = $cpuMs / $wallMs * 100 + + Write-Host (" CPU: {0:F2}% of one core ({1:F0}ms CPU over {2:F0}ms wall)" -f $pct, $cpuMs, $wallMs) -ForegroundColor Yellow + + [pscustomobject]@{ Label = $label; IdleWait = $idleWait; CpuPercent = $pct } + } + finally { + if (-not $proc.HasExited) { + $proc.Kill() + $proc.WaitForExit(10000) | Out-Null + } + } +} + +$legacy = Measure-Loop 0 'Never sleep (max responsiveness)' +$sleeping = Measure-Loop 2 'Idle sleeping' + +Write-Host "" +Write-Host "=== Result ===" -ForegroundColor Green +Write-Host (" never sleep : {0,6:F2}% of one core" -f $legacy.CpuPercent) +Write-Host (" idle sleep : {0,6:F2}% of one core" -f $sleeping.CpuPercent) +if ($sleeping.CpuPercent -gt 0) { + Write-Host (" reduction : {0,6:F1}x" -f ($legacy.CpuPercent / $sleeping.CpuPercent)) +} + +# Leave the config on the new behaviour. +Set-IdleWait 2 diff --git a/tools/measure-event-loop.sh b/tools/measure-event-loop.sh new file mode 100755 index 000000000..9d3db24a2 --- /dev/null +++ b/tools/measure-event-loop.sh @@ -0,0 +1,131 @@ +#!/usr/bin/env bash +# A/B measurement for the event loop scheduler, for macOS and Linux. +# +# Boots the shard twice against identical binaries -- once with idle sleeping disabled +# (server.eventLoopIdleWaitMs = 0) and once with it enabled (= 2) -- and samples process CPU time +# over a fixed window. Everything else is held constant, so the delta is the scheduler. +# +# The Windows equivalent is tools/Measure-EventLoop.ps1. +# +# Usage: ./tools/measure-event-loop.sh [warmup_seconds] [sample_seconds] + +set -euo pipefail + +WARMUP="${1:-45}" +SAMPLE="${2:-60}" + +ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" +DIST="$ROOT/Distribution" +CONFIG="$DIST/Configuration/modernuo.json" + +# The published binary has no extension on these platforms. +EXE="$DIST/ModernUO" + +if [ ! -x "$EXE" ]; then + echo "ModernUO not found at $EXE. Build with: dotnet build -c Release" >&2 + exit 1 +fi + +if [ ! -f "$CONFIG" ]; then + echo "No configuration at $CONFIG. Start the shard once to generate it." >&2 + exit 1 +fi + +mkdir -p "$DIST/Logs" + +# python3 rather than sed: the value must be replaced inside JSON, and the file is the live +# server configuration. macOS ships python3 with the developer tools. +set_idle_wait() { + python3 - "$CONFIG" "$1" <<'PY' +import json, sys +path, value = sys.argv[1], sys.argv[2] +with open(path) as f: + cfg = json.load(f) +cfg.setdefault("settings", {})["server.eventLoopIdleWaitMs"] = value +with open(path, "w") as f: + json.dump(cfg, f, indent=2) +PY +} + +# Process CPU time in seconds. ps reports [[dd-]hh:]mm:ss, which needs unpacking. +cpu_seconds() { + local t + t="$(ps -o time= -p "$1" | tr -d ' ')" + python3 - "$t" <<'PY' +import sys +raw = sys.argv[1] +days, _, rest = raw.rpartition('-') +parts = [float(p) for p in rest.split(':')] +total = 0.0 +for p in parts: + total = total * 60 + p +if days: + total += float(days) * 86400 +print(total) +PY +} + +measure() { + local idle="$1" label="$2" + + set_idle_wait "$idle" + + echo + echo "=== $label (server.eventLoopIdleWaitMs = $idle) ===" + + # Redirect stdin from /dev/null so the server runs headless and never blocks on console input. + "$EXE" < /dev/null > "$DIST/Logs/measure-$idle.out" 2> "$DIST/Logs/measure-$idle.err" & + local pid=$! + + # shellcheck disable=SC2064 + trap "kill $pid 2>/dev/null || true" EXIT + + echo " pid $pid; warming up for ${WARMUP}s..." + sleep "$WARMUP" + + if ! kill -0 "$pid" 2>/dev/null; then + echo " server exited during warmup. See Logs/measure-$idle.err" >&2 + tail -20 "$DIST/Logs/measure-$idle.err" >&2 || true + exit 1 + fi + + local before after wall_before wall_after + before="$(cpu_seconds "$pid")" + wall_before="$(date +%s)" + + echo " sampling for ${SAMPLE}s..." + sleep "$SAMPLE" + + after="$(cpu_seconds "$pid")" + wall_after="$(date +%s)" + + kill "$pid" 2>/dev/null || true + wait "$pid" 2>/dev/null || true + trap - EXIT + + python3 - "$before" "$after" "$wall_before" "$wall_after" <<'PY' +import sys +cpu = float(sys.argv[2]) - float(sys.argv[1]) +wall = float(sys.argv[4]) - float(sys.argv[3]) +pct = cpu / wall * 100 if wall > 0 else 0 +print(f" CPU: {pct:.2f}% of one core ({cpu:.1f}s CPU over {wall:.0f}s wall)") +PY +} + +measure 0 "Never sleep (max responsiveness)" +measure 2 "Idle sleeping" + +echo +echo "=== Result ===" +echo " Compare the two CPU figures above." +echo " Then read the loop: lines for what it cost in timer accuracy:" +echo +grep -h "loop: " "$DIST/Logs/measure-0.out" | tail -3 || true +echo " ---" +grep -h "loop: " "$DIST/Logs/measure-2.out" | tail -3 || true +echo +echo " missed16ms and sched are the health numbers. cpu alone does not tell you" +echo " whether the trade was worth it." + +# Leave the configuration on the default. +set_idle_wait 2