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).
This commit is contained in:
Kamron Batman
GitHub
parent
6d846b11e5
commit
0628902644
5 changed files with 40 additions and 15 deletions
|
|
@ -26,6 +26,7 @@ public enum LoopPhase
|
|||
TimerSlice,
|
||||
NetworkSlice,
|
||||
LoopTasks,
|
||||
WorldSnapshot,
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
|
@ -42,7 +43,7 @@ public enum LoopPhase
|
|||
/// </remarks>
|
||||
public static class EventLoopProfiler
|
||||
{
|
||||
public const int PhaseCount = 5;
|
||||
public const int PhaseCount = 6;
|
||||
private const int RingSize = 900;
|
||||
private const long SampleIntervalMs = 1000;
|
||||
|
||||
|
|
|
|||
|
|
@ -57,6 +57,12 @@ public static class Core
|
|||
/// </summary>
|
||||
public static int EventLoopIdleWaitMs => _eventLoopIdleWaitMs;
|
||||
|
||||
/// <summary>
|
||||
/// True when idle sleeping was disabled at startup because the host cannot honor short
|
||||
/// waits, overriding whatever <c>server.eventLoopIdleWaitMs</c> was configured to.
|
||||
/// </summary>
|
||||
public static bool IdleSleepUnsupported { get; private set; }
|
||||
|
||||
/// <summary>
|
||||
/// Whether idle sleeping is currently suspended because the host returned waits late.
|
||||
/// </summary>
|
||||
|
|
@ -129,18 +135,13 @@ public static class Core
|
|||
return;
|
||||
}
|
||||
|
||||
// Already suspended: extend rather than counting a fresh backoff episode.
|
||||
if (_tickCount - _idleSleepSuspendedUntil < 0)
|
||||
{
|
||||
_idleSleepSuspendedUntil = _tickCount + _currentBackoffMs;
|
||||
return;
|
||||
}
|
||||
|
||||
// A long clean streak resets the escalation. Gated on the count rather than a
|
||||
// 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);
|
||||
|
|
@ -553,11 +554,29 @@ public static class Core
|
|||
ServerConfiguration.Load();
|
||||
|
||||
// 0 disables idle sleeping entirely (full-core spin, zero scheduling overhead).
|
||||
_eventLoopIdleWaitMs = ServerConfiguration.GetSetting("server.eventLoopIdleWaitMs", 2);
|
||||
var idleWaitMs = ServerConfiguration.GetSetting("server.eventLoopIdleWaitMs", 2);
|
||||
if (idleWaitMs < 0)
|
||||
{
|
||||
logger.Warning(
|
||||
"server.eventLoopIdleWaitMs {Value} is negative; using 0 (idle sleeping disabled)",
|
||||
idleWaitMs
|
||||
);
|
||||
}
|
||||
|
||||
_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.
|
||||
_lateWakeThreshold = ServerConfiguration.GetSetting("server.lateWakeThreshold", 1);
|
||||
var lateWakeThreshold = ServerConfiguration.GetSetting("server.lateWakeThreshold", 1);
|
||||
if (lateWakeThreshold < 0)
|
||||
{
|
||||
logger.Warning(
|
||||
"server.lateWakeThreshold {Value} is negative; using 0",
|
||||
lateWakeThreshold
|
||||
);
|
||||
}
|
||||
|
||||
_lateWakeThreshold = Math.Max(0, lateWakeThreshold);
|
||||
|
||||
var assemblyPath = Path.Join(BaseDirectory, AssembliesConfiguration);
|
||||
|
||||
|
|
@ -621,6 +640,7 @@ public static class Core
|
|||
"resolution failed). Idle sleeping is disabled. The loop will spin instead, using a full core."
|
||||
);
|
||||
|
||||
IdleSleepUnsupported = true;
|
||||
_eventLoopIdleWaitMs = 0;
|
||||
}
|
||||
|
||||
|
|
@ -672,8 +692,10 @@ public static class Core
|
|||
|
||||
if (_performSnapshot)
|
||||
{
|
||||
EventLoopProfiler.PhaseStart(LoopPhase.WorldSnapshot);
|
||||
// Return value is the offset that can be used to fix timers that should drift
|
||||
World.Snapshot(_snapshotPath);
|
||||
EventLoopProfiler.PhaseEnd(LoopPhase.WorldSnapshot);
|
||||
_performSnapshot = false;
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -87,7 +87,7 @@ public partial class NetState
|
|||
/// </summary>
|
||||
internal static bool IsIdle =>
|
||||
_throttled.Count == 0 && _throttledPending.Count == 0 &&
|
||||
_flushPending.Count == 0 && _disposed.Count == 0;
|
||||
_flushPending.Count == 0 && _pendingDisconnects.Count == 0 && _disposed.Count == 0;
|
||||
|
||||
/// <summary>
|
||||
/// Gets the listening addresses that the server is bound to.
|
||||
|
|
|
|||
|
|
@ -227,7 +227,8 @@ namespace Server.Gumps
|
|||
}
|
||||
case AdminGumpPage.Information_Perf:
|
||||
{
|
||||
var loopStatus = Core.EventLoopIdleWaitMs == 0 ? "Spinning (configured)" :
|
||||
var loopStatus = Core.IdleSleepUnsupported ? "Spinning - host cannot honor short waits" :
|
||||
Core.EventLoopIdleWaitMs == 0 ? "Spinning (configured)" :
|
||||
Core.IdleSleepSuspended ? "Sleep suspended - host returning waits late" : "Healthy";
|
||||
|
||||
AddLabel(20, 130, LabelHue, "Event Loop:");
|
||||
|
|
|
|||
|
|
@ -8,7 +8,8 @@ funnel in order; most incidents resolve before the last step. Do not start with
|
|||
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`).
|
||||
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.
|
||||
|
|
@ -27,7 +28,7 @@ No build changes needed. Three signals exist, all actionable:
|
|||
|---|---|---|
|
||||
| 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)` | Same as above. |
|
||||
| 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.
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue