diff --git a/.gitignore b/.gitignore index 2cc93a052..d5b26e268 100644 --- a/.gitignore +++ b/.gitignore @@ -14,6 +14,7 @@ /Distribution/Configuration/blocklist.json /Distribution/Configuration/crowdsec.json /Distribution/Configuration/expansion.json +/Distribution/Configuration/firewall.json /Distribution/Configuration/ip-allowlist*.txt /Distribution/Configuration/ip-allowlist*.txt.tmp /Distribution/Configuration/ip-blocklist.txt @@ -25,6 +26,7 @@ /Distribution/Configuration/email-settings.json /Distribution/Configuration/throttles.json /Distribution/Configuration/tot.json +/Distribution/Data/Pathfinding /Distribution/Logs /Distribution/Archives /Distribution/Backups diff --git a/CLAUDE.md b/CLAUDE.md index b1a90f6ea..849ff3175 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -29,6 +29,7 @@ Apply these when writing or reviewing `.cs` files under `Projects/`. 17. **No `System.Text.StringBuilder`** — use `ValueStringBuilder` with `stackalloc` (bounded output) or `ValueStringBuilder.Create()` (unbounded). Supports `$"..."` interpolation directly. Always use `using var` for disposal. Use `Reset()` instead of reassigning → `dev-docs/string-handling.md` 18. **Interpolation anti-patterns on handler-aware APIs** — `Send*`/`Say`/`Emote`/`PublicOverhead*`/`IPropertyList.Add`/gump `AddLabel`/`AddHtml`/`Html.Center`/`SpanWriter.Write*` all have `ref RawInterpolatedStringHandler` overloads that allocate zero strings, but only when the call-site argument is a `$"..."` literal directly. Avoid: ternaries with interpolated branches (`Send(c ? $"a" : $"b")`), switch expressions with interpolated arms, pre-built `var s = $"..."` locals (single-use), `.ToString()` / `.String()` / `string.Format` inside holes, string concat (`{a + b}`), LINQ string ops in holes. Use `:L` format spec for lowercase (`{rank:L}` not `rank.ToString().ToLowerInvariant()`) → `dev-docs/string-handling.md` § Interpolation Anti-Patterns 19. **No `InvalidateProperties()` from inside `GetProperties`** — every property a `GetProperties` override reads must be a pure read. `InvalidateProperties()` rebuilds the list in place (`Reset()` + rebuild), and `Reset()` returns the pooled interpolation buffer — which the compiler rents for the whole `$"..."` expression, so every hole is evaluated while it is live — and rewinds the packet cursor. A getter that invalidates therefore throws `ArgumentNullException` (parameter `"array"`) out of `GetProperties` from an unrelated-looking line, or silently corrupts the tooltip. The engine refuses and logs an error; `DEBUG` throws. Lazy recomputation in a getter is fine — the *notification* is not. Invalidate in the setter that changes the value, or defer with `Timer.DelayCall(InvalidateProperties)` → `dev-docs/property-lists.md` § Never Invalidate From Inside `GetProperties` +20. **Tick-count math must be wraparound-safe** — compare `Core.TickCount`/`GetTimestamp()` values only by subtraction (`a - b < 0`, never `a < b`), no zero/sign sentinels on tick fields, seed deadline fields from a real tick (never rely on the 0 default). Cloud hypervisors (GCP) pass through the host's never-resetting counter: ticks start enormous and can wrap negative. Linux affected in production; Windows not so far → `dev-docs/tick-counts.md` ## Dev-Docs Reference @@ -45,6 +46,9 @@ Apply these when writing or reviewing `.cs` files under `Projects/`. | Commands & targeting | `dev-docs/commands-targeting.md` | | Event system | `dev-docs/events.md` | | Threading model | `dev-docs/threading-model.md` | +| Server hardware requirements | `dev-docs/server-requirements.md` | +| Debugging event-loop performance (profiling build, decomposition, GC/RAM) | `dev-docs/debugging-event-loop.md` | +| Tick-count overflow rules (subtraction comparisons; GCP pass-through counters) | `dev-docs/tick-counts.md` | | Server lifecycle & bootstrap phases (Configure/ConfigurePrompts/Initialize) | `dev-docs/server-lifecycle.md` | | Platform prerequisites (ICU, tzdata, native libs per distro) | `dev-docs/platform-prerequisites.md` | | Configuration system | `dev-docs/configuration.md` | @@ -95,7 +99,18 @@ Then copy only the relevant skill files based on the task: | Migrate persistence (WorldSave) | `migrate-from-runuo/migrate-persistence` | | Migrate multi-file system | `migrate-from-runuo/migrate-systems` | -To enable a skill: `cp dev-docs/claude-skills/.md .claude/skills/` +To enable a skill — Claude Code loads `.claude/skills//SKILL.md`; a bare `.md` dropped +directly into `.claude/skills/` is **not** picked up, and newly installed skills appear in the +*next* session: + +```sh +# Standard skills (modernuo-*) +mkdir -p .claude/skills/ && cp dev-docs/claude-skills/.md .claude/skills//SKILL.md + +# Migration skills — sources live in the migrate-from-runuo/ subfolder, but install under the +# bare skill name (the table's "migrate-from-runuo/" is the source path, not the name): +mkdir -p .claude/skills/ && cp dev-docs/claude-skills/migrate-from-runuo/.md .claude/skills//SKILL.md +``` Migration skills reference the deep docs in `dev-docs/runuo-migration-docs/` and point to existing ModernUO skills for best practices. diff --git a/Directory.Build.props b/Directory.Build.props index 59311d439..30bf85099 100644 --- a/Directory.Build.props +++ b/Directory.Build.props @@ -63,6 +63,13 @@ ..\..\Rules.ruleset latest + + + $(DefineConstants);EVENT_LOOP_PROFILING + diff --git a/Projects/Server.Tests/Tests/Network/EventLoopIdleTests.cs b/Projects/Server.Tests/Tests/Network/EventLoopIdleTests.cs new file mode 100644 index 000000000..dfb8c7be7 --- /dev/null +++ b/Projects/Server.Tests/Tests/Network/EventLoopIdleTests.cs @@ -0,0 +1,69 @@ +using Xunit; + +namespace Server.Tests; + +/// +/// The event loop only sleeps when every queue it drains is empty. These drains are deliberately +/// bounded -- ExecuteTasks stops at its per-frame cap -- so leftover work is normal and must keep +/// the loop awake. Getting this wrong strands queued work for the length of a sleep. +/// +[Collection("Sequential Server Tests")] +public class EventLoopIdleTests +{ + [Fact] + public void FreshContextIsEmpty() + { + var context = new EventLoopContext(); + + Assert.True(context.IsEmpty); + } + + [Fact] + public void PostedWorkMakesContextNonEmpty() + { + var context = new EventLoopContext(); + + context.Post(() => { }); + + Assert.False(context.IsEmpty); + } + + [Fact] + public void PriorityWorkMakesContextNonEmpty() + { + var context = new EventLoopContext(); + + context.Post(() => { }, EventLoopContext.Priority.High); + + Assert.False(context.IsEmpty); + } + + [Fact] + public void ContextIsEmptyAgainOnceDrained() + { + var context = new EventLoopContext(); + context.Post(() => { }); + + context.ExecuteTasks(); + + Assert.True(context.IsEmpty); + } + + [Fact] + public void WorkBeyondThePerFrameCapKeepsContextNonEmpty() + { + // The cap is what makes IsEmpty necessary: a single ExecuteTasks pass cannot be assumed + // to have drained everything, so the loop must not treat "I just ran tasks" as "idle". + const int perFrameCap = 128; + var context = new EventLoopContext(perFrameCap); + + for (var i = 0; i < perFrameCap + 10; i++) + { + context.Post(() => { }); + } + + context.ExecuteTasks(); + + Assert.False(context.IsEmpty); + } +} diff --git a/Projects/Server/Diagnostics/EventLoopProfiler.cs b/Projects/Server/Diagnostics/EventLoopProfiler.cs new file mode 100644 index 000000000..a3fd157f5 --- /dev/null +++ b/Projects/Server/Diagnostics/EventLoopProfiler.cs @@ -0,0 +1,233 @@ +/************************************************************************* + * ModernUO * + * Copyright 2019-2026 - ModernUO Development Team * + * Email: hi@modernuo.com * + * File: EventLoopProfiler.cs * + * * + * This program is free software: you can redistribute it and/or modify * + * it under the terms of the GNU General Public License as published by * + * the Free Software Foundation, either version 3 of the License, or * + * (at your option) any later version. * + * * + * You should have received a copy of the GNU General Public License * + * along with this program. If not, see . * + *************************************************************************/ + +using System; +using System.Diagnostics; +using System.Runtime.CompilerServices; + +namespace Server; + +public enum LoopPhase +{ + MobileDeltas, + ItemDeltas, + TimerSlice, + NetworkSlice, + LoopTasks, +} + +/// +/// Event-loop time accounting, compiled out of normal builds. Build with +/// -p:EventLoopProfiling=true to enable; every hook is +/// [Conditional("EVENT_LOOP_PROFILING")], so without the flag the call sites do not exist +/// in the IL and this class is dormant. See dev-docs/debugging-event-loop.md for how to read it. +/// +/// +/// Each one-second sample decomposes wall time into work (per ), sleep, +/// GC pause, and a stolen residual (wall - work - sleep): time the host ran something else. +/// Samples land in a ring buffer (~15 minutes) so a lag episode can be compared against the good +/// minutes on the same box, build, and world — the baseline RunUO's profiler never had. +/// +public static class EventLoopProfiler +{ + public const int PhaseCount = 5; + private const int RingSize = 900; + private const long SampleIntervalMs = 1000; + + public struct Sample + { + public long WallStart; // Core.TickCount at sample start + public long WallMs; // sample length + public long Iterations; + public long Sleeps; + public double SleepMs; // total time blocked in WaitForCompletion + public double SleepOvershootMaxMs; // worst (elapsed - requested) this sample + public long LateWakes; // overshoot >= Timer.TickRate + public long WheelLagMaxMs; // worst wheel lateness observed at Slice entry + public long WakesIssued; + public long WakesElided; + public double GcPauseMs; // GC.GetTotalPauseDuration delta + public int Gen0; + public int Gen1; + public int Gen2; + public PhaseTimes Phases; + + // Work the phases did not account for and the loop did not spend sleeping: host + // scheduling steals, and anything between the bracketed phases. GC pauses inside a + // phase or sleep inflate those measurements instead, so GcPauseMs overlaps rather + // than subtracts. + public double StolenMs + { + get + { + var known = SleepMs + Phases.Total; + return WallMs > known ? WallMs - known : 0; + } + } + } + + [InlineArray(PhaseCount)] + public struct PhaseTimes + { + private double _element0; + + public double Total + { + get + { + double total = 0; + for (var i = 0; i < PhaseCount; i++) + { + total += this[i]; + } + + return total; + } + } + } + + private static readonly double _msPerTick = 1000.0 / Stopwatch.Frequency; + + private static Sample[] _ring; + private static int _ringCount; + private static int _ringHead; + + private static Sample _current; + private static long _phaseStartTimestamp; + private static long _sampleStartedAt; + private static TimeSpan _lastGcPause; + private static int _lastGen0; + private static int _lastGen1; + private static int _lastGen2; + + /// Number of samples recorded so far (capped at the ring size). + public static int SampleCount => _ringCount; + + /// The sample currently being accumulated (not yet in the ring). + public static Sample Current => _current; + + /// + /// Copies the newest completed samples, oldest first. + /// + public static Sample[] History(int count = RingSize) + { + count = Math.Min(count, _ringCount); + var result = new Sample[count]; + for (var i = 0; i < count; i++) + { + result[i] = _ring[(_ringHead - count + i + RingSize) % RingSize]; + } + + return result; + } + + [Conditional("EVENT_LOOP_PROFILING")] + public static void IterationStart(long tickCount) + { + if (_ring == null) + { + _ring = new Sample[RingSize]; + _sampleStartedAt = tickCount; + _current.WallStart = tickCount; + _lastGcPause = GC.GetTotalPauseDuration(); + _lastGen0 = GC.CollectionCount(0); + _lastGen1 = GC.CollectionCount(1); + _lastGen2 = GC.CollectionCount(2); + } + + _current.Iterations++; + + if (tickCount - _sampleStartedAt < SampleIntervalMs) + { + return; + } + + _current.WallMs = tickCount - _sampleStartedAt; + + var pause = GC.GetTotalPauseDuration(); + _current.GcPauseMs = (pause - _lastGcPause).TotalMilliseconds; + _lastGcPause = pause; + + var gen0 = GC.CollectionCount(0); + var gen1 = GC.CollectionCount(1); + var gen2 = GC.CollectionCount(2); + _current.Gen0 = gen0 - _lastGen0; + _current.Gen1 = gen1 - _lastGen1; + _current.Gen2 = gen2 - _lastGen2; + _lastGen0 = gen0; + _lastGen1 = gen1; + _lastGen2 = gen2; + + _ring[_ringHead] = _current; + _ringHead = (_ringHead + 1) % RingSize; + if (_ringCount < RingSize) + { + _ringCount++; + } + + _sampleStartedAt = tickCount; + _current = default; + _current.WallStart = tickCount; + } + + [Conditional("EVENT_LOOP_PROFILING")] + public static void PhaseStart(LoopPhase phase) => _phaseStartTimestamp = Stopwatch.GetTimestamp(); + + [Conditional("EVENT_LOOP_PROFILING")] + public static void PhaseEnd(LoopPhase phase) => + _current.Phases[(int)phase] += (Stopwatch.GetTimestamp() - _phaseStartTimestamp) * _msPerTick; + + [Conditional("EVENT_LOOP_PROFILING")] + public static void SleepEnd(int requestedMs, long elapsedMs) + { + _current.Sleeps++; + _current.SleepMs += elapsedMs; + + var overshoot = elapsedMs - requestedMs; + if (overshoot > _current.SleepOvershootMaxMs) + { + _current.SleepOvershootMaxMs = overshoot; + } + + if (overshoot >= Timer.TickRate) + { + _current.LateWakes++; + } + } + + [Conditional("EVENT_LOOP_PROFILING")] + public static void WheelSlice(long deltaSinceTurn) + { + var lag = deltaSinceTurn - Timer.TickRate; + if (lag > _current.WheelLagMaxMs) + { + _current.WheelLagMaxMs = lag; + } + } + + // Cross-thread; approximate counts are fine for diagnosis, so no interlocked. + [Conditional("EVENT_LOOP_PROFILING")] + public static void WakeSignal(bool elided) + { + if (elided) + { + _current.WakesElided++; + } + else + { + _current.WakesIssued++; + } + } +} diff --git a/Projects/Server/EventLoopTasks.cs b/Projects/Server/EventLoopTasks.cs index 88ae35b49..c3ff2c10c 100644 --- a/Projects/Server/EventLoopTasks.cs +++ b/Projects/Server/EventLoopTasks.cs @@ -42,10 +42,47 @@ public sealed class EventLoopContext : SynchronizationContext public override SynchronizationContext CreateCopy() => new EventLoopContext(); - public void Post(Action d, Priority priority = Priority.Normal) => - (priority == Priority.High ? _priorityQueue : _queue).Enqueue(d); + /// + /// True when no callbacks are waiting to run. + /// + /// + /// drains at most _maxPerFrame callbacks, so work can + /// legitimately be left over. The event loop checks this before sleeping so a backlog keeps + /// it running instead. + /// + public bool IsEmpty => _queue.IsEmpty && _priorityQueue.IsEmpty; - public override void Post(SendOrPostCallback d, object state) => _queue.Enqueue(() => d(state)); + public void Post(Action d, Priority priority = Priority.Normal) + { + (priority == Priority.High ? _priorityQueue : _queue).Enqueue(d); + WakeEventLoop(); + } + + public override void Post(SendOrPostCallback d, object state) + { + _queue.Enqueue(() => d(state)); + WakeEventLoop(); + } + + /// + /// Nudges the game loop in case it is asleep: the loop blocks on network I/O, which a queue + /// push alone does not signal. + /// + private void WakeEventLoop() + { + // A post from the loop thread cannot need a wake -- the loop is executing this very call + // -- and the signal is a syscall on every backend. + if (Thread.CurrentThread == _mainThread) + { + EventLoopProfiler.WakeSignal(elided: true); + return; + } + + EventLoopProfiler.WakeSignal(elided: false); + + // Safe before networking is configured and after teardown; NetState.Wake does nothing. + Network.NetState.Wake(); + } public override void Send(SendOrPostCallback d, object state) { @@ -63,6 +100,8 @@ public sealed class EventLoopContext : SynchronizationContext evt.Set(); }); + WakeEventLoop(); + evt.WaitOne(); } diff --git a/Projects/Server/Items/Item.cs b/Projects/Server/Items/Item.cs index 186437400..64cef9526 100644 --- a/Projects/Server/Items/Item.cs +++ b/Projects/Server/Items/Item.cs @@ -3325,6 +3325,12 @@ public partial class Item : IHued, IComparable, ISpawnable, IObjectPropert m_DeltaFlags &= ~flags; } + /// + /// True when deltas remain queued after a pass, which is + /// bounded by the count it saw on entry. The event loop consults this before sleeping. + /// + public static bool HasQueuedDeltas => m_DeltaQueue.Count > 0; + public static void ProcessDeltaQueue() { var limit = m_DeltaQueue.Count; diff --git a/Projects/Server/Main.cs b/Projects/Server/Main.cs index 2be9d7d04..eb95e6d4e 100644 --- a/Projects/Server/Main.cs +++ b/Projects/Server/Main.cs @@ -39,10 +39,142 @@ public static class Core { private static readonly ILogger logger = LogFactory.GetLogger(typeof(Core)); - private static bool _performProcessKill; + // 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. + private static volatile bool _performProcessKill; private static bool _restartOnKill; - private static bool _performSnapshot; + 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. + 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. + /// + public static int EventLoopIdleWaitMs => _eventLoopIdleWaitMs; + + /// + /// Whether idle sleeping is currently suspended because the host returned waits late. + /// + /// + /// Compared by subtraction, never directly: tick counts can start enormous and wrap. + /// See dev-docs/tick-counts.md. + /// + public static bool IdleSleepSuspended => _tickCount - _idleSleepSuspendedUntil < 0; + + 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. + private const long BackoffBaseMs = 5000; + private const long BackoffMaxMs = 120_000; + private const int BackoffMaxShift = 5; + + // 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. + private static int _lateWakes; + + private static long _nextHealthSample; + private static long _idleSleepSuspendedUntil; + private static int _lateWakeThreshold = 1; + private static long _idleSleepBackoffs; + private static int _consecutiveBadSamples; + private static int _consecutiveBackoffs; + private static long _currentBackoffMs = BackoffBaseMs; + private static long _lastBackoffAt; + private static bool _loggedBackoffCeiling; + + /// + /// Once a second, suspends idle sleeping (with escalating duration) if the host keeps + /// returning idle waits a full tick or more late. + /// + private static void CheckSchedulerHealth() + { + if (_tickCount - _nextHealthSample < 0) + { + return; + } + + _nextHealthSample = _tickCount + HealthSampleIntervalMs; + + var late = _lateWakes; + _lateWakes = 0; + + if (late <= _lateWakeThreshold) + { + _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) + { + return; + } + + if (_eventLoopIdleWaitMs <= 0) + { + 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 + // "_lastBackoffAt > 0" sentinel because tick counts are not guaranteed positive. + if (_consecutiveBackoffs > 0 && _tickCount - _lastBackoffAt > BackoffResetAfterCleanMs) + { + _consecutiveBackoffs = 0; + } + + _currentBackoffMs = Math.Min(BackoffBaseMs << Math.Min(_consecutiveBackoffs, BackoffMaxShift), BackoffMaxMs); + _consecutiveBackoffs++; + _lastBackoffAt = _tickCount; + _idleSleepSuspendedUntil = _tickCount + _currentBackoffMs; + _idleSleepBackoffs++; + + if (_currentBackoffMs >= BackoffMaxMs) + { + // Escalation has run out of room; say so once in terms the operator can act on. + if (!_loggedBackoffCeiling) + { + _loggedBackoffCeiling = true; + logger.Error( + "This host keeps returning idle waits late and sleeping has backed off {Count} times. " + + "The process is not being scheduled promptly, which is typical of shared or burstable vCPUs. " + + "Set server.eventLoopIdleWaitMs to 0 to disable sleeping permanently and trade a full core for latency.", + _idleSleepBackoffs + ); + } + + 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", + _eventLoopIdleWaitMs, + Timer.TickRate, + late, + _currentBackoffMs + ); + } private static bool _crashed; private static string _baseDirectory; @@ -111,14 +243,6 @@ public static class Core public static long Uptime => TickCount - _firstTick; - private static double _currentCPS; - private static double _averageCPS; - private static bool _cpsInitialized; - - public static double CyclesPerSecond => _currentCPS; - - public static double AverageCPS => _averageCPS; - public static string BaseDirectory { get @@ -235,6 +359,10 @@ 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. + NetState.Wake(); } public static void CurrentDomain_UnhandledException(object sender, UnhandledExceptionEventArgs e) @@ -424,6 +552,13 @@ public static class Core ServerConfiguration.Load(); + // 0 disables idle sleeping entirely (full-core spin, zero scheduling overhead). + _eventLoopIdleWaitMs = ServerConfiguration.GetSetting("server.eventLoopIdleWaitMs", 2); + + // 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 assemblyPath = Path.Join(BaseDirectory, AssembliesConfiguration); // Load UOContent.dll @@ -453,6 +588,12 @@ 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. + _nextHealthSample = _tickCount + HealthSampleIntervalMs; + _idleSleepSuspendedUntil = _tickCount; + Timer.Init(_tickCount); AssemblyHandler.Invoke("Configure"); @@ -469,34 +610,63 @@ public static class Core NetState.Start(); 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. + if (_eventLoopIdleWaitMs > 0 && NetState.Ring?.SupportsHighResolutionWait == false) + { + logger.Error( + "This host cannot honor short waits (no high-resolution timer, and raising the system timer " + + "resolution failed). Idle sleeping is disabled. The loop will spin instead, using a full core." + ); + + _eventLoopIdleWaitMs = 0; + } + RunEventLoop(); } + /// + /// 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. + /// + private static bool IsIdle() => + !Mobile.HasQueuedDeltas && !Item.HasQueuedDeltas && LoopContext.IsEmpty && NetState.IsIdle; + public static void RunEventLoop() { try { - var lastRaw = Stopwatch.GetTimestamp(); - const int interval = 100; - double frequency = Stopwatch.Frequency * interval; - const double alpha = 2.0 / 129; // EMA smoothing (≈128-sample window) - - var sample = 0; - while (!Closing) { _tickCount = GetTimestamp(); _now = DateTime.UtcNow; + EventLoopProfiler.IterationStart(_tickCount); + + EventLoopProfiler.PhaseStart(LoopPhase.MobileDeltas); Mobile.ProcessDeltaQueue(); + EventLoopProfiler.PhaseEnd(LoopPhase.MobileDeltas); + + EventLoopProfiler.PhaseStart(LoopPhase.ItemDeltas); Item.ProcessDeltaQueue(); + EventLoopProfiler.PhaseEnd(LoopPhase.ItemDeltas); + + EventLoopProfiler.PhaseStart(LoopPhase.TimerSlice); Timer.Slice(_tickCount); + EventLoopProfiler.PhaseEnd(LoopPhase.TimerSlice); // Handle networking + EventLoopProfiler.PhaseStart(LoopPhase.NetworkSlice); NetState.Slice(); + EventLoopProfiler.PhaseEnd(LoopPhase.NetworkSlice); // Execute captured post-await methods (like Timer.Pause) + EventLoopProfiler.PhaseStart(LoopPhase.LoopTasks); LoopContext.ExecuteTasks(); + EventLoopProfiler.PhaseEnd(LoopPhase.LoopTasks); Timer.CheckTimerPool(); // Check for pool depletion so we can async refill it. @@ -513,29 +683,28 @@ public static class Core break; } - if (sample++ == interval) + CheckSchedulerHealth(); + + if (_eventLoopIdleWaitMs > 0 && _tickCount - _idleSleepSuspendedUntil >= 0 && IsIdle()) { - sample = 0; - var nowRaw = Stopwatch.GetTimestamp(); - - _currentCPS = frequency / (nowRaw - lastRaw); - - if (!_cpsInitialized) + // 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. + var start = GetTimestamp(); + var due = Timer.MillisecondsUntilNextTick(start); + if (due > 0) { - _averageCPS = _currentCPS; - _cpsInitialized = true; - } - else - { - _averageCPS += alpha * (_currentCPS - _averageCPS); - } + var requested = (int)Math.Min(due, _eventLoopIdleWaitMs); + NetState.WaitForCompletion(requested); - lastRaw = nowRaw; + var elapsed = GetTimestamp() - start; + EventLoopProfiler.SleepEnd(requested, elapsed); - var sleepMs = (int)Timer.MillisecondsUntilNextTick(_tickCount); - if (sleepMs >= 2) - { - NetState.WaitForCompletion(sleepMs - 1); + // 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) + { + _lateWakes++; + } } } } @@ -553,6 +722,10 @@ 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. + NetState.Wake(); } public static void VerifySerialization() diff --git a/Projects/Server/Mobiles/Mobile.cs b/Projects/Server/Mobiles/Mobile.cs index f22c9a939..e47f977a7 100644 --- a/Projects/Server/Mobiles/Mobile.cs +++ b/Projects/Server/Mobiles/Mobile.cs @@ -7834,6 +7834,12 @@ public partial class Mobile : IHued, IComparable, ISpawnable, IObjectPro } } + /// + /// True when deltas remain queued after a pass, which is + /// bounded by the count it saw on entry. The event loop consults this before sleeping. + /// + public static bool HasQueuedDeltas => m_DeltaQueue.Count > 0; + public static void ProcessDeltaQueue() { var limit = m_DeltaQueue.Count; diff --git a/Projects/Server/Network/NetState/NetState.Network.cs b/Projects/Server/Network/NetState/NetState.Network.cs index 7a17d8cd0..9cb7b85fb 100644 --- a/Projects/Server/Network/NetState/NetState.Network.cs +++ b/Projects/Server/Network/NetState/NetState.Network.cs @@ -71,6 +71,24 @@ public partial class NetState _socketManager?.WaitForCompletion(timeoutMs); } + /// + /// Wakes the game loop if it is blocked in . Safe from any + /// thread; a no-op before networking is configured or after teardown. The signal is sticky, + /// so a wake racing the loop's decision to sleep is not lost. + /// + public static void Wake() + { + _socketManager?.Ring?.Wake(); + } + + /// + /// True when no queued network work remains for the loop to drain. defers + /// work in several places, so an empty completion queue alone is not enough. + /// + internal static bool IsIdle => + _throttled.Count == 0 && _throttledPending.Count == 0 && + _flushPending.Count == 0 && _disposed.Count == 0; + /// /// Gets the listening addresses that the server is bound to. /// diff --git a/Projects/Server/Server.csproj b/Projects/Server/Server.csproj index 8ad6a610b..49d8d496a 100644 --- a/Projects/Server/Server.csproj +++ b/Projects/Server/Server.csproj @@ -34,7 +34,7 @@ - + diff --git a/Projects/Server/Timer/Timer.TimerWheel.cs b/Projects/Server/Timer/Timer.TimerWheel.cs index 8c9dc47fd..2ab3ce547 100644 --- a/Projects/Server/Timer/Timer.TimerWheel.cs +++ b/Projects/Server/Timer/Timer.TimerWheel.cs @@ -51,8 +51,15 @@ public partial class Timer } } + /// + /// Milliseconds of simulated time one wheel turn advances. + /// + public static int TickRate => _tickRate; + public static void Slice(long tickCount) { + EventLoopProfiler.WheelSlice(tickCount - _lastTickTurned); + var deltaSinceTurn = tickCount - _lastTickTurned; while (deltaSinceTurn >= _tickRate) { diff --git a/Projects/UOContent/Commands/LoopStats.cs b/Projects/UOContent/Commands/LoopStats.cs new file mode 100644 index 000000000..012de68d8 --- /dev/null +++ b/Projects/UOContent/Commands/LoopStats.cs @@ -0,0 +1,117 @@ +#if EVENT_LOOP_PROFILING +using System; +using System.Globalization; +using System.IO; +using Server.Logging; + +namespace Server.Commands; + +/// +/// Reports the event-loop time decomposition recorded by . +/// Only compiled when the server is built with -p:EventLoopProfiling=true. +/// See dev-docs/debugging-event-loop.md for how to read the output. +/// +public static class LoopStats +{ + private static readonly ILogger logger = LogFactory.GetLogger(typeof(LoopStats)); + + public static void Configure() + { + CommandSystem.Register("LoopStats", AccessLevel.Administrator, LoopStats_OnCommand); + } + + [Usage("LoopStats")] + [Description("Summarizes the last minute of event-loop time accounting and writes the full history to a CSV.")] + private static void LoopStats_OnCommand(CommandEventArgs e) + { + var history = EventLoopProfiler.History(); + if (history.Length == 0) + { + e.Mobile.SendMessage("No samples recorded yet."); + return; + } + + var window = Math.Min(60, history.Length); + + double wall = 0, sleep = 0, gc = 0, stolen = 0, stolenMax = 0; + long iterations = 0, sleeps = 0, lateWakes = 0, wheelLagMax = 0; + Span phases = stackalloc double[EventLoopProfiler.PhaseCount]; + Span phaseMax = stackalloc double[EventLoopProfiler.PhaseCount]; + + for (var i = history.Length - window; i < history.Length; i++) + { + ref var s = ref history[i]; + wall += s.WallMs; + sleep += s.SleepMs; + gc += s.GcPauseMs; + stolen += s.StolenMs; + iterations += s.Iterations; + sleeps += s.Sleeps; + lateWakes += s.LateWakes; + + if (s.StolenMs > stolenMax) + { + stolenMax = s.StolenMs; + } + + if (s.WheelLagMaxMs > wheelLagMax) + { + wheelLagMax = s.WheelLagMaxMs; + } + + for (var p = 0; p < EventLoopProfiler.PhaseCount; p++) + { + phases[p] += s.Phases[p]; + if (s.Phases[p] > phaseMax[p]) + { + phaseMax[p] = s.Phases[p]; + } + } + } + + e.Mobile.SendMessage($"Loop, last {window}s of wall time {wall:F0}ms:"); + e.Mobile.SendMessage($" sleep {100 * sleep / wall:F1}%, gc {100 * gc / wall:F1}%, stolen {100 * stolen / wall:F1}% (worst {stolenMax:F0}ms/s)"); + + for (var p = 0; p < EventLoopProfiler.PhaseCount; p++) + { + e.Mobile.SendMessage($" {(LoopPhase)p}: {100 * phases[p] / wall:F1}% (worst {phaseMax[p]:F0}ms/s)"); + } + + e.Mobile.SendMessage($" {iterations} iterations, {sleeps} sleeps, {lateWakes} late wakes, worst wheel lag {wheelLagMax}ms"); + + var path = Path.Combine(Core.BaseDirectory, $"loopstats-{Core.Now:yyyyMMdd-HHmmss}.csv"); + WriteCsv(path, history); + e.Mobile.SendMessage($"Full history ({history.Length} samples) written to {path}"); + logger.Information("Loop stats dumped to {Path}", path); + } + + private static void WriteCsv(string path, EventLoopProfiler.Sample[] history) + { + using var writer = new StreamWriter(path); + writer.Write("wallStart,wallMs,iterations,sleeps,sleepMs,sleepOvershootMaxMs,lateWakes,wheelLagMaxMs,wakesIssued,wakesElided,gcPauseMs,gen0,gen1,gen2,stolenMs"); + for (var p = 0; p < EventLoopProfiler.PhaseCount; p++) + { + writer.Write(','); + writer.Write((LoopPhase)p); + } + + writer.WriteLine(); + + for (var i = 0; i < history.Length; i++) + { + ref var s = ref history[i]; + writer.Write(string.Create( + CultureInfo.InvariantCulture, + $"{s.WallStart},{s.WallMs},{s.Iterations},{s.Sleeps},{s.SleepMs:F2},{s.SleepOvershootMaxMs:F2},{s.LateWakes},{s.WheelLagMaxMs},{s.WakesIssued},{s.WakesElided},{s.GcPauseMs:F2},{s.Gen0},{s.Gen1},{s.Gen2},{s.StolenMs:F2}" + )); + for (var p = 0; p < EventLoopProfiler.PhaseCount; p++) + { + writer.Write(','); + writer.Write(string.Create(CultureInfo.InvariantCulture, $"{s.Phases[p]:F2}")); + } + + writer.WriteLine(); + } + } +} +#endif diff --git a/Projects/UOContent/Gumps/AdminGump.cs b/Projects/UOContent/Gumps/AdminGump.cs index 3a48bc5aa..130d031fc 100644 --- a/Projects/UOContent/Gumps/AdminGump.cs +++ b/Projects/UOContent/Gumps/AdminGump.cs @@ -227,9 +227,11 @@ namespace Server.Gumps } case AdminGumpPage.Information_Perf: { - AddLabel(20, 130, LabelHue, "Cycles Per Second:"); - AddLabel(40, 150, LabelHue, $"Current: {Core.CyclesPerSecond:N2}"); - AddLabel(40, 170, LabelHue, $"Average: {Core.AverageCPS:N2}"); + var loopStatus = Core.EventLoopIdleWaitMs == 0 ? "Spinning (configured)" : + Core.IdleSleepSuspended ? "Sleep suspended - host returning waits late" : "Healthy"; + + AddLabel(20, 130, LabelHue, "Event Loop:"); + AddLabel(40, 150, LabelHue, loopStatus); using var sb = ValueStringBuilder.Create(); diff --git a/README.md b/README.md index 2321fe8e3..b8d49f544 100644 --- a/README.md +++ b/README.md @@ -15,7 +15,7 @@ ModernUO [![Discord](https://img.shields.io/discord/751317910504603701?logo=disc ## Requirements #### Supported Operating Systems -[![Windows 10/11/2012/2016/2019/2022/2025](https://img.shields.io/badge/-server%202025-3c78d5?labelColor=222222&logo=data:image/svg%2bxml;base64,PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHJvbGU9ImltZyIgdmlld0JveD0iMCAwIDI0IDI0Ij48dGl0bGU+V2luZG93czwvdGl0bGU+PHBhdGggZD0iTTAsMEgxMS4zNzdWMTEuMzcySDBaTTEyLjYyMywwSDI0VjExLjM3MkgxMi42MjNaTTAsMTIuNjIzSDExLjM3N1YyNEgwWm0xMi42MjMsMEgyNFYyNEgxMi42MjMiIGZpbGw9IiMzYzc4ZDUiLz48L3N2Zz4=)](https://www.microsoft.com/en-US/evalcenter/evaluate-windows-server-2022) +[![Windows 10/11/2012 R2/2016/2019/2022/2025](https://img.shields.io/badge/-server%202025-3c78d5?labelColor=222222&logo=data:image/svg%2bxml;base64,PHN2ZyB4bWxucz0iaHR0cDovL3d3dy53My5vcmcvMjAwMC9zdmciIHJvbGU9ImltZyIgdmlld0JveD0iMCAwIDI0IDI0Ij48dGl0bGU+V2luZG93czwvdGl0bGU+PHBhdGggZD0iTTAsMEgxMS4zNzdWMTEuMzcySDBaTTEyLjYyMywwSDI0VjExLjM3MkgxMi42MjNaTTAsMTIuNjIzSDExLjM3N1YyNEgwWm0xMi42MjMsMEgyNFYyNEgxMi42MjMiIGZpbGw9IiMzYzc4ZDUiLz48L3N2Zz4=)](https://www.microsoft.com/en-US/evalcenter/evaluate-windows-server-2022) ![MacOS 14+](https://img.shields.io/badge/-sonoma-222222?logo=apple&logoColor=white&labelColor=222222) [![Debian 12+](https://img.shields.io/badge/-trixie-A81D33?logo=debian&logoColor=A81D33&labelColor=222222)](https://www.debian.org/distrib/) [![Ubuntu 22+ LTS](https://img.shields.io/badge/-26LTS-E95420?logo=ubuntu&logoColor=E95420&labelColor=222222)](https://ubuntu.com/download/server) @@ -37,6 +37,23 @@ ModernUO [![Discord](https://img.shields.io/discord/751317910504603701?logo=disc ##### Windows [![VC++ Redistributable v14](https://img.shields.io/badge/-Redist%20v14-00599C?logo=cplusplus&logoColor=white&labelColor=222222)](https://aka.ms/vc14/vc_redist.x64.exe) +#### Hardware + +| Use | vCPU | RAM | Storage | +|---|---|---|---| +| Development / test | 2 **dedicated** | 2 GB | SSD | +| Small live shard (< 50 concurrent) | 4 dedicated | 4 GB | NVMe | +| Medium (50–200) | 4–8 | 8 GB | NVMe | +| Large (200+) | 8+, high clock | 16 GB+ | NVMe | + +Game logic is single-threaded, so **single-core clock speed matters more than core count**, and +**dedicated vCPU matters more than either** — burstable or shared plans throttle once credits run +out, which is the most common cause of unexplained lag spikes. Save size drives RAM more than +player count does. + +See [dev-docs/server-requirements.md](dev-docs/server-requirements.md) for the reasoning and tuning +options. + #### Development [![git](https://img.shields.io/badge/-git-F05032?logo=git&logoColor=F05032&labelColor=222222)](https://git-scm.com/downloads) [![.NET](https://img.shields.io/badge/-%2010.0.100%20SDK-5C2D91?logo=.NET&logoColor=white&labelColor=222222)](https://dotnet.microsoft.com/download/dotnet/10.0) diff --git a/dev-docs/claude-skills/modernuo-code-audit.md b/dev-docs/claude-skills/modernuo-code-audit.md index 5d5af15bb..d805b0578 100644 --- a/dev-docs/claude-skills/modernuo-code-audit.md +++ b/dev-docs/claude-skills/modernuo-code-audit.md @@ -200,8 +200,27 @@ mob.SendMessage($"You earned a {rank:L} trophy!"); // "gold" not "Gold" **See**: `dev-docs/property-lists.md` § "Never Invalidate From Inside `GetProperties`". +### 20. Tick-Count Math Must Be Wraparound-Safe +**Check**: Every comparison between `Core.TickCount` / `Core.GetTimestamp()` values (or fields +derived from them — names like `*Until`, `*At`, `*Next*`, `deadline`) must be in subtraction form. +Flag direct comparisons, zero/sign sentinels, and deadline fields left at their zero default. +**Bad**: `if (Core.TickCount < _deadline)`; `if (_lastEventAt > 0)` as "has happened"; +`private static long _deadline;` compared before being seeded from a real tick. +**Good**: `if (Core.TickCount - _deadline < 0)`; a separate `bool` for "has happened"; seeding +deadline fields from the first observed timestamp. +**Why**: On some hypervisors — Google Cloud specifically — the VM receives a pass-through of the +host's never-resetting counter. Tick counts are NOT zero at process start, NOT zero at OS boot, +can be enormous from the first read, and can wrap negative. Direct comparisons and sign sentinels +then fail only on those hosts, after long host uptimes — the least reproducible bug class there +is. Windows has not shown this in testing; Linux has, in production. Subtraction of two ticks +wraps correctly in two's complement. +**Note**: `DateTime`/`DateTimeOffset` comparisons are unaffected; this applies only to the +monotonic tick domain. + +**See**: `dev-docs/tick-counts.md` for the full rules and review checklist. + ## Severity Levels -- **ERROR**: Rules 3, 9, 10, 13, 19 (will cause bugs, build failures, or client-side leaks) +- **ERROR**: Rules 3, 9, 10, 13, 19, 20 (will cause bugs, build failures, or client-side leaks) - **WARNING**: Rules 1 (Tier 3 LINQ), 2, 4, 5, 6, 7, 8, 12, 14, 15, 17 (performance/convention issues) - **INFO**: Rules 1 (Tier 2 LINQ on warm paths — note it but don't flag as violation), 16 (switch patterns — suggest but don't flag) - **ASK**: Rule 11 (need user input) diff --git a/dev-docs/debugging-event-loop.md b/dev-docs/debugging-event-loop.md new file mode 100644 index 000000000..5c5ea3b63 --- /dev/null +++ b/dev-docs/debugging-event-loop.md @@ -0,0 +1,115 @@ +# Debugging Event Loop Performance + +How to diagnose "the server feels slow" — written for both humans and AI assistants. Follow the +funnel in order; most incidents resolve before the last step. Do not start with dotnet-trace. + +## The model + +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`). +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. +4. **Stolen** — the host ran something else: hypervisor scheduling, noisy neighbors, CPU credit + throttling. + +A sleep is bounded by the time to the next wheel turn, so **a correctly honoured sleep can never +cost a deadline**. The only way sleeping harms the game is the wait *returning late* — that is +stolen time, and the server measures it directly on every sleep. + +## Step 0 — Read what production already tells you + +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. | +| Admin gump → Performance → *Event Loop* | `Healthy` / `Sleep suspended (host)` / `Spinning (configured)` | Same as above. | + +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. + +## Step 1 — Flip the profiling build + +``` +dotnet build -p:EventLoopProfiling=true +``` + +This compiles in `EventLoopProfiler` (Server) and the `[LoopStats` command (UOContent). Without +the flag every hook call site is removed by the compiler (`[Conditional]`), so there is nothing to +"turn off" in normal builds and no cost to leave the hooks in the code. The profiling build's own +overhead is a handful of timestamp reads per iteration — small enough to run for days while +hunting an intermittent problem. + +**Capture a baseline first.** Run `[LoopStats` while the shard feels *fine* and keep the CSV. The +profiler also keeps ~15 minutes of history in memory, so if the problem is episodic you can wait +for an episode and the good minutes on either side are already recorded. Numbers without a +baseline are how RunUO's profiler became useless — always compare bad minutes to good minutes on +the same box, build, and world. + +## Step 2 — Read the decomposition + +`[LoopStats` prints the last minute and writes the full history CSV (one row per second). Match +the shape against these signatures: + +| Signature | Diagnosis | Next step | +|---|---|---| +| One phase consistently hot (e.g. `TimerSlice` 40%/s) | Deep processing in that subsystem | Step 3 — find the culprit in that phase | +| All phases near zero, `stolen` high, `lateWakes` > 0 | Host is stealing CPU | Host problem; see step 0 actions | +| `gcPauseMs` high, gen2 counts rising | GC pressure — something is allocating heavily | Step 3 on the allocating phase, or dotnet-counters for alloc rate | +| Iterations ≫ sleeps while shard is idle | The loop is not sleeping: a queue never drains or a wake storm | Check `IsIdle` inputs; a stuck signal in the ring is the historical example | +| Sleeps ≈ iterations, each sleep ~0ms | Spurious wake storm | Ring backend issue; count `wakesIssued` vs actual cross-thread posts | +| Everything normal, complaint persists | Not the event loop | Look at the network path, client, or DB/save timing | + +**Wheel lag vs player lag:** `wheelLagMaxMs` is how late timer callbacks fired. Receives are +handled the moment they arrive (they wake the loop), so player-felt lag with a clean wheel points +away from the loop entirely. + +## Step 3 — Find the culprit inside a hot phase + +Add a temporary culprit hook rather than reaching for a tracer. The pattern: same +`[Conditional("EVENT_LOOP_PROFILING")]` attribute, own file or the profiler file, record only the +worst offender per second (identity + duration), never a per-event log. Examples: + +- `TimerSlice` hot → time each timer callback, keep the max and its `timer.ToString()`. +- `NetworkSlice` hot → time packet handlers by packet id, keep the max. +- GC pressure → `dotnet-counters monitor --counters System.Runtime` for alloc rate first; it is + cheap and often names the culprit generation without a trace. + +Keep the hook after the hunt if it earns its cost in the profiling build; delete it otherwise. + +## Step 4 — dotnet-trace, last and targeted + +Only when a hot phase resists the culprit hook. Know the costs: EventPipe visibly slows the +process (worst exactly when things are already bad) and adds artifacts to the trace — on small +vCPU hosts the tracer's own threads appear as hotspots and Rider/PerfView hotspot views can +mislead. Mitigate by being narrow: + +- Trace the specific minutes the decomposition flagged, not "a while". +- `dotnet-trace collect --profile cpu-sampling --duration 00:00:30` is usually enough. +- Compare against a trace of a good minute (same rule as step 1: no baseline, no conclusions). + +## The RAM / GC misconception (read before declaring a leak) + +ModernUO allocates very little, and the GC collects opportunistically — mostly during idle sleeps +and world saves. Under a spinning loop (`eventLoopIdleWaitMs=0`, or the pre-2026 default) the GC +may find **no** natural pause point: memory climbs to a large fraction of physical RAM, a forced +collection eventually drops part of it, and fragmentation keeps the baseline permanently above +where it started. Task manager shows alarming numbers; the in-game numbers do not. **Performance +is unaffected — this is lazy collection working as designed, not a leak.** Idle sleeping largely +removes the effect because every sleep is a natural GC opportunity. Before investigating "a leak": +check `gen0/1/2` and `gcPauseMs` in the decomposition, and compare working set *after a world +save*, which forces the collection the spin loop never allowed. + +## Rules of thumb + +- Never trade always-on profiling for the numbers. Production carries one timestamp per sleep and + nothing else; everything heavier lives behind the build flag or on the `measure/event-loop` + branch (full harness, A/B scripts, vendored ring experiments). +- One decomposition chart beats a thousand log lines. Resist adding warnings the reader cannot + act on; the three production signals are deliberate. +- When filing or reporting: attach the baseline CSV and the episode CSV. Relative statements + ("TimerSlice went from 4% to 61% during the episode") are the useful form. diff --git a/dev-docs/server-requirements.md b/dev-docs/server-requirements.md new file mode 100644 index 000000000..daf71e03e --- /dev/null +++ b/dev-docs/server-requirements.md @@ -0,0 +1,120 @@ +# Server Requirements + +Hardware guidance for running a ModernUO shard. + +## Tiers + +| Use | vCPU | RAM | Storage | +|---|---|---|---| +| Development / test | 2 **dedicated** | 2 GB | SSD | +| Small live shard (< 50 concurrent) | 4 dedicated | 4 GB | NVMe | +| Medium (50–200) | 4–8 | 8 GB | NVMe | +| Large (200+) | 8+, high clock | 16 GB+ | NVMe | + +These are starting points. Save size drives RAM more than player count does, and single-thread +clock speed drives tick latency more than core count does. Both are explained below. + +## Dedicated vCPU, not burstable + +This matters more than any other line on this page. + +Budget VPS plans sold as "2 vCPU" are frequently shared or burstable: you get a CPU credit balance +or a cgroup quota, and once it is exhausted the hypervisor throttles you. Throttling shows up in +game as periodic freezes that correlate with nothing in your logs, and it is the single most common +cause of "ModernUO is laggy on my $3/month VPS". + +Symptoms worth checking before blaming the server: + +- Steal time above ~1% (`top`, the `%st` column on Linux) +- Lag that disappears when you move to a larger plan with the same core count +- Tick lag spikes with no matching CPU spike in the process itself + +## Cores + +Game logic is **single-threaded**. Every mobile, item, timer, and packet handler runs on one +thread, so a shard's headroom is bounded by how fast one core is. Two fast cores beat four slow +ones. + +Cores beyond the first are used by: + +- **World saves.** `world.useMultithreadedSaves` (default on) spins up `ProcessorCount - 1` + serialization workers plus one inline on the main thread. On a 2-core box that is one worker; on + a 2-core box with a large world, consider setting it to `false` so saves do not contend with the + loop. +- **The .NET runtime.** Tiered JIT compilation (heaviest in the first minutes after boot) and + background GC. +- **Everything else on the machine**, including your OS and, on Windows, antivirus. + +Since ModernUO 2026 the loop sleeps when idle, so an empty shard costs roughly 1% of a core rather +than spinning. That change disproportionately helps small hosts. + +## Memory + +Three things dominate, and only one of them scales with players. + +**World size.** A world of ~190,000 items and ~33,000 mobiles loads in about a second and is not +itself large. Items and mobiles are the cheap part. + +**Saves.** Each serialization worker pre-allocates a heap sized to its share of the last save, at +roughly 1.25× total save size, and those buffers are retained afterwards. A 400 MB save therefore +implies about 500 MB of resident serialization heap on top of the live world. **This is the reason +1 GB hosts are not viable for a real shard**, even though an empty one boots fine. + +**Map residency.** `TileMatrix` reads map blocks from disk on demand and caches them permanently — +there is no eviction. Memory climbs toward full-facet residency as players explore. Felucca's land +tiles alone are around 117 MB, and statics are larger. + +Optional systems can add substantially more. The pathfinding prebake +(`pathfinding.prebakeMaps`) peaks above 1 GB of heap while baking. Budget for it or leave it off on +small hosts. + +Network buffers are minor by comparison: 64 KB receive plus a configurable 256 KB send +(`network.sendBufferSize`) per connection, so 100 players is roughly 32 MB. + +ModernUO runs **Workstation GC**, which is the right default for small hosts. Do not switch to +Server GC on a 2-core box. + +## Storage + +Saves are write-heavy bursts. Cheap network-attached storage with throttled IOPS will stall the +save path, and `World.WaitForWriteCompletion` blocks the loop at shutdown. Use local NVMe or SSD. + +Budget disk for: the world save, plus archives and backups if `autoArchive` is enabled (retention +defaults keep 24 hourly, 30 daily, and 12 monthly copies), plus the pathfinding cache if enabled. + +## Operating systems + +See the README for the full supported list. Two things are worth calling out: + +- **Windows Server 2012 R2 and 2016 sleep via a raised timer resolution.** Sleeping for a couple + of milliseconds prefers a high-resolution waitable timer, which requires Windows 10 1803 / + Server 2019. On older versions the ring falls back to `timeBeginPeriod(1)`, which raises the + system timer resolution to 1 ms so the plain wait timeout is accurate enough. The trade-off is a + higher interrupt rate (system-wide on those versions) — an acceptable price on a dedicated game + server, and the reason the high-resolution timer is preferred where it exists. + + Only if *both* mechanisms fail does the server detect it at startup, log it, and spin instead — + the same behaviour as setting `server.eventLoopIdleWaitMs` to 0: a full core at idle, and zero + missed deadlines. A host that claims short waits but cannot deliver them is caught at runtime by + the adaptive backoff. +- **Linux kernel 6.1** or newer (Debian 12 and equivalents). io_uring is used where available, with + automatic epoll fallback. + +## Tuning for a small host + +| 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. | +| `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. | +| `autoArchive.*` retention | 24h/30d/12m | Reduce if disk is tight. | + +## Am I undersized? + +Watch the log. The server warns when the host returns idle waits late and suspends idle sleeping, +and says so at startup if the host cannot honour short waits at all. Those warnings mean the host +is not scheduling the process promptly — typical of burstable or shared vCPU plans — and no +server-side change fixes that. For anything deeper, see +[debugging-event-loop.md](debugging-event-loop.md). diff --git a/dev-docs/tick-counts.md b/dev-docs/tick-counts.md new file mode 100644 index 000000000..f53e223d4 --- /dev/null +++ b/dev-docs/tick-counts.md @@ -0,0 +1,55 @@ +# Tick Counts: Overflow and Huge Starting Values + +Rules for any code that compares `Core.TickCount` / `Core.GetTimestamp()` values. Getting this +wrong produces bugs that only appear on specific cloud hosts after long host uptimes — the worst +kind to reproduce. + +## Why this matters (the Linux/cloud problem) + +`Core.GetTimestamp()` is built on `Stopwatch.GetTimestamp()`, which on Linux reads the kernel's +monotonic clock — and on some hypervisors, notably **Google Cloud**, the VM receives a +**pass-through of the host's never-resetting counter**. The tick count is *not* zero when the +process starts and *not* zero when the operating system booted; it is however long the physical +host has been up, which can be months or years. We have been burned by this in production. + +Consequences: + +- Raw values are enormous from the first read. Arithmetic that would "never overflow in 292 + years" of process uptime can overflow immediately (`Core.GetTimestamp()`'s `UInt128` + conversion path exists precisely because `raw * 1000` does not fit in 64 bits for large raws). +- Wrapped values can be **negative**. Nothing may assume a tick count is positive. +- **Windows is not affected** in our testing so far, which is exactly why this class of bug + ships: it works on every dev machine and fails on a customer's GCP instance. + +## The rules + +1. **Compare by subtraction, never directly.** Subtraction of two ticks wraps correctly in two's + complement; direct comparison does not. + + ```csharp + // WRONG: fails when ticks wrap or start huge + if (Core.TickCount < deadline) + + // RIGHT: wraparound-safe + if (Core.TickCount - deadline < 0) + ``` + +2. **Durations are always subtractions of two readings** (`elapsed = end - start`). Never derive + a duration from a single absolute value. + +3. **No zero or sign sentinels.** `if (_lastEventAt > 0)` as "has this happened yet" breaks when + ticks are negative. Track "has happened" with a separate `bool` or an existing counter. + +4. **Seed deadline fields from a real tick, not from field initialization.** A `long _deadline;` + left at 0 compares wrong against a huge or negative tick. Initialize relative to the first + observed timestamp (see the schedule-state seeding in `Core.Setup`). + +5. **Store deadlines as `start + interval` only if every comparison follows rule 1.** The + addition may wrap; the subtraction comparison handles it. + +## Reviewing for it + +Grep the diff for `TickCount <`, `TickCount >`, `GetTimestamp() <`, and comparisons against any +field whose name suggests a deadline (`*Until`, `*At`, `*Next*`). Each hit must be in subtraction +form. `DateTime`/`DateTimeOffset` comparisons are unaffected; this applies only to the monotonic +tick domain.