From 0ed659e6652243ab6607e61cf5c2d31b18dd0514 Mon Sep 17 00:00:00 2001 From: Pixnop <77785313+Pixnop@users.noreply.github.com> Date: Thu, 3 Sep 2026 14:40:30 +0200 Subject: [PATCH] Attribute the tick to the mods eating it The engine ships a per-mod tick attributor behind one public boolean and never turns it on. With sapi.World.FrameProfiler.Enabled true the server stamps a mark after every game tick listener, delayed callback and main-thread entity behaviour, and leaves the completed tree on PrevRootEntry. Pulse now drives that in short bursts, folds the tree into seconds per mod, and turns it back off. Four families, all behind a new Attribution block in pulse.json that defaults to off: pulse_mod_tick_share{modid}, pulse_mod_tick_seconds_total{modid}, pulse_attribution_ticks_total and pulse_attribution_dropped_samples_total. Two hazards the engine sets and this handles. Flipping the flag part way through a tick on a profiler that has never run makes End() dereference a null root, outside the try/catch guarding the tick and inside a loop with no guard of its own, which kills the process; the profiler is primed once from the RunGame run phase, and the duty cycle refuses to enable it until PrevRootEntry proves a tick completed. A mark's elapsed time accumulates into an int and wraps negative past about two seconds inside one tick, so a negative reading is dropped and counted rather than published. --- .github/workflows/sonar.yml | 2 +- CHANGELOG.md | 10 + Pulse.Scenarios/AttributionScenarios.cs | 139 +++++++++++ Pulse.Scenarios/data/attribution/pulse.json | 12 + Pulse.Tests/ModOwnersTests.cs | 100 ++++++++ Pulse.Tests/TickAttributionTests.cs | 246 ++++++++++++++++++++ Pulse/AttributionProbe.cs | 100 ++++++++ Pulse/ModOwners.cs | 54 +++++ Pulse/PulseConfig.cs | 20 ++ Pulse/PulseModSystem.cs | 218 +++++++++++++++++ Pulse/TickAttribution.cs | 224 ++++++++++++++++++ README.md | 99 +++++++- tools/mutation-check.sh | 26 ++- 13 files changed, 1246 insertions(+), 4 deletions(-) create mode 100644 Pulse.Scenarios/AttributionScenarios.cs create mode 100644 Pulse.Scenarios/data/attribution/pulse.json create mode 100644 Pulse.Tests/ModOwnersTests.cs create mode 100644 Pulse.Tests/TickAttributionTests.cs create mode 100644 Pulse/AttributionProbe.cs create mode 100644 Pulse/ModOwners.cs create mode 100644 Pulse/TickAttribution.cs diff --git a/.github/workflows/sonar.yml b/.github/workflows/sonar.yml index eeb6347..b766449 100644 --- a/.github/workflows/sonar.yml +++ b/.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 diff --git a/CHANGELOG.md b/CHANGELOG.md index 8f98c87..48ce1fe 100644 --- a/CHANGELOG.md +++ b/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` diff --git a/Pulse.Scenarios/AttributionScenarios.cs b/Pulse.Scenarios/AttributionScenarios.cs new file mode 100644 index 0000000..729c733 --- /dev/null +++ b/Pulse.Scenarios/AttributionScenarios.cs @@ -0,0 +1,139 @@ +using System.Globalization; +using Atlas.Api; +using Atlas.XUnit; +using Xunit; + +namespace Pulse.Scenarios; + +/// 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. +/// The fixture runs a burst of five ticks a second apart, so a burst lands inside a +/// scenario rather than half a minute later. +[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", + ]; + + /// 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. + private static async Task 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; + } + + /// Reads one labelled sample line, of which there is exactly one per mod. + 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); + } + + /// 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". + [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); + } + + /// 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. + [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); + } +} diff --git a/Pulse.Scenarios/data/attribution/pulse.json b/Pulse.Scenarios/data/attribution/pulse.json new file mode 100644 index 0000000..aef9e44 --- /dev/null +++ b/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 + } +} diff --git a/Pulse.Tests/ModOwnersTests.cs b/Pulse.Tests/ModOwnersTests.cs new file mode 100644 index 0000000..e8bd515 --- /dev/null +++ b/Pulse.Tests/ModOwnersTests.cs @@ -0,0 +1,100 @@ +using Xunit; + +namespace Pulse.Tests; + +public class ModOwnersTests +{ + /// 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. + 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 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")); + + /// 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. + [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")); + } + + /// 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. + [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)); + } + + /// 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. + [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")); + } +} diff --git a/Pulse.Tests/TickAttributionTests.cs b/Pulse.Tests/TickAttributionTests.cs new file mode 100644 index 0000000..c7024d0 --- /dev/null +++ b/Pulse.Tests/TickAttributionTests.cs @@ -0,0 +1,246 @@ +using Vintagestory.API.Common; +using Xunit; + +// Same collision as in the class under test: the game's API declares its own Func delegate. +using OwnerLookup = System.Func; + +namespace Pulse.Tests; + +public class TickAttributionTests +{ + /// One profiled tick as the engine leaves it: a thousand ticks of wall time, four + /// hundred of them asleep, and six hundred of work split between an engine system, a mod's tick + /// listener, a listener nothing claims, an entity behavior in a nested range, and a hundred + /// ticks nobody marked at all. + private static ProfileEntryRange Tick() => new() + { + Code = "all", + ElapsedTicks = 1000, + Marks = new Dictionary + { + ["sleep"] = new ProfileEntry(400, 1), + ["ss-tick-Vintagestory.Server.ServerSystemEntitySimulation"] = new ProfileEntry(100, 1), + ["gmleMy.Mod.Thing"] = new ProfileEntry(200, 1), + ["gmleSomebody.Elses.Thing"] = new ProfileEntry(50, 1), + ["end"] = new ProfileEntry(0, 1), + }, + ChildRanges = new Dictionary + { + ["tickentities"] = new ProfileEntryRange + { + Code = "tickentities", + ElapsedTicks = 150, + Marks = new Dictionary { ["done-behavior-health"] = new ProfileEntry(150, 40) }, + }, + }, + }; + + private static readonly OwnerLookup Owners = name => name switch + { + "My.Mod.Thing" => "mymod", + "health" => "survival", + _ => null, + }; + + /// Runs the duty cycle from idle to the end of one burst, feeding every profiled tick + /// the same tree. + private static AttributionBurst Cycle(TickAttribution attribution, ProfileEntryRange tick, OwnerLookup owners) + { + for (int guard = 0; guard < 1000; guard++) + { + if (attribution.OnTick(1.0, tick, owners) is { } burst) + { + return burst; + } + } + + throw new InvalidOperationException("the burst never completed"); + } + + private static double Share(AttributionBurst burst, string modid) + => burst.Seconds.Single(entry => entry.Key == modid).Value / burst.BusySeconds; + + [Fact] + public void Constructor_Floors_TheIntervalAndTheBurstLength() + { + TickAttribution attribution = new(0, 0); + + Assert.Equal(1, attribution.BurstTicks); + Assert.Equal(TickAttribution.MinimumIntervalSeconds, attribution.IntervalSeconds); + } + + [Fact] + public void Constructor_Caps_TheBurstLength() + => Assert.Equal(TickAttribution.MaximumBurstTicks, new TickAttribution(100000, 10).BurstTicks); + + [Fact] + public void Constructor_Keeps_AConfiguredDutyCycle() + { + TickAttribution attribution = new(30, 10); + + Assert.Equal(30, attribution.BurstTicks); + Assert.Equal(10, attribution.IntervalSeconds); + } + + [Fact] + public void OnTick_LeavesTheProfilerOff_UntilTheIntervalHasPassed() + { + TickAttribution attribution = new(5, 10); + + for (int tick = 0; tick < 9; tick++) + { + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); + Assert.False(attribution.Profiling); + } + + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); + Assert.True(attribution.Profiling); + } + + /// The tick that turns the profiler on never got its Begin(), so the tree it ends with + /// is whatever the last burst left behind. Folding it would count that stale tick again. + [Fact] + public void OnTick_Discards_TheFirstSampleAfterTheProfilerComesOn() + { + TickAttribution attribution = new(1, 1); + + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); // the profiler comes on + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); // stale sample, discarded + AttributionBurst burst = attribution.OnTick(1.0, Tick(), Owners)!; + + Assert.Equal(1, burst.Ticks); + } + + [Fact] + public void OnTick_TurnsTheProfilerBackOff_WhenTheBurstIsDone() + { + TickAttribution attribution = new(3, 1); + + AttributionBurst burst = Cycle(attribution, Tick(), Owners); + + Assert.False(attribution.Profiling); + Assert.Equal(3, burst.Ticks); + } + + [Fact] + public void OnTick_Runs_ASecondBurstAfterTheNextInterval() + { + TickAttribution attribution = new(2, 1); + + Cycle(attribution, Tick(), Owners); + AttributionBurst second = Cycle(attribution, Tick(), Owners); + + Assert.Equal(2, second.Ticks); + Assert.Equal(150.0 / 600.0, Share(second, "survival"), 6); + } + + [Fact] + public void OnTick_Ends_ABurstEvenWhenTheProfilerLeftNoTree() + { + TickAttribution attribution = new(2, 1); + + AttributionBurst burst = Cycle(attribution, null!, Owners); + + Assert.False(attribution.Profiling); + Assert.Equal(0, burst.BusySeconds); + Assert.Empty(burst.Seconds); + } + + [Fact] + public void Fold_Attributes_AListenerMarkToTheModThatOwnsIt() + => Assert.Equal(200.0 / 600.0, Share(Cycle(new TickAttribution(1, 1), Tick(), Owners), "mymod"), 6); + + /// Entity behaviors are marked in a nested range and keyed by behavior code rather than + /// by type name, so a fold that only read the root would report this mod's cost as the + /// engine's. + [Fact] + public void Fold_Attributes_ABehaviorMarkFromANestedRange() + => Assert.Equal(150.0 / 600.0, Share(Cycle(new TickAttribution(1, 1), Tick(), Owners), "survival"), 6); + + [Fact] + public void Fold_Reports_AMarkNoModClaims_AsUnattributed() + => Assert.Equal(50.0 / 600.0, Share(Cycle(new TickAttribution(1, 1), Tick(), Owners), TickAttribution.Unattributed), 6); + + /// The engine's own systems, plus everything the marks did not name: the gap before the + /// first mark and every range entered without a mark inside it. + [Fact] + public void Fold_Charges_TheEnginesOwnMarksAndTheUnmarkedRemainder_ToTheEngine() + => Assert.Equal(200.0 / 600.0, Share(Cycle(new TickAttribution(1, 1), Tick(), Owners), TickAttribution.Engine), 6); + + [Fact] + public void Fold_Excludes_TheThrottleSleep_FromBusyTime() + { + AttributionBurst burst = Cycle(new TickAttribution(1, 1), Tick(), Owners); + + Assert.DoesNotContain(burst.Seconds, entry => entry.Key == "sleep"); + Assert.Equal(1.0, burst.Seconds.Sum(entry => entry.Value) / burst.BusySeconds, 6); + } + + /// A mark's elapsed time accumulates into an int, so past about two seconds inside one + /// tick it wraps negative. That reading is garbage rather than a large number. + [Fact] + public void Fold_Drops_AMarkWhoseElapsedTimeHasWrappedNegative() + { + ProfileEntryRange tick = Tick(); + tick.Marks!["gmleMy.Mod.Thing"] = new ProfileEntry(-1234, 1); + + AttributionBurst burst = Cycle(new TickAttribution(1, 1), tick, Owners); + + Assert.Equal(1, burst.Dropped); + Assert.Equal(0, Share(burst, "mymod")); + + // The wrapped time is not silently handed to somebody else either: it lands in the + // remainder, which is the engine's bucket, and the shares still add to one. + Assert.Equal(1.0, burst.Seconds.Sum(entry => entry.Value) / burst.BusySeconds, 6); + } + + [Fact] + public void Fold_Counts_EveryWrappedMark_AndResetsTheCountEachBurst() + { + ProfileEntryRange tick = Tick(); + tick.Marks!["gmleMy.Mod.Thing"] = new ProfileEntry(-1, 1); + tick.ChildRanges!["tickentities"].Marks!["done-behavior-health"] = new ProfileEntry(-1, 1); + TickAttribution attribution = new(2, 1); + + Assert.Equal(4, Cycle(attribution, tick, Owners).Dropped); + Assert.Equal(0, Cycle(attribution, Tick(), Owners).Dropped); + } + + /// A gauge keeps whatever it was last given, so a mod that stops ticking would sit at + /// the share it had when it stopped until the server restarted. + [Fact] + public void Take_Keeps_ReportingAModThatWentQuiet() + { + TickAttribution attribution = new(1, 1); + ProfileEntryRange quiet = Tick(); + quiet.Marks!.Remove("gmleMy.Mod.Thing"); + + Cycle(attribution, Tick(), Owners); + AttributionBurst second = Cycle(attribution, quiet, Owners); + + Assert.Equal(0, Share(second, "mymod")); + } + + [Fact] + public void Take_Orders_TheBucketsStably() + { + AttributionBurst burst = Cycle(new TickAttribution(1, 1), Tick(), Owners); + + Assert.Equal( + ["engine", "mymod", "survival", "unattributed"], + burst.Seconds.Select(entry => entry.Key)); + } + + [Fact] + public void Take_Accumulates_AcrossTheTicksOfOneBurst() + { + AttributionBurst one = Cycle(new TickAttribution(1, 1), Tick(), Owners); + AttributionBurst four = Cycle(new TickAttribution(4, 1), Tick(), Owners); + + Assert.Equal(4 * one.BusySeconds, four.BusySeconds, 12); + Assert.Equal( + 4 * one.Seconds.Single(entry => entry.Key == "mymod").Value, + four.Seconds.Single(entry => entry.Key == "mymod").Value, + 12); + } +} diff --git a/Pulse/AttributionProbe.cs b/Pulse/AttributionProbe.cs new file mode 100644 index 0000000..f17a814 --- /dev/null +++ b/Pulse/AttributionProbe.cs @@ -0,0 +1,100 @@ +using System.Reflection; +using System.Runtime.CompilerServices; +using Vintagestory.API.Common; +using Vintagestory.API.Server; +using Vintagestory.Common; +using Vintagestory.Server; + +namespace Pulse; + +/// The second place in Pulse that names types from VintagestoryLib, and the only one that +/// reflects. +/// The engine marks a tick listener with the type name of its handler's target and stops +/// there; nothing public says which mod that type came from. Walking the listener lists closes the +/// gap exactly, because GameTickListener.Handler is a public field on a public type and its +/// target's assembly is the mod's. The lists themselves are assembly-scoped fields on +/// Vintagestory.Common.EventManager, hence one reflected read each. +/// This walk only sharpens ; it is never the only source. Without it +/// the table still maps every listener a mod registered from its own ModSystem, which is most of +/// them. Losing it costs the rest, and nothing else. +/// Members are deliberately not inlinable, for the same reason as : +/// a moved or renamed engine type surfaces as a TypeLoadException when the method naming it is JIT +/// compiled, and the caller can only catch that if the naming stays behind a call. +internal sealed class AttributionProbe +{ + private readonly EventManager[] managers; + private readonly FieldInfo? entityListeners; + private readonly FieldInfo? blockListeners; + + private AttributionProbe(ServerMain server) + { + // Both managers, on purpose. Listeners from sapi.Event.RegisterGameTickListener land on + // EventManager and broadcast handlers on ModEventManager, and TriggerGameTickDebug runs + // through both, so a walk of one alone misses whatever the other holds. + managers = [server.EventManager, server.ModEventManager]; + entityListeners = ListField("GameTickListenersEntity"); + blockListeners = ListField("GameTickListenersBlock"); + } + + /// Resolves the probe, or returns null when the world is not a ServerMain. + /// Call from inside a try/catch: this throws, rather than returning null, when the + /// engine type is gone entirely. + [MethodImpl(MethodImplOptions.NoInlining)] + public static AttributionProbe? TryResolve(ICoreServerAPI api) + => api.World as ServerMain is { } server ? new AttributionProbe(server) : null; + + /// Walks both event managers' tick listener lists and teaches + /// which mod each handler's target type belongs to. + /// Main thread only. These are plain lists the tick loop mutates, so a walk from the + /// scrape thread would risk an InvalidOperationException and a torn read of a block list that + /// on a built-up server holds thousands of entries. + [MethodImpl(MethodImplOptions.NoInlining)] + public void Refresh(ModOwners owners) + { + // Indexed rather than foreach, and the count re-read every step: unregistering a listener + // nulls its slot, and a mod registering one from a background thread can grow the list + // underneath us. Neither is worth a lock on a walk that runs once per burst. + foreach (EventManager manager in managers) + { + if (entityListeners?.GetValue(manager) is List entity) + { + for (int i = 0; i < entity.Count; i++) + { + GameTickListener? listener = entity[i]; + Learn(owners, listener?.ProfilerName, listener?.Handler); + } + } + + if (blockListeners?.GetValue(manager) is List block) + { + for (int i = 0; i < block.Count; i++) + { + GameTickListenerBlock? listener = block[i]; + Learn(owners, listener?.ProfilerName, (Delegate?)listener?.Handler ?? listener?.HandlerBare); + } + } + } + } + + private static FieldInfo? ListField(string name) + => typeof(EventManager).GetField(name, BindingFlags.NonPublic | BindingFlags.Instance); + + /// Pins one listener's mark name to the mod that declared its handler's target. + /// A null name is a handler on a static method: the engine marks those with the bare + /// prefix and no identity at all, so there is nothing to learn and the mark reports as + /// unattributed. + private static void Learn(ModOwners owners, string? name, Delegate? handler) + { + if (name != null && handler?.Target?.GetType().Assembly is { } assembly + && (owners.OfAssembly(assembly) ?? EngineOrNull(assembly)) is { } modid) + { + owners.Learn(name, modid); + } + } + + /// The engine's own listeners, which are not unattributed: they are the engine. + private static string? EngineOrNull(Assembly assembly) + => assembly == typeof(ServerMain).Assembly || assembly == typeof(FrameProfilerUtil).Assembly + ? TickAttribution.Engine + : null; +} diff --git a/Pulse/ModOwners.cs b/Pulse/ModOwners.cs new file mode 100644 index 0000000..545acde --- /dev/null +++ b/Pulse/ModOwners.cs @@ -0,0 +1,54 @@ +using System.Reflection; + +namespace Pulse; + +/// Maps the name the engine stamps into a profiler mark back to the mod that owns it. +/// Two name spaces share one table, and they cannot collide. Game tick listeners, block +/// listeners and delayed callbacks are marked with the fully qualified type name of the handler's +/// target (GameTickListener.ProfilerName); entity behaviors are marked with the code their +/// class was registered under (EntityBehavior.ProfilerName). A dotted CLR type name is never +/// a behavior code. +/// The table is seeded from the mod loader, which is public API and always available, and +/// sharpened by the listener walk in , which is not. Behavior codes +/// are resolved on first sight through the class registry and then remembered, misses +/// included. +internal sealed class ModOwners(Func behaviorClass) +{ + private readonly Dictionary byAssembly = []; + private readonly Dictionary byName = []; + + /// Records one of a mod's own systems: its assembly identifies the mod, and its type + /// name is the mark a listener registered from that system produces. + public void AddSystem(string modid, Type system) + { + byAssembly[system.Assembly] = modid; + byName[system.ToString()] = modid; + } + + /// The mod that ships , or null when no loaded mod claims + /// it. A mod's side libraries are among the nulls: only the assembly a ModSystem was declared + /// in is claimed. + public string? OfAssembly(Assembly assembly) + => byAssembly.TryGetValue(assembly, out string? modid) ? modid : null; + + /// Pins a mark name to a mod id, overriding whatever the table would work out on its + /// own. + public void Learn(string name, string modid) => byName[name] = modid; + + /// The mod behind a mark name, or null when nothing claims it. + public string? Owner(string name) + { + if (byName.TryGetValue(name, out string? known)) + { + return known; + } + + // Not a type name the table was told about, so try it as an entity behavior code: the + // class registry is the only thing that can turn one back into a type. Remembered either + // way, so a name that resolves to nothing is looked up once and never again. + Type? behavior = behaviorClass(name); + string? resolved = behavior == null ? null : OfAssembly(behavior.Assembly); + byName[name] = resolved; + return resolved; + } +} diff --git a/Pulse/PulseConfig.cs b/Pulse/PulseConfig.cs index 3ad3054..04889c6 100644 --- a/Pulse/PulseConfig.cs +++ b/Pulse/PulseConfig.cs @@ -21,4 +21,24 @@ public sealed class PulseConfig /// whole loaded-chunk dictionary under the chunk lock. The gauge reads 0 until the first /// refresh. public int ChunksRefreshSeconds { get; set; } = 30; + + /// Per-mod tick attribution. Off by default, and duty-cycled when on. + public AttributionConfig Attribution { get; set; } = new(); +} + +/// The Attribution block of ModConfig/pulse.json. +/// Off by default on purpose. Attribution runs the engine's own frame profiler, which +/// stamps a mark after every listener and every main-thread entity behavior, and that costs a low +/// single-digit percentage of the tick budget for as long as it runs. The duty cycle is what makes +/// it affordable: a short burst, then nothing until the next interval. +public sealed class AttributionConfig +{ + public bool Enabled { get; set; } + + /// Consecutive ticks profiled per burst. Tick composition is stable over seconds, so + /// a burst of a few dozen ticks describes the minute around it perfectly well. + public int BurstTicks { get; set; } = 30; + + /// Seconds between the end of one burst and the start of the next. + public int IntervalSeconds { get; set; } = 10; } diff --git a/Pulse/PulseModSystem.cs b/Pulse/PulseModSystem.cs index dabac41..90ec181 100644 --- a/Pulse/PulseModSystem.cs +++ b/Pulse/PulseModSystem.cs @@ -28,6 +28,20 @@ public sealed class PulseModSystem : ModSystem + "packet and byte counts, the connection queue and the UDP byte totals will not be " + "served; every other metric is unaffected."; + private const string AttributionWarning = + "Pulse could not read the engine's frame profiler ({0}). Per-mod tick attribution is off " + + "for the rest of this run and its families stop updating; every other metric is " + + "unaffected."; + + private const string ListenerWalkWarning = + "Pulse could not read the engine's tick listener lists ({0}). Per-mod attribution carries " + + "on from the mod loader's own type list, which maps fewer marks: the rest report as " + + "unattributed."; + + /// How many ticks attribution waits for the primed profiler to complete one, before + /// concluding that priming never took. Roughly half a minute at the default tick rate. + private const int UnprimedTickLimit = 1000; + /// Tick period buckets, seconds. Placed around the 33.3 ms default budget so a /// healthy server fills the low buckets and every overrun is separable. private static readonly double[] TickBuckets = [0.025, 0.0334, 0.05, 0.075, 0.1, 0.25, 0.5, 1.0]; @@ -54,6 +68,13 @@ public sealed class PulseModSystem : ModSystem private MetricsHttpServer? http; private TickBookkeeper? tickBookkeeper; private EngineProbe? probe; + private TickAttribution? attribution; + private ModOwners? owners; + private AttributionProbe? attributionProbe; + private Gauge? modTickShare; + private Counter? modTickSeconds; + private Counter? attributionTicks; + private Counter? attributionDropped; private Counter? columnsGenerated; private Counter? logEntries; private Counter? engineWarnings; @@ -61,6 +82,7 @@ public sealed class PulseModSystem : ModSystem private Counter? suspends; private Counter? suspendSeconds; private Gauge? entitiesByCode; + private int unprimedTicks; private long listenerId = -1; private long chunksListenerId = -1; private long engineListenerId = -1; @@ -139,12 +161,16 @@ public override void StartServerSide(ICoreServerAPI api) // healthy server with no traffic. StartEngineProbe(api, meter); + // Only if the operator asked for it: this one costs tick time while it runs. + StartAttribution(api, meter, config.Attribution ?? new AttributionConfig()); + // The runtime publishes System.Runtime itself, so listening to it is the whole of the // integration: no instrumentation, no dependency, dotted OpenTelemetry names that the // writer maps on the way out. string[] meters = config.RuntimeMetrics ? [MeterName, RuntimeMeterName] : [MeterName]; aggregator = new MetricsAggregator(OnUnsupportedInstrument, meters); SeedCounters(logEntries, engineWarnings, suspendSeconds, columnsGenerated, playerDeaths, suspends); + SeedAttribution(); PublishSnapshot(); // The errorHandler overload is not optional. Without it an exception from this listener @@ -185,6 +211,13 @@ public override void Dispose() sapi.Event.PlayerDeath -= OnPlayerDeath; sapi.Event.ServerSuspend -= OnServerSuspend; sapi.Event.ServerResume -= OnServerResume; + + // Whatever else is shutting down, the engine does not keep paying for a profiler that + // Pulse turned on and no longer reads. + if (attribution != null && sapi.World.FrameProfiler is { } profiler) + { + profiler.Enabled = false; + } } UnregisterListener(ref listenerId); @@ -237,6 +270,11 @@ private void OnTick(float _) { PublishSnapshot(); } + + if (attribution != null) + { + OnAttributionTick(elapsedSeconds); + } } private void OnTickError(Exception e) => sapi?.Logger.Error(e); @@ -318,6 +356,186 @@ private void OnEngineTick(float _) } } + /// Publishes the attribution families and arms the duty cycle, when the config asks + /// for it. + /// Nothing here is registered when Attribution.Enabled is false, priming + /// included, so a server that has not asked for attribution never touches the engine's frame + /// profiler at all. + private void StartAttribution(ICoreServerAPI api, Meter attributionMeter, AttributionConfig config) + { + if (!config.Enabled) + { + return; + } + + owners = new ModOwners(api.ClassRegistry.GetEntityBehaviorClass); + foreach (Mod mod in api.ModLoader.Mods) + { + foreach (ModSystem system in mod.Systems) + { + owners.AddSystem(mod.Info.ModID, system.GetType()); + } + } + + try + { + attributionProbe = AttributionProbe.TryResolve(api); + } + catch (Exception e) + { + attributionProbe = null; + api.Logger.Warning(ListenerWalkWarning, e.Message); + } + + attribution = new TickAttribution(config.BurstTicks, config.IntervalSeconds); + modTickShare = attributionMeter.CreateGauge( + "pulse_mod_tick_share", "1", + "Fraction of the profiled main-thread busy time attributed to one mod over the last completed burst."); + modTickSeconds = attributionMeter.CreateCounter( + "pulse_mod_tick_seconds_total", "s", + "Main-thread seconds attributed to one mod while attribution was profiling. Sampled: this is time inside the bursts, not since startup."); + attributionTicks = attributionMeter.CreateCounter( + "pulse_attribution_ticks_total", "{tick}", + "Ticks actually profiled, so the sampled seconds can be normalised against the ticks they came from."); + attributionDropped = attributionMeter.CreateCounter( + "pulse_attribution_dropped_samples_total", "{sample}", + "Profiler marks discarded because their elapsed time had overflowed the engine's 32 bit counter."); + + // Before the tick loop exists, and not one moment later. See PrimeFrameProfiler. + api.Event.ServerRunPhase(EnumServerRunPhase.RunGame, PrimeFrameProfiler); + api.Logger.Notification( + "Pulse attributes the tick per mod: bursts of {0} ticks every {1}s.", + attribution.BurstTicks, attribution.IntervalSeconds); + } + + /// Turns the engine's frame profiler on once, before the server starts ticking. + /// This is not a nicety, it is the difference between a working feature and a server + /// that dies the first time Pulse starts a burst. FrameProfilerUtil.End dereferences the + /// root range that the matching Begin creates, and ServerMain.Process calls + /// End outside the try/catch guarding the tick (1.22.7:1556-1562), from a loop with no + /// guard of its own (ServerProgram.cs:133-137). On a server whose profiler has never + /// run, flipping the flag part-way through a tick means End runs with no Begin + /// before it and the NullReferenceException takes the process down. Enabling here, while + /// Launch is still running, guarantees the first Begin establishes that root. + /// Afterwards the duty cycle flips the flag from Pulse's own tick listener, where the profiler + /// sits at depth zero and both directions are safe. + private void PrimeFrameProfiler() + { + // The profiler is thread-static and this runs on the thread that will do the ticking, so + // it is there. Guarded anyway: nothing wraps a run phase handler, and throwing out of one + // would take the server's startup with it. + if (sapi?.World.FrameProfiler is { } profiler) + { + profiler.Enabled = true; + } + } + + /// Advances the attribution duty cycle by one tick, and gives up on it for good if + /// that ever throws. + /// Same bargain as the engine probe, with one addition: the profiler flag is put back + /// before giving up, because leaving it on would charge every later tick a few percent for data + /// nobody is reading any more. + private void OnAttributionTick(double elapsedSeconds) + { + if (sapi!.World.FrameProfiler is not { } profiler) + { + return; + } + + // The guard that makes the crash in PrimeFrameProfiler structurally impossible rather than + // merely avoided. Only End() sets PrevRootEntry, and it sets it after dereferencing the + // root range that Begin() creates, so a non-null value here is proof that the profiler has + // completed a tick and that the same dereference will not throw next time. The flag is + // never flipped on before that proof exists. + if (profiler.PrevRootEntry == null) + { + // Priming runs once, before the tick loop, and the very next completed tick sets this. + // Still null half a minute later means the flag never took, on a thread Pulse cannot + // reach: stop rather than report zeros that look like a server nothing is running on. + if (++unprimedTicks > UnprimedTickLimit) + { + attribution = null; + sapi.Logger.Warning(AttributionWarning, "the engine's profiler never completed a primed tick"); + } + + return; + } + + try + { + bool starting = !attribution!.Profiling; + AttributionBurst? burst = attribution.OnTick(elapsedSeconds, profiler.PrevRootEntry, owners!.Owner); + if (starting && attribution.Profiling) + { + RefreshOwners(); + } + + if (burst != null) + { + PublishBurst(burst); + } + + profiler.Enabled = attribution.Profiling; + } + catch (Exception e) + { + attribution = null; + profiler.Enabled = false; + sapi.Logger.Warning(AttributionWarning, e.Message); + } + } + + /// Re-reads which mod owns which tick listener, once per burst. + /// Once per burst rather than once at startup because mods register and drop listeners + /// as the world runs. Its own catch: losing the walk costs precision in the map, not the + /// feature. + private void RefreshOwners() + { + try + { + attributionProbe?.Refresh(owners!); + } + catch (Exception e) + { + attributionProbe = null; + sapi!.Logger.Warning(ListenerWalkWarning, e.Message); + } + } + + private void PublishBurst(AttributionBurst burst) + { + attributionTicks!.Add(burst.Ticks); + attributionDropped!.Add(burst.Dropped); + foreach (KeyValuePair entry in burst.Seconds) + { + KeyValuePair modid = new("modid", entry.Key); + modTickSeconds!.Add(entry.Value, modid); + modTickShare!.Record(burst.BusySeconds > 0 ? entry.Value / burst.BusySeconds : 0, modid); + } + } + + /// Puts the attribution families on the wire from boot, at zero, rather than the first + /// time a burst completes. + /// The two labelled families are seeded on the buckets that always exist. A mod's own + /// series still appears the first time it is measured, which is unavoidable: nothing knows + /// which mods eat tick time until one has been profiled. + private void SeedAttribution() + { + if (attribution == null) + { + return; + } + + attributionTicks!.Add(0); + attributionDropped!.Add(0); + foreach (string modid in new[] { TickAttribution.Engine, TickAttribution.Unattributed }) + { + KeyValuePair label = new("modid", modid); + modTickSeconds!.Add(0, label); + modTickShare!.Record(0, label); + } + } + private void OnSlowTick(float _) { ICoreServerAPI api = sapi!; diff --git a/Pulse/TickAttribution.cs b/Pulse/TickAttribution.cs new file mode 100644 index 0000000..452842d --- /dev/null +++ b/Pulse/TickAttribution.cs @@ -0,0 +1,224 @@ +using System.Diagnostics; +using Vintagestory.API.Common; + +// The game's API declares a Func delegate of its own in Vintagestory.API.Common, so the one this +// file wants gets a name of its own rather than a namespace qualifier on every signature. +using OwnerLookup = System.Func; + +namespace Pulse; + +/// The duty cycle and the arithmetic behind per-mod tick attribution: when the engine's +/// frame profiler should be running, and how one profiled tick's mark tree becomes seconds per +/// mod. +/// Knows nothing about meters, the server or the profiler flag itself. It is handed the +/// previous tick's completed tree and says whether the profiler should be on when the current tick +/// ends, which is what makes the whole duty cycle drivable from a unit test. +internal sealed class TickAttribution +{ + /// Everything the engine spends on itself: its own server systems, the time between + /// ranges nobody marked, and every mark that names no mod. + public const string Engine = "engine"; + + /// Marks that do name something, but nothing loaded claims it. A handler on a static + /// method has no target type at all and lands here, as does a listener registered from a mod's + /// side library rather than from the assembly its ModSystem lives in. + public const string Unattributed = "unattributed"; + + /// Shortest interval between bursts. The duty cycle is the whole reason this is + /// affordable, so it stays a duty cycle. + public const int MinimumIntervalSeconds = 1; + + /// Longest burst. Ten seconds of profiling at the default tick rate, which is already + /// far more than tick composition varies over. + public const int MaximumBurstTicks = 300; + + /// The engine's bucket for the throttle sleep, charged in ServerMain.Process + /// (1.22.7:1553). It is the one root mark that is not work, so it is what busy time is measured + /// against rather than attributed. + private const string SleepMark = "sleep"; + + /// Mark prefixes the engine puts in front of a name that identifies an owner. The + /// first five come from EventManager.TriggerGameTickDebug (1.22.7:200-264) and carry the + /// handler target's type name; the last is EntityBehavior.ProfilerName and carries a + /// behavior code. Every other mark in the tree is the engine's own. + private static readonly string[] OwnedPrefixes = ["gmle", "gmlb", "dce", "dcb", "sdcb", "done-behavior-"]; + + private readonly Dictionary ticksByMod = []; + + /// Every mod that has appeared in any burst so far, so one that goes quiet publishes a + /// zero instead of freezing its gauge at the share it had when it stopped. + private readonly HashSet seenMods = []; + + private double idleSeconds; + private int burstTicksElapsed; + private int sampled; + private long busyTicks; + private long dropped; + private bool warm; + + public TickAttribution(int burstTicks, int intervalSeconds) + { + BurstTicks = Math.Clamp(burstTicks, 1, MaximumBurstTicks); + IntervalSeconds = Math.Max(MinimumIntervalSeconds, intervalSeconds); + } + + public int BurstTicks { get; } + + public int IntervalSeconds { get; } + + /// Whether the engine's frame profiler has to be enabled when the current tick ends. + public bool Profiling { get; private set; } + + /// Advances the duty cycle by one tick, folding when + /// it is a sample this burst wants. Returns the finished burst on the tick that completes + /// one. + public AttributionBurst? OnTick(double elapsedSeconds, ProfileEntryRange? previousTick, OwnerLookup owner) + { + if (!Profiling) + { + idleSeconds += elapsedSeconds; + if (idleSeconds < IntervalSeconds) + { + return null; + } + + idleSeconds = 0; + burstTicksElapsed = 0; + warm = false; + Profiling = true; + return null; + } + + // The profiler was switched on part-way through the previous tick, so that tick never got + // its Begin() and the tree it ended with is whatever the last burst left in the profiler. + // One stale sample per burst, discarded here rather than folded. + if (!warm) + { + warm = true; + return null; + } + + if (previousTick != null) + { + Fold(previousTick, owner); + } + + // Counted whether or not there was a tree to read, so a burst always ends and the profiler + // always goes back off. + if (++burstTicksElapsed < BurstTicks) + { + return null; + } + + Profiling = false; + return Take(); + } + + /// Folds one completed tick's tree into the burst. + /// Every mark in the tree is disjoint from every other: entering a child range moves + /// the parent's last-mark cursor past the child on the way out, so a child's time is never also + /// charged to a parent mark. What the marks leave over is the engine's. + private void Fold(ProfileEntryRange root, OwnerLookup owner) + { + long sleep = root.Marks != null && root.Marks.TryGetValue(SleepMark, out ProfileEntry? nap) + ? Elapsed(nap) + : 0; + + long busy = Math.Max(0, root.ElapsedTicks - sleep); + Add(Engine, Math.Max(0, busy - Walk(root, owner))); + busyTicks += busy; + sampled++; + } + + /// Charges every mark under to its owner and returns their + /// total. + private long Walk(ProfileEntryRange range, OwnerLookup owner) + { + long total = 0; + if (range.Marks != null) + { + foreach (KeyValuePair mark in range.Marks) + { + if (mark.Key == SleepMark) + { + continue; + } + + long ticks = Elapsed(mark.Value); + Add(Bucket(mark.Key, owner), ticks); + total += ticks; + } + } + + if (range.ChildRanges != null) + { + foreach (ProfileEntryRange child in range.ChildRanges.Values) + { + total += Walk(child, owner); + } + } + + return total; + } + + private static string Bucket(string mark, OwnerLookup owner) + { + foreach (string prefix in OwnedPrefixes) + { + if (mark.StartsWith(prefix, StringComparison.Ordinal)) + { + return owner(mark[prefix.Length..]) ?? Unattributed; + } + } + + return Engine; + } + + /// Reads one mark's elapsed time, dropping a reading that has wrapped. + /// A mark accumulates into an int (FrameProfilerUtil.MarkInternal) while + /// the stopwatch behind it ticks at a nanosecond on Linux, so a single bucket goes negative + /// past about 2.147 seconds inside one tick. That is exactly the pathological tick an operator + /// wants explained, and a wrapped value is not a large number, it is garbage: drop it, count it + /// and let the meta counter say how often it happened. + private long Elapsed(ProfileEntry entry) + { + if (entry.ElapsedTicks < 0) + { + dropped++; + return 0; + } + + return entry.ElapsedTicks; + } + + private void Add(string modid, long ticks) + { + seenMods.Add(modid); + ticksByMod.TryGetValue(modid, out long accumulated); + ticksByMod[modid] = accumulated + ticks; + } + + /// Closes the burst and starts the next one empty. + private AttributionBurst Take() + { + double frequency = Stopwatch.Frequency; + List> seconds = []; + foreach (string modid in seenMods.Order(StringComparer.Ordinal)) + { + ticksByMod.TryGetValue(modid, out long ticks); + seconds.Add(new KeyValuePair(modid, ticks / frequency)); + } + + AttributionBurst burst = new(seconds, busyTicks / frequency, sampled, dropped); + ticksByMod.Clear(); + busyTicks = 0; + sampled = 0; + dropped = 0; + return burst; + } +} + +/// One completed burst: profiled seconds per mod, the busy time they are a share of, how +/// many ticks were folded into it, and how many marks were thrown away as wrapped. +internal sealed record AttributionBurst( + IReadOnlyList> Seconds, double BusySeconds, int Ticks, long Dropped); diff --git a/README.md b/README.md index 8734271..913b6ef 100644 --- a/README.md +++ b/README.md @@ -54,6 +54,9 @@ degraded mode below for what happens when they are unavailable. - `pulse_network_udp_sent_bytes_total` and `pulse_network_udp_received_bytes_total` (counters): the UDP totals missing from the two public byte counters above. +Four more answer "which mod is eating the tick", and only when you turn them on. They have a +section of their own further down. + The tick period is measured rather than taken from the value the engine hands tick listeners, because that one is rounded to whole milliseconds. Overruns still land exactly: once a tick's work exceeds the budget the engine's throttle sleep is zero, and the period is the busy time. @@ -103,6 +106,91 @@ Pulse renders the shape each instrument declares, including where that is arguab as an ObservableCounter, even though the number goes down as often as up. Second-guessing the framework here would only make the series harder to correlate with any other .NET exporter. +## Attribution + +Tick busy time tells you the server is working hard. Attribution tells you what it is working on. +Turned on, it reports a per-mod share of the main thread, on a continuous series you can graph and +alert on, rather than in a one-off profiling report. + +It is off by default, because it is not free. Add an `Attribution` block to `ModConfig/pulse.json`: + +```json +{ + "Attribution": { + "Enabled": true, + "BurstTicks": 30, + "IntervalSeconds": 10 + } +} +``` + +`BurstTicks` is how many consecutive ticks each measurement covers, `IntervalSeconds` how long the +server runs unmeasured between two of them. The defaults measure about one tick in twelve. Both are +clamped on read: at least a second between bursts, at most 300 ticks in one. + +Four families appear once it is on: + +- `pulse_mod_tick_share{modid}` (gauge): the fraction of profiled main-thread busy time that went + to one mod over the last completed burst. The shares add up to 1 across every `modid`, including + the two Pulse adds: `engine` for the server's own systems and for the time no marker named, and + `unattributed` for work that was marked but that no loaded mod claims. +- `pulse_mod_tick_seconds_total{modid}` (counter): main-thread seconds attributed to one mod. + Sampled, not total: this is time measured inside the bursts, not time since startup. Divide by + the tick counter below to compare two servers, or take `rate()` of it against + `rate(pulse_attribution_ticks_total)` for seconds per profiled tick. +- `pulse_attribution_ticks_total` (counter): ticks actually profiled, which is what makes the + sampled seconds mean anything. +- `pulse_attribution_dropped_samples_total` (counter): profiler readings thrown away because they + overflowed. The engine accumulates each marker's time into a 32 bit counter of stopwatch ticks, + which wraps negative somewhere past two seconds inside a single tick. A wrapped reading is not a + large number, it is garbage, so it is dropped and counted here instead of being published as + data. Anything but a flat zero means the server had a tick so bad that a single marker ran for + over two seconds. + +### How it works, and what it costs + +The engine already contains a per-mod tick attributor and simply never switches it on. With its +frame profiler enabled, the server stamps a marker after every game tick listener, every delayed +callback and every main-thread entity behaviour, keyed by the type that declared the handler or by +the behaviour's registered code. Pulse turns the profiler on for a burst, reads the tree the tick +left behind, maps each key back to a mod through the mod loader, and turns it off again. No +Harmony, no engine patch, no bundled dependency. + +The cost is why it bursts. Each marker is a dictionary write and a clock read, and the number of +markers scales with loaded entities times their behaviours, not with how many mods you run. On a +twenty-player server holding four thousand entities, a profiled tick costs roughly 2.8% of the +33 ms budget. At the default duty cycle that averages out to about 0.3%, and on an idle server it +is nothing at all. Raising `BurstTicks` or lowering `IntervalSeconds` moves that number in the +obvious direction. + +One visible side effect: the engine logs "Over 400ms tick. Skipping N physics ticks" only when its +profiler is on. If your server is already overloaded you will see that warning appear during +bursts. It is the engine reporting a real condition it otherwise keeps to itself. + +### What it cannot see + +Say this out loud before reading a dashboard built on it. + +Broadcast events carry no markers. Roughly forty of them, `PlayerJoin`, `DidBreakBlock`, +`OnEntityDeath` and the rest, are plain C# events the engine invokes without timing. A mod that +does all its work in an event handler shows up as a rounding error here, and the time it spends +lands in the `engine` bucket. The listener-and-behaviour half is what this measures. + +It is a main-thread share, not a total. Entity behaviours that declare themselves thread-safe run +across several threads, and only the main thread's slice is marked. A mod whose behaviour is +thread-safe therefore reads low, by roughly the thread count. + +Mapping is by assembly. A mod that ships several dlls only has the one its `ModSystem` lives in +claimed, so a listener registered from a side library reads as `unattributed`. So does a handler +on a static method, which the engine marks with no identity at all. + +And it is a sample. Thirty ticks out of every twelve seconds describe a steady server well and a +spiky one badly. The share is an average over the burst, so a mod that stalls for 200 ms once a +minute may well be profiled during a quiet stretch and read as harmless. + +If the numbers matter enough to act on, this is a first pass that says which mod to look at, not +a call tree. Lithos Probe's sampling profiler is the tool for the second pass. + ## Install Drop `pulse_0.1.0.zip` into your server's `Mods/` folder and start the server. Add @@ -115,7 +203,12 @@ the OTLP one does not. On first boot Pulse writes `ModConfig/pulse.json` with it "Bind": "127.0.0.1", "Port": 9464, "RuntimeMetrics": true, - "ChunksRefreshSeconds": 30 + "ChunksRefreshSeconds": 30, + "Attribution": { + "Enabled": false, + "BurstTicks": 30, + "IntervalSeconds": 10 + } } ``` @@ -123,7 +216,9 @@ Set `Enabled` to false and the mod loads but registers nothing at all: no tick l socket, no meter. `RuntimeMetrics` false drops the `dotnet_*` families and keeps the rest, which is what you want if something else already collects them on that host. `ChunksRefreshSeconds` is how often the loaded-chunk gauge is refreshed, and 30 is already fast for what that read -costs; lower it only if you know why. Every one of these takes a server restart. +costs; lower it only if you know why. `Attribution` is the per-mod breakdown described above, off +because it costs tick time; with it off, nothing in that section is registered and the engine's +profiler is never touched. Every one of these takes a server restart. ## Scraping it diff --git a/tools/mutation-check.sh b/tools/mutation-check.sh index a7bcb5a..a71551b 100755 --- a/tools/mutation-check.sh +++ b/tools/mutation-check.sh @@ -43,7 +43,7 @@ mutate() { #