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 <noreply@anthropic.com>
This commit is contained in:
Kamron Batman
parent
6d846b11e5
commit
e09bd6ea71
6 changed files with 581 additions and 0 deletions
87
tools/HostLatencyProbe.cs
Normal file
87
tools/HostLatencyProbe.cs
Normal file
|
|
@ -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<long> 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);
|
||||
96
tools/Measure-EventLoop.ps1
Normal file
96
tools/Measure-EventLoop.ps1
Normal file
|
|
@ -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
|
||||
131
tools/measure-event-loop.sh
Executable file
131
tools/measure-event-loop.sh
Executable file
|
|
@ -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
|
||||
Loading…
Add table
Add a link
Reference in a new issue