fix: stop the idle-sleep backoff tripping on healthy hosts (#2572)

## 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

@@ -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
+    // Written off-loop (Kill, RequestSnapshot); volatile because the loop blocks between reads.
-    // because the loop now genuinely blocks between reads rather than spinning past them.
     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
+    // A backstop, not a latency control: the wheel's tick rate already bounds the sleep.
-    // limits the damage if a wake signal is ever missed. Measured across 1/2/4/8ms, 2 is optimal.
+    // Measured across 1/2/4/8ms; 2 is optimal.
     private static int _eventLoopIdleWaitMs = 2;
 
     /// <summary>
-    /// Longest the loop will block while idle, in milliseconds. 0 disables idle sleeping,
+    /// Longest the loop will block while idle, in milliseconds. 0 spins instead; the backoff
-    /// leaving the loop to spin; the adaptive backoff does the same thing temporarily when the
+    /// does the same temporarily when the host keeps returning waits late.
-    /// host keeps returning waits late.
     /// </summary>
     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
+    // Doubling: a fixed suspension oscillates forever on a persistently bad host, while doubling
-    // host, while doubling converges on "stop sleeping" within minutes yet still recovers from a
+    // converges on "stop sleeping" yet still recovers from a transient.
-    // transient problem.
     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
+    // Below this a backoff is still recoverable and not actionable, so it only logs at Debug.
-    // never miss a deadline; the only way sleeping harms the wheel is the wait returning late
+    private const int WarnAfterConsecutiveBackoffs = 3;
-    // (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.
+    // A sleep is bounded by the next wheel turn, so only a wait returning late can cost a deadline.
-    // Loop-thread only, so plain increments are safe.
+    // 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
+        // Lateness is a rate: an idle loop sleeps hundreds of times a second, so a few outliers are
-        // host that is genuinely oversubscribed stays that way, so it trips on the second sample.
+        // 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 " +
+            "This host returned a {Requested}ms idle wait at least {TickRate}ms late {Count} of {Sleeps} time(s) in " +
-            "second; idle sleeping suspended for {Duration}ms",
+            "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
+        // Callers are usually off-loop (console input, signal handlers); wake so the request
-        // would not notice the request until it woke for some other reason.
+        // 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
+        // Floor for the backoff: idle waits per second the host may return a full tick late before
-        // jittery host; set very high to disable the backoff.
+        // 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
+        // First-boot interactive setup. After assemblies load so content can register prompts,
-        // register prompts) but before any Serilog output, so console prompts are not
+        // before any Serilog output so prompts are not interleaved with the async console sink.
-        // interleaved with the async console sink. Handlers self-gate on first-boot state
-        // (e.g. "is my setting already present?").
         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
+        // Seed from a real tick: tick counts need not start near zero, so a zero-initialized
-        // anywhere near zero (hypervisor pass-through counters), so zero-initialized deadlines
+        // deadline compares wrong. See dev-docs/tick-counts.md.
-        // would compare 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
+        // Without a high-resolution wait a 2ms request quantises to 15.625ms and the loop runs a
-        // quietly run a tick behind; spinning is the lesser evil and must not be silent. Only
+        // tick behind. Only fires when the high-res timer and the timeBeginPeriod fallback both failed.
-        // fires when both the ring's high-res timer and its timeBeginPeriod fallback failed.
         if (_eventLoopIdleWaitMs > 0 && NetState.Ring?.SupportsHighResolutionWait == false)
         {
             logger.Error(
@@ -649,8 +697,7 @@ public static class Core
 
     /// <summary>
     /// 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
+    /// The drains are bounded, so leftovers are normal and must keep the loop awake.
-    /// at its per-frame cap), so leftovers are normal and must keep the loop awake.
     /// </summary>
     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
+                    // Re-read the clock: a stale timestamp overstates the time to the next tick
-                    // would overstate the time to the next tick and sleep straight past it.
+                    // 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
+                        // The second collection read sits behind the overshoot test, so the common
-                        // returned late can cost the wheel a deadline.
+                        // path reads the counter once, not twice.
-                        if (elapsed - requested >= Timer.TickRate)
+                        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
+        // Save requests arrive off-loop; wake so the snapshot starts now.
-        // loop happens to surface for another reason.
         NetState.Wake();
     }
 

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.
 

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