perf: Sleep the event loop when idle. Fixes networking micro-stalls. Adds event loop instrumentation. (#2559)
## Problem
`RunEventLoop` span through its body regardless of whether there was anything to do — ~10% of a desktop core for an empty shard, and ~70% of a core on a 3 vCPU VPS. A process that never idles is exactly what burstable vCPU plans throttle, which is how this surfaced: lag spikes that went away when the operator bought more cores. The spin also denied the GC its natural pause points, so memory climbed until a world save forced a collection — alarming in task manager, harmless in practice, and a recurring source of "is my server leaking?" reports.
## Result
Windows desktop, real world of **190,728 items / 33,158 mobiles**, no players, saves and prebake off, three consecutive runs:
| | Legacy spin | Idle sleeping |
|---|---|---|
| **CPU** | 10.42 – 10.50% of one core | **0.78 – 1.00%** |
| **Tick lag** (peak/15s) | 4–10 ms | 5–11 ms |
**~10× less CPU with tick lag unchanged** — the CPU came free rather than being traded for latency. Slower hosts gain proportionally more. Spin mode (`server.eventLoopIdleWaitMs=0`) independently gained **7× the iterations per core** (1.19M → 8.3M cycles/sec) from the ring's AcceptEx rework.
## How
The loop blocks in `NetState.WaitForCompletion` whenever every queue it drains is empty (all the drains are bounded, so leftovers keep it awake). Receive completions, new connections, and cross-thread `LoopContext.Post` (via the ring's sticky `Wake()`) are all in the wait set, so sleeping adds no latency to any of them. Only timer-driven logic sees wheel lag, bounded by the idle wait.
**Health is measured at the only place sleeping can cause harm.** A sleep is bounded by the time to the next wheel turn, so a correctly honoured sleep can never miss a deadline — the only failure mode is the host returning the wait late. That overshoot is measured on every sleep (one extra timestamp read; production's entire accounting cost), and an escalating backoff suspends sleeping when it persists. By construction, server work — saves, heavy staff commands, deep timer callbacks — cannot trip it, so the warning means exactly one thing: *the host is not scheduling the process promptly*, with two known remedies (dedicated CPU, or `=0`). Hosts with no high-resolution wait mechanism at all are detected once at startup and spin instead.
**CPS is removed.** `Core.CyclesPerSecond`/`AverageCPS` measured nothing actionable before and became actively misleading once the loop sleeps (the rate is set by the sleep, not by shard health). The admin gump's Performance page now shows the verdict instead: `Healthy` / `Sleep suspended (host)` / `Spinning (configured)`.
## Configuration
| Setting | Default | Meaning |
|---|---|---|
| `server.eventLoopIdleWaitMs` | `2` | Longest idle block. Measured across 1/2/4/8 ms, 2 is where the trade stops being free. `0` = never sleep: ~98% of a core, zero scheduling overhead — for large shards on dedicated CPU. |
| `server.lateWakeThreshold` | `1` | Idle waits the host may return a full tick late, per second, before sleeping backs off. Raise for jittery hosts; very high disables the backoff. |
## Diagnostics (compiled out by default)
`dotnet build -p:EventLoopProfiling=true` compiles in `EventLoopProfiler` — every hook is `[Conditional("EVENT_LOOP_PROFILING")]`, so normal builds contain zero profiling IL. The profiling build decomposes each second of wall time into **work (per loop phase) / sleep / GC pause / stolen residual**, keeps ~15 minutes of history in a ring buffer, and the `[LoopStats` command prints the last minute and dumps the full history to CSV. `dev-docs/debugging-event-loop.md` is the diagnosis guide (for humans and AI): what production already tells you, when to flip the profiling build, the signature table for host-steal vs deep-processing vs GC vs wake bugs, why dotnet-trace comes last, and the GC/RAM "leak" misconception.
## Verification
- 815 Server.Tests green; both build configurations compile.
- Docker echo harness green on epoll and io_uring (ping-pong mode); kqueue verified manually on an M1 Max.
- A/B measurements and per-change numbers: `measure/event-loop` branch.
## Notes
The full measurement harness and vendored ring sources used to develop this live on the [`measure/event-loop`](https://github.com/modernuo/ModernUO/tree/measure/event-loop) branch, kept for future loop work.
This commit is contained in:
parent
a7e65aab01
commit
6d846b11e5
19 changed files with 1066 additions and 46 deletions
115
dev-docs/debugging-event-loop.md
Normal file
115
dev-docs/debugging-event-loop.md
Normal file
|
|
@ -0,0 +1,115 @@
|
|||
# Debugging Event Loop Performance
|
||||
|
||||
How to diagnose "the server feels slow" — written for both humans and AI assistants. Follow the
|
||||
funnel in order; most incidents resolve before the last step. Do not start with dotnet-trace.
|
||||
|
||||
## The model
|
||||
|
||||
Every second of the main thread's wall time goes to exactly one of four places:
|
||||
|
||||
1. **Work** — the loop's phases: mobile deltas, item deltas, timer callbacks (`Timer.Slice`),
|
||||
network processing (`NetState.Slice`), posted tasks (`LoopContext`).
|
||||
2. **Sleep** — idle blocking in `NetState.WaitForCompletion`, bounded by the next timer tick and
|
||||
`server.eventLoopIdleWaitMs`.
|
||||
3. **GC pauses** — land inside whichever phase (or sleep) was running.
|
||||
4. **Stolen** — the host ran something else: hypervisor scheduling, noisy neighbors, CPU credit
|
||||
throttling.
|
||||
|
||||
A sleep is bounded by the time to the next wheel turn, so **a correctly honoured sleep can never
|
||||
cost a deadline**. The only way sleeping harms the game is the wait *returning late* — that is
|
||||
stolen time, and the server measures it directly on every sleep.
|
||||
|
||||
## Step 0 — Read what production already tells you
|
||||
|
||||
No build changes needed. Three signals exist, all actionable:
|
||||
|
||||
| Signal | Meaning | Action |
|
||||
|---|---|---|
|
||||
| Startup error: *host cannot honour short waits* | No high-resolution timer and `timeBeginPeriod` failed. Very old or unusual Windows. | Nothing is wrong with the server; it spins and uses a full core. Upgrade the OS or accept the core. |
|
||||
| Warning: *host returned a Nms idle wait late* + sleeping suspended | The OS did not reschedule the process promptly after a 1–2ms wait. Shared/burstable vCPU signature. | Move to dedicated CPU, or set `server.eventLoopIdleWaitMs=0` to spin permanently. This is a **host** problem — no amount of server-side change fixes it. |
|
||||
| Admin gump → Performance → *Event Loop* | `Healthy` / `Sleep suspended (host)` / `Spinning (configured)` | Same as above. |
|
||||
|
||||
If none of these fired and the shard still feels laggy, the cause is work, GC, or something a
|
||||
boot-time signal cannot see. Continue.
|
||||
|
||||
## Step 1 — Flip the profiling build
|
||||
|
||||
```
|
||||
dotnet build -p:EventLoopProfiling=true
|
||||
```
|
||||
|
||||
This compiles in `EventLoopProfiler` (Server) and the `[LoopStats` command (UOContent). Without
|
||||
the flag every hook call site is removed by the compiler (`[Conditional]`), so there is nothing to
|
||||
"turn off" in normal builds and no cost to leave the hooks in the code. The profiling build's own
|
||||
overhead is a handful of timestamp reads per iteration — small enough to run for days while
|
||||
hunting an intermittent problem.
|
||||
|
||||
**Capture a baseline first.** Run `[LoopStats` while the shard feels *fine* and keep the CSV. The
|
||||
profiler also keeps ~15 minutes of history in memory, so if the problem is episodic you can wait
|
||||
for an episode and the good minutes on either side are already recorded. Numbers without a
|
||||
baseline are how RunUO's profiler became useless — always compare bad minutes to good minutes on
|
||||
the same box, build, and world.
|
||||
|
||||
## Step 2 — Read the decomposition
|
||||
|
||||
`[LoopStats` prints the last minute and writes the full history CSV (one row per second). Match
|
||||
the shape against these signatures:
|
||||
|
||||
| Signature | Diagnosis | Next step |
|
||||
|---|---|---|
|
||||
| One phase consistently hot (e.g. `TimerSlice` 40%/s) | Deep processing in that subsystem | Step 3 — find the culprit in that phase |
|
||||
| All phases near zero, `stolen` high, `lateWakes` > 0 | Host is stealing CPU | Host problem; see step 0 actions |
|
||||
| `gcPauseMs` high, gen2 counts rising | GC pressure — something is allocating heavily | Step 3 on the allocating phase, or dotnet-counters for alloc rate |
|
||||
| Iterations ≫ sleeps while shard is idle | The loop is not sleeping: a queue never drains or a wake storm | Check `IsIdle` inputs; a stuck signal in the ring is the historical example |
|
||||
| Sleeps ≈ iterations, each sleep ~0ms | Spurious wake storm | Ring backend issue; count `wakesIssued` vs actual cross-thread posts |
|
||||
| Everything normal, complaint persists | Not the event loop | Look at the network path, client, or DB/save timing |
|
||||
|
||||
**Wheel lag vs player lag:** `wheelLagMaxMs` is how late timer callbacks fired. Receives are
|
||||
handled the moment they arrive (they wake the loop), so player-felt lag with a clean wheel points
|
||||
away from the loop entirely.
|
||||
|
||||
## Step 3 — Find the culprit inside a hot phase
|
||||
|
||||
Add a temporary culprit hook rather than reaching for a tracer. The pattern: same
|
||||
`[Conditional("EVENT_LOOP_PROFILING")]` attribute, own file or the profiler file, record only the
|
||||
worst offender per second (identity + duration), never a per-event log. Examples:
|
||||
|
||||
- `TimerSlice` hot → time each timer callback, keep the max and its `timer.ToString()`.
|
||||
- `NetworkSlice` hot → time packet handlers by packet id, keep the max.
|
||||
- GC pressure → `dotnet-counters monitor --counters System.Runtime` for alloc rate first; it is
|
||||
cheap and often names the culprit generation without a trace.
|
||||
|
||||
Keep the hook after the hunt if it earns its cost in the profiling build; delete it otherwise.
|
||||
|
||||
## Step 4 — dotnet-trace, last and targeted
|
||||
|
||||
Only when a hot phase resists the culprit hook. Know the costs: EventPipe visibly slows the
|
||||
process (worst exactly when things are already bad) and adds artifacts to the trace — on small
|
||||
vCPU hosts the tracer's own threads appear as hotspots and Rider/PerfView hotspot views can
|
||||
mislead. Mitigate by being narrow:
|
||||
|
||||
- Trace the specific minutes the decomposition flagged, not "a while".
|
||||
- `dotnet-trace collect --profile cpu-sampling --duration 00:00:30` is usually enough.
|
||||
- Compare against a trace of a good minute (same rule as step 1: no baseline, no conclusions).
|
||||
|
||||
## The RAM / GC misconception (read before declaring a leak)
|
||||
|
||||
ModernUO allocates very little, and the GC collects opportunistically — mostly during idle sleeps
|
||||
and world saves. Under a spinning loop (`eventLoopIdleWaitMs=0`, or the pre-2026 default) the GC
|
||||
may find **no** natural pause point: memory climbs to a large fraction of physical RAM, a forced
|
||||
collection eventually drops part of it, and fragmentation keeps the baseline permanently above
|
||||
where it started. Task manager shows alarming numbers; the in-game numbers do not. **Performance
|
||||
is unaffected — this is lazy collection working as designed, not a leak.** Idle sleeping largely
|
||||
removes the effect because every sleep is a natural GC opportunity. Before investigating "a leak":
|
||||
check `gen0/1/2` and `gcPauseMs` in the decomposition, and compare working set *after a world
|
||||
save*, which forces the collection the spin loop never allowed.
|
||||
|
||||
## Rules of thumb
|
||||
|
||||
- Never trade always-on profiling for the numbers. Production carries one timestamp per sleep and
|
||||
nothing else; everything heavier lives behind the build flag or on the `measure/event-loop`
|
||||
branch (full harness, A/B scripts, vendored ring experiments).
|
||||
- One decomposition chart beats a thousand log lines. Resist adding warnings the reader cannot
|
||||
act on; the three production signals are deliberate.
|
||||
- When filing or reporting: attach the baseline CSV and the episode CSV. Relative statements
|
||||
("TimerSlice went from 4% to 61% during the episode") are the useful form.
|
||||
Loading…
Add table
Add a link
Reference in a new issue