diff --git a/Projects/Server/Main.cs b/Projects/Server/Main.cs index 620d67c28..ce0097990 100644 --- a/Projects/Server/Main.cs +++ b/Projects/Server/Main.cs @@ -84,6 +84,11 @@ public static class Core // Clean streak that clears the escalation. private const long BackoffResetAfterCleanMs = 60_000; + // Backoffs below this are still recoverable and not something an operator can act on, so they + // are logged at Debug. Past it the host has stayed bad through several doublings and is worth + // a Warning; the ceiling above escalates to Error. + private const int WarnAfterConsecutiveBackoffs = 3; + // 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 @@ -91,9 +96,13 @@ public static class Core // Loop-thread only, so plain increments are safe. private static int _lateWakes; + // Denominator for the late-wake rate: sleeps actually performed in the current sample window. + 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 +124,28 @@ public static class Core _nextHealthSample = _tickCount + HealthSampleIntervalMs; var late = _lateWakes; + var sleeps = _sleepAttempts; _lateWakes = 0; + _sleepAttempts = 0; + + // A long clean streak resets the escalation, re-arming the ceiling Error so a host that + // recovers and later degrades again gets re-reported. Checked on every sample rather than + // only on bad ones, so a host that recovers for good still says so instead of waiting to + // degrade again. 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,6 +153,18 @@ public static class Core return; } + // Lateness is a rate, not a count. An idle loop performs hundreds of ~2ms sleeps a second, + // so a handful of outliers -- a co-tenant burst, a page fault, another process changing the + // system timer resolution -- is normal on a perfectly healthy host. A host that genuinely + // cannot schedule the process returns *most* of its waits late, which is two orders of + // magnitude away. The absolute threshold stays on as a floor for windows with few sleeps, + // where a proportion means nothing. + if (late * 100 < sleeps * _lateWakePercent) + { + _consecutiveBadSamples = 0; + 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. if (++_consecutiveBadSamples < 2) @@ -135,15 +177,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; @@ -167,12 +200,32 @@ public static class Core return; } + // Each backoff doubles the suspension, so every one of these is a distinct escalation step + // and needs no further rate limiting. The first couple are recoverable and not actionable, + // so they stay at Debug; only a host that survives several doublings earns a Warning. + 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 ); } @@ -565,8 +618,9 @@ 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 late-wake backoff: idle waits per second the host may return a full tick + // (8ms) late before the rate test below even applies. Raise to tolerate a jittery host; set + // very high to disable the backoff. var lateWakeThreshold = ServerConfiguration.GetSetting("server.lateWakeThreshold", 1); if (lateWakeThreshold < 0) { @@ -578,6 +632,22 @@ public static class Core _lateWakeThreshold = Math.Max(0, lateWakeThreshold); + // Share of a second's idle waits that must come back late before the backoff trips. A bare + // count cannot separate a few tail outliers from a host that never schedules us -- an idle + // loop sleeps hundreds of times a second -- but the proportion can. 0 leaves the absolute + // threshold 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 @@ -716,14 +786,24 @@ public static class Core if (due > 0) { var requested = (int)Math.Min(due, _eventLoopIdleWaitMs); + + // The GC deliberately collects during idle sleeps -- that is the natural + // pause point it looks for -- so its pauses land here by design and must + // not be charged to the host. Gen1 and above are the only ones whose pause + // approaches a tick; CollectionCount(1) counts those and gen2 with it. + 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) + // returned late can cost the wheel a deadline. The second collection read + // is short-circuited behind the overshoot test, so the common path pays for + // one counter read, not two. + if (elapsed - requested >= Timer.TickRate && GC.CollectionCount(1) == collections) { _lateWakes++; } 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. |