mirror of
https://github.com/modernuo/ModernUO
synced 2026-08-11 22:23:06 -04:00
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).
116 lines
7.2 KiB
Markdown
116 lines
7.2 KiB
Markdown
# 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`), world snapshots
|
||
(`WorldSnapshot` — the on-loop portion of a save).
|
||
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)` / `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:
|
||
|
||
- `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.
|