0628902644
Follow-ups to #2559, from a review of the ported idle-sleep/scheduler-health changes. ### Fixes - **`NetState.IsIdle` omitted `_pendingDisconnects`** — `Slice()` drains five queues; the property checked four. The other deferred work (`_connectingQueue`, alive checks, movement throttle) is time-gated and correctly excluded; the disconnect queue was the only ready-work omission. Impact was bounded (≤ one idle wait of delay), but the property's contract is "sleeping cannot strand pending work". - **Neither new setting was clamped** (`Main.cs`): - `server.lateWakeThreshold: -1` made `late <= threshold` false for every sample even at zero late wakes, so from the second sample on, sleeping was re-suspended every second, forever — a permanent full-core spin whose only trace was a nonsense warning ("… at least 8ms late 0 time(s)"). - `server.eventLoopIdleWaitMs: -1` disabled sleeping while the admin gump reported **Healthy** (it tested `== 0`). - Both now clamp to `>= 0` and log a warning naming the configured value. `-1` is a natural thing to reach for given the sibling key's doc says "set very high to disable". - **World snapshots were misattributed to `StolenMs`** — `World.Snapshot` ran outside all five profiler phases, so a 3-second save inside a sample read as ~75% stolen, and `debugging-event-loop.md` teaches stolen = "the host ran something else". The diagnostic pointed operators at buying dedicated CPU for their own largest loop-thread stall. Saves now land in a new `WorldSnapshot` phase; `[LoopStats` iterates `PhaseCount` generically, so the report and CSV pick it up with no changes. - **Admin gump conflated host-forced spin with configured spin** — when the startup probe finds no high-resolution wait support it zeroes the idle wait, after which the gump said "Spinning (configured)" and the operator's config said 2. New `Core.IdleSleepUnsupported` property; the gump now shows "Spinning - host cannot honor short waits" as a distinct fourth verdict. A genuinely configured 0 still reads "configured" (the probe only runs when the configured value was > 0). - **The backoff-ceiling `Error` logged once per process lifetime** — `_loggedBackoffCeiling` never reset, and at the ceiling the method returns before the `Warning`, so a host that recovered (>60s clean streak) and later degraded back to the ceiling never re-logged the one operator-actionable message. The flag now resets with the clean-streak escalation reset. - **Removed the unreachable "already suspended, extend" branch** — no sleeps occur while suspended, so `_lateWakes` stays 0 and every suspended sample early-returns before reaching it; with the threshold clamped it can never fire. If sleep gating ever changes, the normal path handles the case by counting a fresh episode. `dev-docs/debugging-event-loop.md` updated to match (phase list + gump verdict table). ### Verification - `dotnet build` clean (0 warnings) both normally and with `-p:EventLoopProfiling=true` (the snapshot phase only becomes live IL under the profiling flag).
7.2 KiB
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:
- Work — the loop's phases: mobile deltas, item deltas, timer callbacks (
Timer.Slice), network processing (NetState.Slice), posted tasks (LoopContext), world snapshots (WorldSnapshot— the on-loop portion of a save). - Sleep — idle blocking in
NetState.WaitForCompletion, bounded by the next timer tick andserver.eventLoopIdleWaitMs. - GC pauses — land inside whichever phase (or sleep) was running.
- 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) / Spinning - host cannot honor short waits |
Same as above; the last verdict is the startup error's state, not a config choice. |
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:
TimerSlicehot → time each timer callback, keep the max and itstimer.ToString().NetworkSlicehot → time packet handlers by packet id, keep the max.- GC pressure →
dotnet-counters monitor --counters System.Runtimefor 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:30is 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-loopbranch (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.