From 240118340e56e3440d1e0dd960d851dd56530f2b Mon Sep 17 00:00:00 2001 From: Kamron Batman <3953314+kamronbatman@users.noreply.github.com> Date: Thu, 13 Aug 2026 19:58:03 -0700 Subject: [PATCH] fix: stop the idle-sleep backoff tripping on healthy hosts (#2572) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Problem The late-wake detector added in #2559 suspends idle sleeping on perfectly healthy hosts. The visible symptom is this Warning firing periodically on stable machines: > This host returned a 2ms idle wait at least 8ms late 2 time(s) in the last second; idle sleeping suspended for 5000ms Demoting it to Debug would hide the symptom but not the cost: every one of those lines means the shard dropped idle sleeping for 5s and burned a full core for no reason. The detector is what was mis-tuned. ## Cause 1 — lateness was a count, not a rate An idle loop performs **~400–500 sleeps per second** (2ms each, bounded by the 8ms wheel tick). The trip condition was `late > 1` across two consecutive one-second samples — a **0.4% tail-outlier rate**. A co-tenant burst, a page fault, or another process changing the system timer resolution clears that bar on a healthy host. A host that genuinely cannot schedule the process — throttled burstable vCPU — returns *most* of its waits late. Signal and noise were two orders of magnitude apart, and the check sat in the noise. Now gated on the proportion, with the absolute count kept as a floor: ```csharp if (late <= _lateWakeThreshold) { _consecutiveBadSamples = 0; return; } // floor if (late * 100 < sleeps * _lateWakePercent) { _consecutiveBadSamples = 0; return; } // rate ``` New `server.lateWakePercent` (default `10`). The floor is what keeps a window with only a handful of sleeps from tripping on a meaningless percentage; `server.lateWakeThreshold` keeps its existing meaning. ## Cause 2 — GC pauses were charged to the host `dev-docs/debugging-event-loop.md` already documents that the GC collects preferentially **during idle sleeps** — that is the natural pause point it looks for. So the detector was systematically measuring the GC's chosen pause point and billing it to the host's scheduler. Not an occasional coincidence; a designed-in one. ```csharp var collections = GC.CollectionCount(1); NetState.WaitForCompletion(requested); ... if (elapsed - requested >= Timer.TickRate && GC.CollectionCount(1) == collections) ``` Gen1 (which counts gen2 with it) rather than gen0 — gen0 pauses don't approach the 8ms `TickRate` bar anyway, and gating on them would discard useful samples. The second read short-circuits behind the overshoot test, so the common path costs **one** `GC.CollectionCount` per sleep: an internal counter read, single-digit nanoseconds, ~500/sec. ## Cause 3 — every backoff logged at Warning Tiered to the escalation that already existed, since a single suspension is recoverable and not something an operator can act on: | Backoff | Level | |---|---| | 1–2 | `Debug` | | 3–5 | `Warning` (now includes the sleep count and "for the Nth time running") | | ceiling | `Error`, unchanged | | recovery | `Information` (new) | Each backoff doubles the suspension, so every line is already a distinct escalation step — no further rate limiting needed. ## Drive-by The `BackoffResetAfterCleanMs` reset only ran on the path to a *new* backoff, making it unreachable for a host that recovered for good — such a host never cleared its escalation or re-armed `_loggedBackoffCeiling`. It now runs on every health sample, which is also what makes the new recovery line reachable. ## Testing Full solution builds clean, 0 warnings. No tests added: the state is private static in `Core` coupled to `_tickCount` with no injection point, and nothing covered it before — adding a seam purely to test it seemed worse than the gap. Happy to add one if reviewers disagree. --- Projects/Server/Main.cs | 157 +++++++++++++++++++++---------- dev-docs/debugging-event-loop.md | 9 +- dev-docs/server-requirements.md | 3 +- 3 files changed, 115 insertions(+), 54 deletions(-) diff --git a/Projects/Server/Main.cs b/Projects/Server/Main.cs index 620d67c28..608256651 100644 --- a/Projects/Server/Main.cs +++ b/Projects/Server/Main.cs @@ -39,21 +39,19 @@ public static class Core { private static readonly ILogger logger = LogFactory.GetLogger(typeof(Core)); - // Written from other threads (Kill, RequestSnapshot) and read by the event loop. Volatile - // because the loop now genuinely blocks between reads rather than spinning past them. + // Written off-loop (Kill, RequestSnapshot); volatile because the loop blocks between reads. private static volatile bool _performProcessKill; private static bool _restartOnKill; private static volatile bool _performSnapshot; private static string _snapshotPath; - // A backstop, not a latency control: the wheel's tick rate bounds the sleep, so this only - // limits the damage if a wake signal is ever missed. Measured across 1/2/4/8ms, 2 is optimal. + // A backstop, not a latency control: the wheel's tick rate already bounds the sleep. + // Measured across 1/2/4/8ms; 2 is optimal. private static int _eventLoopIdleWaitMs = 2; /// - /// Longest the loop will block while idle, in milliseconds. 0 disables idle sleeping, - /// leaving the loop to spin; the adaptive backoff does the same thing temporarily when the - /// host keeps returning waits late. + /// Longest the loop will block while idle, in milliseconds. 0 spins instead; the backoff + /// does the same temporarily when the host keeps returning waits late. /// public static int EventLoopIdleWaitMs => _eventLoopIdleWaitMs; @@ -74,9 +72,8 @@ public static class Core private const long HealthSampleIntervalMs = 1000; - // Backoff escalates by doubling: a fixed suspension oscillates forever on a persistently bad - // host, while doubling converges on "stop sleeping" within minutes yet still recovers from a - // transient problem. + // Doubling: a fixed suspension oscillates forever on a persistently bad host, while doubling + // converges on "stop sleeping" yet still recovers from a transient. private const long BackoffBaseMs = 5000; private const long BackoffMaxMs = 120_000; private const int BackoffMaxShift = 5; @@ -84,16 +81,20 @@ public static class Core // Clean streak that clears the escalation. private const long BackoffResetAfterCleanMs = 60_000; - // A sleep is bounded by the time to the next wheel turn, so a correctly honoured sleep can - // never miss a deadline; the only way sleeping harms the wheel is the wait returning late - // (the host descheduled the process). That overshoot is measured per sleep, which is why - // server work -- saves, heavy commands, deep timer callbacks -- cannot trip this backoff. - // Loop-thread only, so plain increments are safe. + // Below this a backoff is still recoverable and not actionable, so it only logs at Debug. + private const int WarnAfterConsecutiveBackoffs = 3; + + // A sleep is bounded by the next wheel turn, so only a wait returning late can cost a deadline. + // Measured per sleep, which is why server work (saves, heavy commands) cannot trip the backoff. private static int _lateWakes; + // Denominator for the late-wake rate. + private static int _sleepAttempts; + private static long _nextHealthSample; private static long _idleSleepSuspendedUntil; private static int _lateWakeThreshold = 1; + private static int _lateWakePercent = 10; private static long _idleSleepBackoffs; private static int _consecutiveBadSamples; private static int _consecutiveBackoffs; @@ -115,7 +116,25 @@ public static class Core _nextHealthSample = _tickCount + HealthSampleIntervalMs; var late = _lateWakes; + var sleeps = _sleepAttempts; _lateWakes = 0; + _sleepAttempts = 0; + + // A clean streak resets the escalation and re-arms the ceiling Error. Gated on the count + // rather than a "_lastBackoffAt > 0" sentinel because tick counts are not guaranteed positive. + if (_consecutiveBackoffs > 0 && _tickCount - _lastBackoffAt > BackoffResetAfterCleanMs) + { + if (_consecutiveBackoffs >= WarnAfterConsecutiveBackoffs) + { + logger.Information( + "This host has returned idle waits on time for {Duration}ms; idle sleeping is back to normal", + BackoffResetAfterCleanMs + ); + } + + _consecutiveBackoffs = 0; + _loggedBackoffCeiling = false; + } if (late <= _lateWakeThreshold) { @@ -123,8 +142,17 @@ public static class Core return; } - // Require the condition to persist: any host can drop one sample to unrelated load, and a - // host that is genuinely oversubscribed stays that way, so it trips on the second sample. + // Lateness is a rate: an idle loop sleeps hundreds of times a second, so a few outliers are + // normal, while a host that cannot schedule the process returns most of its waits late. The + // threshold above is the floor for windows with too few sleeps for a proportion to mean anything. + if (late * 100 < sleeps * _lateWakePercent) + { + _consecutiveBadSamples = 0; + return; + } + + // Require persistence: any host can drop one sample to unrelated load, but an oversubscribed + // one stays bad. if (++_consecutiveBadSamples < 2) { return; @@ -135,15 +163,6 @@ public static class Core return; } - // A long clean streak resets the escalation, re-arming the ceiling Error so a host that - // recovers and later degrades again gets re-reported. Gated on the count rather than a - // "_lastBackoffAt > 0" sentinel because tick counts are not guaranteed positive. - if (_consecutiveBackoffs > 0 && _tickCount - _lastBackoffAt > BackoffResetAfterCleanMs) - { - _consecutiveBackoffs = 0; - _loggedBackoffCeiling = false; - } - _currentBackoffMs = Math.Min(BackoffBaseMs << Math.Min(_consecutiveBackoffs, BackoffMaxShift), BackoffMaxMs); _consecutiveBackoffs++; _lastBackoffAt = _tickCount; @@ -152,7 +171,7 @@ public static class Core if (_currentBackoffMs >= BackoffMaxMs) { - // Escalation has run out of room; say so once in terms the operator can act on. + // Escalation has run out of room; say so once. if (!_loggedBackoffCeiling) { _loggedBackoffCeiling = true; @@ -167,12 +186,31 @@ public static class Core return; } + // Each backoff doubles the suspension, so every line is a distinct escalation step and + // needs no further rate limiting. + if (_consecutiveBackoffs < WarnAfterConsecutiveBackoffs) + { + logger.Debug( + "This host returned a {Requested}ms idle wait at least {TickRate}ms late {Count} of {Sleeps} time(s) " + + "in the last second; idle sleeping suspended for {Duration}ms", + _eventLoopIdleWaitMs, + Timer.TickRate, + late, + sleeps, + _currentBackoffMs + ); + + return; + } + logger.Warning( - "This host returned a {Requested}ms idle wait at least {TickRate}ms late {Count} time(s) in the last " + - "second; idle sleeping suspended for {Duration}ms", + "This host returned a {Requested}ms idle wait at least {TickRate}ms late {Count} of {Sleeps} time(s) in " + + "the last second, for the {Backoffs}th time running; idle sleeping suspended for {Duration}ms", _eventLoopIdleWaitMs, Timer.TickRate, late, + sleeps, + _consecutiveBackoffs, _currentBackoffMs ); } @@ -361,8 +399,8 @@ public static class Core _restartOnKill = restart; _performProcessKill = true; - // Callers are usually off-loop (console input, signal handlers). Without this the loop - // would not notice the request until it woke for some other reason. + // Callers are usually off-loop (console input, signal handlers); wake so the request + // is noticed now rather than whenever the loop next surfaces. NetState.Wake(); } @@ -565,8 +603,8 @@ public static class Core _eventLoopIdleWaitMs = Math.Max(0, idleWaitMs); - // 16ms-budget misses per second before idle sleeping backs off. Raise to tolerate a - // jittery host; set very high to disable the backoff. + // Floor for the backoff: idle waits per second the host may return a full tick late before + // the rate test below applies at all. Set very high to disable the backoff. var lateWakeThreshold = ServerConfiguration.GetSetting("server.lateWakeThreshold", 1); if (lateWakeThreshold < 0) { @@ -578,6 +616,20 @@ public static class Core _lateWakeThreshold = Math.Max(0, lateWakeThreshold); + // Share of a second's idle waits that must return late before the backoff trips. 0 leaves + // the threshold above in sole charge. + var lateWakePercent = ServerConfiguration.GetSetting("server.lateWakePercent", 10); + if (lateWakePercent is < 0 or > 100) + { + logger.Warning( + "server.lateWakePercent {Value} is outside 0-100; using {Clamped}", + lateWakePercent, + Math.Clamp(lateWakePercent, 0, 100) + ); + } + + _lateWakePercent = Math.Clamp(lateWakePercent, 0, 100); + var assemblyPath = Path.Join(BaseDirectory, AssembliesConfiguration); // Load UOContent.dll @@ -594,10 +646,8 @@ public static class Core AssemblyHandler.LoadAssemblies(assemblyFiles); - // First-boot interactive setup. Runs after assemblies are loaded (so content can - // register prompts) but before any Serilog output, so console prompts are not - // interleaved with the async console sink. Handlers self-gate on first-boot state - // (e.g. "is my setting already present?"). + // First-boot interactive setup. After assemblies load so content can register prompts, + // before any Serilog output so prompts are not interleaved with the async console sink. AssemblyHandler.Invoke("ConfigurePrompts"); logger.Information("Running on {Framework}", RuntimeInformation.FrameworkDescription); @@ -607,9 +657,8 @@ public static class Core _now = DateTime.UtcNow; _firstTick = _tickCount = GetTimestamp(); - // Seed schedule state from the first real tick: tick counts are not guaranteed to start - // anywhere near zero (hypervisor pass-through counters), so zero-initialized deadlines - // would compare wrong. See dev-docs/tick-counts.md. + // Seed from a real tick: tick counts need not start near zero, so a zero-initialized + // deadline compares wrong. See dev-docs/tick-counts.md. _nextHealthSample = _tickCount + HealthSampleIntervalMs; _idleSleepSuspendedUntil = _tickCount; @@ -630,9 +679,8 @@ public static class Core PingServer.Start(); EventSink.InvokeServerStarted(); - // Without a high-resolution wait a 2ms request quantises to 15.625ms and the loop would - // quietly run a tick behind; spinning is the lesser evil and must not be silent. Only - // fires when both the ring's high-res timer and its timeBeginPeriod fallback failed. + // Without a high-resolution wait a 2ms request quantises to 15.625ms and the loop runs a + // tick behind. Only fires when the high-res timer and the timeBeginPeriod fallback both failed. if (_eventLoopIdleWaitMs > 0 && NetState.Ring?.SupportsHighResolutionWait == false) { logger.Error( @@ -649,8 +697,7 @@ public static class Core /// /// True when every queue the loop drains is empty, so sleeping cannot strand pending work. - /// The drains are bounded (ProcessDeltaQueue stops at the count seen on entry, ExecuteTasks - /// at its per-frame cap), so leftovers are normal and must keep the loop awake. + /// The drains are bounded, so leftovers are normal and must keep the loop awake. /// private static bool IsIdle() => !Mobile.HasQueuedDeltas && !Item.HasQueuedDeltas && LoopContext.IsEmpty && NetState.IsIdle; @@ -709,21 +756,28 @@ public static class Core if (_eventLoopIdleWaitMs > 0 && _tickCount - _idleSleepSuspendedUntil >= 0 && IsIdle()) { - // Re-read the clock: the loop body consumed real time, and a stale timestamp - // would overstate the time to the next tick and sleep straight past it. + // Re-read the clock: a stale timestamp overstates the time to the next tick + // and sleeps straight past it. var start = GetTimestamp(); var due = Timer.MillisecondsUntilNextTick(start); if (due > 0) { var requested = (int)Math.Min(due, _eventLoopIdleWaitMs); + + // The GC prefers to collect during idle sleeps, so its pauses land here by + // design and are not the host's fault. Gen1 and above (what + // CollectionCount(1) counts) are the only pauses long enough to reach a tick. + var collections = GC.CollectionCount(1); + NetState.WaitForCompletion(requested); var elapsed = GetTimestamp() - start; EventLoopProfiler.SleepEnd(requested, elapsed); + _sleepAttempts++; - // A sleep is bounded by the next wheel turn, so only a wait the host - // returned late can cost the wheel a deadline. - if (elapsed - requested >= Timer.TickRate) + // The second collection read sits behind the overshoot test, so the common + // path reads the counter once, not twice. + if (elapsed - requested >= Timer.TickRate && GC.CollectionCount(1) == collections) { _lateWakes++; } @@ -745,8 +799,7 @@ public static class Core _snapshotPath = snapshotPath; _performSnapshot = true; - // Save requests arrive off-loop. Wake so the snapshot starts now rather than after the - // loop happens to surface for another reason. + // Save requests arrive off-loop; wake so the snapshot starts now. NetState.Wake(); } diff --git a/dev-docs/debugging-event-loop.md b/dev-docs/debugging-event-loop.md index 8b5fdcf36..c38a0e6f7 100644 --- a/dev-docs/debugging-event-loop.md +++ b/dev-docs/debugging-event-loop.md @@ -27,9 +27,16 @@ 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. | +| Warning: *host returned a Nms idle wait late … for the Nth time running* | The OS did not reschedule the process promptly after a 1–2ms wait, through several escalating backoffs. 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. | +| Error: *keeps returning idle waits late and sleeping has backed off N times* | The escalation hit its 120s ceiling. The host is not going to recover. | As above, but stop waiting for it to settle. Logged once per degradation, re-armed after a clean minute. | | 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. | +The first two backoffs of any episode log at **Debug**, not Warning: a single suspension is +recoverable and not something an operator can act on. Raise the log level if you are chasing a +marginal host and want to see them. Late wakes that coincide with a gen1-or-higher GC are not +counted at all — the GC deliberately collects during idle sleeps, so its pauses land there by +design and are not the host's fault. + 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. diff --git a/dev-docs/server-requirements.md b/dev-docs/server-requirements.md index daf71e03e..0b2c50569 100644 --- a/dev-docs/server-requirements.md +++ b/dev-docs/server-requirements.md @@ -105,7 +105,8 @@ See the README for the full supported list. Two things are worth calling out: | Setting | Default | Why change it | |---|---|---| | `server.eventLoopIdleWaitMs` | `2` | `0` never sleeps: ~98% of one core, but zero skipped timer slots and zero lag. The choice for a large shard on dedicated CPU that would rather spend a core than risk a late wake. Above `2` the wheel starts losing slots. | -| `server.lateWakeThreshold` | `1` | Idle waits the host may return a full tick late, per second, before idle sleeping backs off. Raise on a jittery host; set very high to disable the backoff. | +| `server.lateWakeThreshold` | `1` | Floor for the backoff: idle waits the host may return a full tick late, per second, before the rate test below applies at all. Raise on a jittery host; set very high to disable the backoff. | +| `server.lateWakePercent` | `10` | Share of a second's idle waits that must come back late before idle sleeping backs off. An idle loop sleeps hundreds of times a second, so a bare count cannot tell a few tail outliers from a host that never schedules the process — a genuinely bad host misses *most* of its waits. `0` leaves `lateWakeThreshold` in sole charge. | | `world.useMultithreadedSaves` | `true` | Set `false` on 2-core hosts so saves do not contend with the game loop. | | `pathfinding.prebakeMaps` | varies | Leave off on memory-constrained hosts; it peaks above 1 GB while baking. | | `network.sendBufferSize` | 256 KB | Lower it if you are memory-bound with many connections. |