Attribute the tick to the mods eating it

.github/workflows/sonar.yml

@@ -93,7 +93,7 @@ jobs:
             /d:sonar.token="$SONAR_TOKEN" \
             /d:sonar.host.url="https://sonarcloud.io" \
             /d:sonar.exclusions="**/bin/**,**/obj/**,docs/**" \
-            /d:sonar.coverage.exclusions="Pulse/PulseModSystem.cs,Pulse.Otlp/PulseOtlpModSystem.cs,Pulse/EngineProbe.cs,contrib/**,tools/**" \
+            /d:sonar.coverage.exclusions="Pulse/PulseModSystem.cs,Pulse.Otlp/PulseOtlpModSystem.cs,Pulse/EngineProbe.cs,Pulse/AttributionProbe.cs,contrib/**,tools/**" \
             /d:sonar.cs.opencover.reportsPaths="**/TestResults/**/coverage.opencover.xml"
 
       - name: Build

CHANGELOG.md

@@ -10,6 +10,16 @@ first.
 
 ### Added
 
+- Per-mod tick attribution, behind a new `Attribution` block in `pulse.json` and off by default.
+  `pulse_mod_tick_share{modid}` is the fraction of profiled main-thread busy time one mod took over
+  the last burst, `pulse_mod_tick_seconds_total{modid}` the sampled seconds behind it,
+  `pulse_attribution_ticks_total` the ticks those seconds were measured over, and
+  `pulse_attribution_dropped_samples_total` the readings discarded because the engine's 32 bit
+  marker counter had wrapped. It drives the engine's own frame profiler in short bursts (30 ticks
+  every 10 seconds by default) rather than leaving it on, which costs about 0.3% of the tick
+  budget amortised against roughly 2.8% while a burst runs. The README section lists what it
+  cannot see: broadcast event handlers carry no markers, and thread-safe physics is measured for
+  the main thread only.
 - `contrib/alerts/pulse-alerts.yml`, a Prometheus alerting rules file covering tick rate, tick
   saturation, sustained tick overruns, engine warnings, log errors, endpoint availability and a
   stuck worldgen queue, calibrated against the engine's own thresholds. `contrib/alerts/README.md`

Pulse.Scenarios/AttributionScenarios.cs

@@ -0,0 +1,139 @@
+using System.Globalization;
+using Atlas.Api;
+using Atlas.XUnit;
+using Xunit;
+
+namespace Pulse.Scenarios;
+
+/// <summary>Per-mod attribution against a real engine, which is the only place it can be proven.
+/// Everything it reads is an engine internal with no compatibility promise: the profiler flag, the
+/// mark tree, the prefixes the engine writes into mark keys, and the run phase that primes the
+/// profiler before the tick loop exists. A unit test can only check the arithmetic. This checks
+/// that the engine still produces what the arithmetic is for.
+/// <para>The fixture runs a burst of five ticks a second apart, so a burst lands inside a
+/// scenario rather than half a minute later.</para></summary>
+[AtlasDataFiles("data/attribution/pulse.json", TargetPath = "ModConfig")]
+public class AttributionScenarios : AtlasScenarioBase
+{
+    private const int Port = 39465;
+
+    private static readonly string[] Families =
+    [
+        "pulse_mod_tick_share",
+        "pulse_mod_tick_seconds_total",
+        "pulse_attribution_ticks_total",
+        "pulse_attribution_dropped_samples_total",
+    ];
+
+    /// <summary>Ticks until a burst has completed, or gives up and fails with the body it last
+    /// saw. A burst needs its interval, then a discarded sample, then five profiled ticks.</summary>
+    private static async Task<string> Burst(IWorldSession world)
+    {
+        string body = string.Empty;
+        for (int attempt = 0; attempt < 20; attempt++)
+        {
+            await world.Ticks(30);
+            body = await Scrape.Metrics(Port);
+            if (Scrape.Value(body, "pulse_attribution_ticks_total") > 0)
+            {
+                return body;
+            }
+        }
+
+        Assert.Fail("no burst ever completed:\n" + body);
+        return body;
+    }
+
+    /// <summary>Reads one labelled sample line, of which there is exactly one per mod.</summary>
+    private static double Share(string exposition, string modid)
+    {
+        string name = $"pulse_mod_tick_share{{modid=\"{modid}\"}}";
+        string? line = exposition.Split('\n').FirstOrDefault(l => l.StartsWith(name + " ", StringComparison.Ordinal));
+        Assert.True(line != null, $"{name} is not in the exposition:\n{exposition}");
+        return double.Parse(line![(name.Length + 1)..], CultureInfo.InvariantCulture);
+    }
+
+    [AtlasScenario]
+    public async Task Attribution_Serves_ItsFamilies_FromBoot()
+    {
+        await World.Ticks(5);
+
+        string body = await Scrape.Metrics(Port);
+
+        // Seeded at zero, so the families are on the wire before the first burst rather than
+        // appearing minutes into a dashboard's life.
+        foreach (string family in Families)
+        {
+            Assert.Contains("# TYPE " + family + " ", body);
+        }
+
+        Assert.Contains("pulse_mod_tick_share{modid=\"engine\"} ", body);
+        Assert.Contains("pulse_mod_tick_share{modid=\"unattributed\"} ", body);
+    }
+
+    /// <summary>The whole feature end to end: the profiler was primed without killing the server,
+    /// a burst ran, the marks parsed, and Pulse found itself in its own numbers. Pulse registers
+    /// three game tick listeners off one ModSystem, so the engine marks them all with the type name
+    /// this mod's assembly declares, and the mod loader maps that name back to modid "pulse".</summary>
+    [AtlasScenario]
+    public async Task Attribution_Attributes_TickTime_ToPulseItself()
+    {
+        string body = await Burst(World);
+
+        double share = Share(body, "pulse");
+
+        // A share, not a duration: whatever the host machine is doing, Pulse's listeners are some
+        // fraction of a tick and never the whole of one.
+        Assert.InRange(share, double.Epsilon, 1.0);
+    }
+
+    [AtlasScenario]
+    public async Task Attribution_Splits_TheWholeBusyTick_BetweenItsBuckets()
+    {
+        string body = await Burst(World);
+
+        double total = body.Split('\n')
+            .Where(line => line.StartsWith("pulse_mod_tick_share{", StringComparison.Ordinal))
+            .Sum(line => double.Parse(line[(line.LastIndexOf(' ') + 1)..], CultureInfo.InvariantCulture));
+
+        // The engine's own time, the mods' and the remainder nobody marked add up to the tick, so
+        // a share can be read straight off a dashboard as a proportion of the whole.
+        Assert.Equal(1.0, total, 6);
+    }
+
+    [AtlasScenario]
+    public async Task Attribution_Counts_TheSecondsItSampled()
+    {
+        string body = await Burst(World);
+
+        double ticks = Scrape.Value(body, "pulse_attribution_ticks_total");
+        double seconds = body.Split('\n')
+            .Where(line => line.StartsWith("pulse_mod_tick_seconds_total{", StringComparison.Ordinal))
+            .Sum(line => double.Parse(line[(line.LastIndexOf(' ') + 1)..], CultureInfo.InvariantCulture));
+
+        // Sampled seconds, and the tick count is what makes them mean anything: five profiled
+        // ticks cannot add up to more busy time than five ticks of the budget.
+        Assert.True(ticks >= 5, $"the burst profiled {ticks} ticks");
+        Assert.InRange(seconds, double.Epsilon, ticks);
+    }
+
+    /// <summary>The duty cycle is the reason any of this is affordable, so it has to actually
+    /// idle between bursts rather than leave the profiler running.</summary>
+    [AtlasScenario]
+    public async Task Attribution_Profiles_OnlyASliceOfTheTicks()
+    {
+        string before = await Burst(World);
+        await World.Ticks(300);
+        string after = await Scrape.Metrics(Port);
+
+        double profiled = Scrape.Value(after, "pulse_attribution_ticks_total")
+            - Scrape.Value(before, "pulse_attribution_ticks_total");
+        double ticked = Scrape.Value(after, "pulse_server_ticks_total")
+            - Scrape.Value(before, "pulse_server_ticks_total");
+
+        // Five profiled ticks per second-long interval is about one tick in seven at the default
+        // tick rate. Asserted loosely, because the ratio moves with how fast the host ticks.
+        Assert.True(ticked > 0, "the server did not tick");
+        Assert.InRange(profiled / ticked, 0, 0.5);
+    }
+}

Pulse.Scenarios/data/attribution/pulse.json

@@ -0,0 +1,12 @@
+{
+  "Enabled": true,
+  "Bind": "127.0.0.1",
+  "Port": 39465,
+  "RuntimeMetrics": false,
+  "ChunksRefreshSeconds": 30,
+  "Attribution": {
+    "Enabled": true,
+    "BurstTicks": 5,
+    "IntervalSeconds": 1
+  }
+}

Pulse.Tests/ModOwnersTests.cs

@@ -0,0 +1,100 @@
+using Xunit;
+
+namespace Pulse.Tests;
+
+public class ModOwnersTests
+{
+    /// <summary>Two types from two different assemblies, which is what the table keys on. The test
+    /// assembly stands in for a mod's, and the framework's for something no mod ships.</summary>
+    private static readonly Type ModType = typeof(ModOwnersTests);
+    private static readonly Type ForeignType = typeof(string);
+
+    private static ModOwners Owners(params (string Code, Type Behavior)[] registry)
+    {
+        Dictionary<string, Type> classes = registry.ToDictionary(entry => entry.Code, entry => entry.Behavior);
+        return new ModOwners(code => classes.GetValueOrDefault(code));
+    }
+
+    [Fact]
+    public void Owner_Maps_AModSystemsOwnTypeName()
+    {
+        ModOwners owners = Owners();
+        owners.AddSystem("mymod", ModType);
+
+        Assert.Equal("mymod", owners.Owner(ModType.ToString()));
+    }
+
+    [Fact]
+    public void Owner_Returns_Null_ForANameNothingClaims()
+        => Assert.Null(Owners().Owner("Some.Unknown.Type"));
+
+    /// <summary>Entity behaviors are marked with the code the class was registered under, so the
+    /// class registry is the only bridge from the mark back to an assembly.</summary>
+    [Fact]
+    public void Owner_Resolves_ABehaviorCode_ThroughTheClassRegistry()
+    {
+        ModOwners owners = Owners(("health", ModType));
+        owners.AddSystem("mymod", ModType);
+
+        Assert.Equal("mymod", owners.Owner("health"));
+    }
+
+    [Fact]
+    public void Owner_Returns_Null_ForABehaviorFromAnAssemblyNoModClaims()
+    {
+        ModOwners owners = Owners(("health", ForeignType));
+        owners.AddSystem("mymod", ModType);
+
+        Assert.Null(owners.Owner("health"));
+    }
+
+    /// <summary>The registry lookup is the expensive half, and it runs on every profiled tick, so a
+    /// miss has to be remembered as firmly as a hit.</summary>
+    [Fact]
+    public void Owner_Asks_TheClassRegistryOncePerName()
+    {
+        int asked = 0;
+        ModOwners owners = new(_ =>
+        {
+            asked++;
+            return null;
+        });
+
+        owners.Owner("health");
+        owners.Owner("health");
+
+        Assert.Equal(1, asked);
+    }
+
+    [Fact]
+    public void OfAssembly_Answers_ForAnAssemblyAModSystemWasDeclaredIn()
+    {
+        ModOwners owners = Owners();
+        owners.AddSystem("mymod", ModType);
+
+        Assert.Equal("mymod", owners.OfAssembly(ModType.Assembly));
+        Assert.Null(owners.OfAssembly(ForeignType.Assembly));
+    }
+
+    /// <summary>What the listener walk contributes: a handler whose target type belongs to a mod but
+    /// is not that mod's ModSystem, which the mod loader alone cannot map.</summary>
+    [Fact]
+    public void Learn_Pins_ANameTheTableWouldNotHaveWorkedOut()
+    {
+        ModOwners owners = Owners();
+        owners.Learn("Some.Mod.Internal.Ticker", "mymod");
+
+        Assert.Equal("mymod", owners.Owner("Some.Mod.Internal.Ticker"));
+    }
+
+    [Fact]
+    public void Learn_Overrides_ARememberedMiss()
+    {
+        ModOwners owners = Owners();
+        Assert.Null(owners.Owner("Some.Mod.Internal.Ticker"));
+
+        owners.Learn("Some.Mod.Internal.Ticker", "mymod");
+
+        Assert.Equal("mymod", owners.Owner("Some.Mod.Internal.Ticker"));
+    }
+}