mirror of
https://github.com/modernuo/ModernUO
synced 2026-08-11 22:23:06 -04:00
## Problem
`RunEventLoop` span through its body regardless of whether there was anything to do — ~10% of a desktop core for an empty shard, and ~70% of a core on a 3 vCPU VPS. A process that never idles is exactly what burstable vCPU plans throttle, which is how this surfaced: lag spikes that went away when the operator bought more cores. The spin also denied the GC its natural pause points, so memory climbed until a world save forced a collection — alarming in task manager, harmless in practice, and a recurring source of "is my server leaking?" reports.
## Result
Windows desktop, real world of **190,728 items / 33,158 mobiles**, no players, saves and prebake off, three consecutive runs:
| | Legacy spin | Idle sleeping |
|---|---|---|
| **CPU** | 10.42 – 10.50% of one core | **0.78 – 1.00%** |
| **Tick lag** (peak/15s) | 4–10 ms | 5–11 ms |
**~10× less CPU with tick lag unchanged** — the CPU came free rather than being traded for latency. Slower hosts gain proportionally more. Spin mode (`server.eventLoopIdleWaitMs=0`) independently gained **7× the iterations per core** (1.19M → 8.3M cycles/sec) from the ring's AcceptEx rework.
## How
The loop blocks in `NetState.WaitForCompletion` whenever every queue it drains is empty (all the drains are bounded, so leftovers keep it awake). Receive completions, new connections, and cross-thread `LoopContext.Post` (via the ring's sticky `Wake()`) are all in the wait set, so sleeping adds no latency to any of them. Only timer-driven logic sees wheel lag, bounded by the idle wait.
**Health is measured at the only place sleeping can cause harm.** A sleep is bounded by the time to the next wheel turn, so a correctly honoured sleep can never miss a deadline — the only failure mode is the host returning the wait late. That overshoot is measured on every sleep (one extra timestamp read; production's entire accounting cost), and an escalating backoff suspends sleeping when it persists. By construction, server work — saves, heavy staff commands, deep timer callbacks — cannot trip it, so the warning means exactly one thing: *the host is not scheduling the process promptly*, with two known remedies (dedicated CPU, or `=0`). Hosts with no high-resolution wait mechanism at all are detected once at startup and spin instead.
**CPS is removed.** `Core.CyclesPerSecond`/`AverageCPS` measured nothing actionable before and became actively misleading once the loop sleeps (the rate is set by the sleep, not by shard health). The admin gump's Performance page now shows the verdict instead: `Healthy` / `Sleep suspended (host)` / `Spinning (configured)`.
## Configuration
| Setting | Default | Meaning |
|---|---|---|
| `server.eventLoopIdleWaitMs` | `2` | Longest idle block. Measured across 1/2/4/8 ms, 2 is where the trade stops being free. `0` = never sleep: ~98% of a core, zero scheduling overhead — for large shards on dedicated CPU. |
| `server.lateWakeThreshold` | `1` | Idle waits the host may return a full tick late, per second, before sleeping backs off. Raise for jittery hosts; very high disables the backoff. |
## Diagnostics (compiled out by default)
`dotnet build -p:EventLoopProfiling=true` compiles in `EventLoopProfiler` — every hook is `[Conditional("EVENT_LOOP_PROFILING")]`, so normal builds contain zero profiling IL. The profiling build decomposes each second of wall time into **work (per loop phase) / sleep / GC pause / stolen residual**, keeps ~15 minutes of history in a ring buffer, and the `[LoopStats` command prints the last minute and dumps the full history to CSV. `dev-docs/debugging-event-loop.md` is the diagnosis guide (for humans and AI): what production already tells you, when to flip the profiling build, the signature table for host-steal vs deep-processing vs GC vs wake bugs, why dotnet-trace comes last, and the GC/RAM "leak" misconception.
## Verification
- 815 Server.Tests green; both build configurations compile.
- Docker echo harness green on epoll and io_uring (ping-pong mode); kqueue verified manually on an M1 Max.
- A/B measurements and per-change numbers: `measure/event-loop` branch.
## Notes
The full measurement harness and vendored ring sources used to develop this live on the [`measure/event-loop`](https://github.com/modernuo/ModernUO/tree/measure/event-loop) branch, kept for future loop work.
334 lines
10 KiB
C#
334 lines
10 KiB
C#
/*************************************************************************
|
|
* ModernUO *
|
|
* Copyright 2019-2026 - ModernUO Development Team *
|
|
* Email: hi@modernuo.com *
|
|
* File: Timer.TimerWheel.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 <http://www.gnu.org/licenses/>. *
|
|
*************************************************************************/
|
|
|
|
using System;
|
|
using System.Collections.Generic;
|
|
using System.Diagnostics;
|
|
using System.IO;
|
|
using System.Linq;
|
|
using System.Runtime.CompilerServices;
|
|
|
|
namespace Server;
|
|
|
|
public partial class Timer
|
|
{
|
|
#if DEBUG_TIMERS
|
|
private const int _chainExecutionThreshold = 512;
|
|
#endif
|
|
private const int _ringSizePowerOf2 = 12;
|
|
private const int _ringSize = 1 << _ringSizePowerOf2; // 4096
|
|
private const int _ringLayers = 3;
|
|
private const int _tickRatePowerOf2 = 3;
|
|
private const int _tickRate = 1 << _tickRatePowerOf2; // 8ms
|
|
private const long _maxDuration = (long)_tickRate << (_ringSizePowerOf2 * _ringLayers - 1);
|
|
|
|
private static readonly Timer[][] _rings = new Timer[_ringLayers][];
|
|
private static readonly int[] _ringIndexes = new int[_ringLayers];
|
|
private static readonly Timer[] _executingRings = new Timer[_ringLayers];
|
|
|
|
private static long _lastTickTurned = -1;
|
|
|
|
public static void Init(long tickCount)
|
|
{
|
|
_lastTickTurned = tickCount;
|
|
|
|
for (var i = 0; i < _rings.Length; i++)
|
|
{
|
|
_rings[i] = new Timer[_ringSize];
|
|
_ringIndexes[i] = 0;
|
|
}
|
|
}
|
|
|
|
/// <summary>
|
|
/// Milliseconds of simulated time one wheel turn advances.
|
|
/// </summary>
|
|
public static int TickRate => _tickRate;
|
|
|
|
public static void Slice(long tickCount)
|
|
{
|
|
EventLoopProfiler.WheelSlice(tickCount - _lastTickTurned);
|
|
|
|
var deltaSinceTurn = tickCount - _lastTickTurned;
|
|
while (deltaSinceTurn >= _tickRate)
|
|
{
|
|
deltaSinceTurn -= _tickRate;
|
|
_lastTickTurned += _tickRate;
|
|
Turn();
|
|
}
|
|
}
|
|
|
|
[MethodImpl(MethodImplOptions.AggressiveInlining)]
|
|
public static long MillisecondsUntilNextTick(long tickCount) => Math.Max(0, _tickRate - (tickCount - _lastTickTurned));
|
|
|
|
private static void Turn()
|
|
{
|
|
var turnNextWheel = false;
|
|
|
|
// Detach the chain from the timer wheel. This allows adding timers to the same slot during execution.
|
|
for (var i = 0; i < _ringLayers; i++)
|
|
{
|
|
if (i == 0 || turnNextWheel)
|
|
{
|
|
var ringIndex = ++_ringIndexes[i];
|
|
turnNextWheel = ringIndex >= _ringSize;
|
|
|
|
if (turnNextWheel)
|
|
{
|
|
ringIndex = _ringIndexes[i] = 0;
|
|
}
|
|
|
|
_executingRings[i] = _rings[i][ringIndex];
|
|
_rings[i][ringIndex] = null;
|
|
}
|
|
else
|
|
{
|
|
_executingRings[i] = null;
|
|
}
|
|
}
|
|
|
|
for (var i = 0; i < _ringLayers; i++)
|
|
{
|
|
#if DEBUG_TIMERS
|
|
var executionCount = 0;
|
|
#endif
|
|
while (_executingRings[i] != null)
|
|
{
|
|
#if DEBUG_TIMERS
|
|
executionCount++;
|
|
#endif
|
|
|
|
var timer = _executingRings[i];
|
|
|
|
// Set the executing timer to the next in the link list because we will be detaching.
|
|
_executingRings[i] = timer._nextTimer;
|
|
|
|
timer.Detach();
|
|
|
|
// Check to see if it's running just in case it was stopped by another timer
|
|
if (timer.Running)
|
|
{
|
|
if (i > 0 && timer._remaining > 0)
|
|
{
|
|
// Promote
|
|
AddTimer(timer, timer._remaining);
|
|
}
|
|
else
|
|
{
|
|
Execute(timer);
|
|
}
|
|
}
|
|
}
|
|
#if DEBUG_TIMERS
|
|
if (executionCount > _chainExecutionThreshold)
|
|
{
|
|
logger.Warning(
|
|
"Timer threshold of {Threshold} met. Executed {Count} timers sequentially.",
|
|
_chainExecutionThreshold,
|
|
executionCount
|
|
);
|
|
}
|
|
#endif
|
|
}
|
|
}
|
|
|
|
private static void Execute(Timer timer)
|
|
{
|
|
var finished = timer.Count != 0 && timer.Index + 1 >= timer.Count;
|
|
|
|
// Stop the timer from running so that way if Start() is called in OnTick, the timer will be started.
|
|
if (finished)
|
|
{
|
|
timer.InternalStop();
|
|
timer.Version++;
|
|
}
|
|
|
|
var version = timer.Version;
|
|
|
|
timer.OnTick();
|
|
|
|
// Starting doesn't change the timer version, so we need to check if it's finished and if it's still running.
|
|
if (timer.Version != version || finished && timer.Running)
|
|
{
|
|
return;
|
|
}
|
|
|
|
if (!finished)
|
|
{
|
|
AddTimer(timer, (long)timer.Interval.TotalMilliseconds);
|
|
}
|
|
else
|
|
{
|
|
// Already stopped and detached, now run OnDetach
|
|
timer.OnDetach();
|
|
}
|
|
|
|
timer.Index++;
|
|
}
|
|
|
|
[MethodImpl(MethodImplOptions.AggressiveInlining)]
|
|
private static long RoundTicksToNextPowerOfTwo(long value)
|
|
{
|
|
if (value <= 0)
|
|
{
|
|
return _tickRate;
|
|
}
|
|
|
|
const long mask = _tickRate - 1;
|
|
return (value + mask) & ~mask;
|
|
}
|
|
|
|
private static void AddTimer(Timer timer, long delay)
|
|
{
|
|
var actualDelay = delay;
|
|
|
|
var resolutionPowerOf2 = _tickRatePowerOf2;
|
|
for (var i = 0; i < _ringLayers; i++)
|
|
{
|
|
var resolution = 1L << resolutionPowerOf2;
|
|
var nextResolutionPowerOf2 = resolutionPowerOf2 + _ringSizePowerOf2;
|
|
var max = 1L << nextResolutionPowerOf2;
|
|
var lastRing = i == _ringLayers - 1;
|
|
|
|
if (delay < max || lastRing)
|
|
{
|
|
var ringIndex = _ringIndexes[i];
|
|
var remaining = delay & (resolution - 1);
|
|
var slot = (delay >> resolutionPowerOf2) + ringIndex + (remaining > 0 ? 1 : 0);
|
|
|
|
// Round up if we have a delay of 0
|
|
if (delay == 0)
|
|
{
|
|
slot++;
|
|
remaining = 0;
|
|
}
|
|
|
|
if (slot >= _ringSize)
|
|
{
|
|
slot -= _ringSize;
|
|
|
|
// Slot should only be more than 4096 if we are on the last ring and the timer is more than max capacity
|
|
// In this case, we will just throw it on the last slot.
|
|
if (lastRing && slot > _ringSize)
|
|
{
|
|
logger.Error(
|
|
$"Timer {{Timer}} has a duration of {{Duration}}ms, more than max capacity of {{MaxDuration}}ms.{Environment.NewLine}{{StackTrace}}",
|
|
timer.GetType(),
|
|
actualDelay,
|
|
_maxDuration,
|
|
new StackTrace()
|
|
);
|
|
|
|
slot = Math.Max(0, ringIndex - 1);
|
|
}
|
|
}
|
|
|
|
timer.Next = Core.Now + timer.Delay;
|
|
timer.Attach(_rings[i][slot]);
|
|
timer._remaining = remaining;
|
|
timer._ring = i;
|
|
timer._slot = (int)slot;
|
|
|
|
_rings[i][slot] = timer;
|
|
return;
|
|
}
|
|
|
|
// The remaining amount until we turn this ring
|
|
var offsetDelay = resolution * (_ringSize - _ringIndexes[i]);
|
|
delay -= offsetDelay;
|
|
resolutionPowerOf2 = nextResolutionPowerOf2;
|
|
}
|
|
}
|
|
|
|
public static void DumpInfo(TextWriter tw)
|
|
{
|
|
tw.WriteLine($"Date: {Core.Now.ToLocalTime()}{Environment.NewLine}");
|
|
tw.WriteLine($"Pool - Count: {_poolCount}; Capacity {_poolCapacity}{Environment.NewLine}");
|
|
|
|
var total = 0.0;
|
|
var hash = new Dictionary<string, int>();
|
|
|
|
for (var i = 0; i < _ringLayers; i++)
|
|
{
|
|
for (var j = 0; j < _ringSize; j++)
|
|
{
|
|
var t = _rings[i][j];
|
|
if (t == null)
|
|
{
|
|
continue;
|
|
}
|
|
|
|
while (t != null)
|
|
{
|
|
var name = t.ToString();
|
|
|
|
hash.TryGetValue(name, out var count);
|
|
hash[name] = count + 1;
|
|
|
|
total++;
|
|
|
|
t = t._nextTimer;
|
|
}
|
|
}
|
|
}
|
|
|
|
tw.WriteLine("Timers:");
|
|
|
|
foreach (var (name, count) in hash.OrderByDescending(o => o.Value))
|
|
{
|
|
var percent = count / total;
|
|
var line = $"{count:#,0} ({percent:P1})";
|
|
// 6 - 15 / 8 = 1
|
|
var tabs = new string('\t', line.Length < 12 ? 2 : 1);
|
|
tw.WriteLine($"{line}{tabs}{name}");
|
|
}
|
|
|
|
#if DEBUG_TIMERS
|
|
tw.WriteLine($"{Environment.NewLine}Stack Traces:");
|
|
foreach (var kvp in DelayCallTimer._stackTraces)
|
|
{
|
|
tw.WriteLine(kvp.Value);
|
|
tw.WriteLine();
|
|
}
|
|
#endif
|
|
|
|
tw.WriteLine();
|
|
tw.WriteLine();
|
|
}
|
|
|
|
public static void ClearAllTimers(long tickCount)
|
|
{
|
|
_lastTickTurned = tickCount;
|
|
|
|
foreach (var t in _rings)
|
|
{
|
|
if (t == null)
|
|
{
|
|
continue;
|
|
}
|
|
|
|
for (var i = 0; i < _ringSize; i++)
|
|
{
|
|
var node = t[i];
|
|
Timer next;
|
|
|
|
do
|
|
{
|
|
next = node?._nextTimer;
|
|
node?.Stop();
|
|
} while (next != null);
|
|
}
|
|
}
|
|
}
|
|
}
|