modernuo

mmo-ref/modernuo

Fork 0

mirror of https://github.com/modernuo/ModernUO synced 2026-08-11 22:23:06 -04:00

Commit graph

Author	SHA1	Message	Date
Kamron Batman	0628902644	fix: harden idle-sleep scheduling against bad config and misattributed saves (#2567 ) 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).	2026-08-09 22:05:18 -07:00
Kamron Batman	6d846b11e5	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.	2026-08-09 13:24:59 -07:00

Author

SHA1

Message

Date

Kamron Batman

0628902644

fix: harden idle-sleep scheduling against bad config and misattributed saves (#2567 )

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).

2026-08-09 22:05:18 -07:00

Kamron Batman

6d846b11e5

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.

2026-08-09 13:24:59 -07:00

2 commits