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() { #