diff --git a/CHANGELOG.md b/CHANGELOG.md index fc99140..e3ac9de 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,17 @@ first. ### Added +- `/pulse`, a server command behind the `controlserver` privilege, so per-mod tick attribution no + longer needs a restart to switch. `/pulse attribution on` and `off` drive the duty cycle on the + running server without writing `pulse.json`, `/pulse attribution status` reports the cycle in use + and the ticks it has profiled, and `/pulse reload` re-reads the config file and applies the + `Attribution` block live, naming any other key whose value in the file has drifted from what the + server is running. A file that fails to parse leaves everything as it was and the reply carries + the parse error. This is the shape a profiler wants: the moment you need attribution is while the + server is struggling, and a restart erases what you wanted to look at. The four families and the + frame profiler priming are now registered whether or not `Attribution.Enabled` is set, which is + what makes a later switch-on safe rather than merely likely to work; an instrument nothing has + recorded into is not a series, so an idle server serves the exposition it always did. - Config files are brought up to date at startup instead of only on first boot. Each mod compares the file on disk against the keys it knows and writes the missing ones back with their defaults, keeping every value already in the file, so a server upgrading from 0.1.0 gets the `Attribution` diff --git a/Pulse.Scenarios/ConfigReloadScenarios.cs b/Pulse.Scenarios/ConfigReloadScenarios.cs new file mode 100644 index 0000000..9ccde08 --- /dev/null +++ b/Pulse.Scenarios/ConfigReloadScenarios.cs @@ -0,0 +1,69 @@ +using Atlas.Api; +using Atlas.XUnit; +using Xunit; + +namespace Pulse.Scenarios; + +/// /pulse reload against a real server: the file on disk is rewritten under a +/// running server and read back through the same loader startup uses. +[AtlasDataFiles("data/reload/pulse.json", TargetPath = "ModConfig")] +public class ConfigReloadScenarios : AtlasScenarioBase +{ + private const int Port = 39474; + + private static string Config(int port, bool attribution, int burstTicks) => + $$""" + { + "Enabled": true, + "Bind": "127.0.0.1", + "Port": {{port}}, + "RuntimeMetrics": false, + "ChunksRefreshSeconds": 30, + "Attribution": { + "Enabled": {{(attribution ? "true" : "false")}}, + "BurstTicks": {{burstTicks}}, + "IntervalSeconds": 1 + } + } + """; + + [AtlasScenario] + public async Task Reload_Applies_TheAttributionBlock_AndNamesWhatItCannot() + { + await World.Ticks(5); + string path = Path.Combine(World.Api.GetOrCreateDataPath("ModConfig"), "pulse.json"); + + File.WriteAllText(path, Config(Port, attribution: true, burstTicks: 7)); + CommandResult applied = await World.ExecuteCommand("/pulse reload"); + + Assert.True(applied.Ok, applied.Message); + Assert.Equal( + "Reloaded pulse.json. Attribution is on: bursts of 7 ticks every 1s. " + + "Nothing else in the file differs from what the server is running.", + applied.Message); + + // Not the tick count: the server is ticking while this reads, so a burst may well have + // landed between the reload and the question. + CommandResult status = await World.ExecuteCommand("/pulse attribution status"); + Assert.StartsWith("Attribution is on: bursts of 7 ticks every 1s,", status.Message); + + // A key that was wired into a socket at startup. Reload cannot move it, and the reply has + // to say which one rather than leave the operator wondering why nothing happened. + File.WriteAllText(path, Config(19999, attribution: true, burstTicks: 7)); + CommandResult needsRestart = await World.ExecuteCommand("/pulse reload"); + + Assert.EndsWith("Port differs from what the server is running and needs a restart.", needsRestart.Message); + Assert.Contains("pulse_server_ticks_total", await Scrape.Metrics(Port)); + + // And a file nobody can read changes nothing at all. + File.WriteAllText(path, "this is not json"); + CommandResult broken = await World.ExecuteCommand("/pulse reload"); + + Assert.False(broken.Ok); + Assert.StartsWith("Pulse could not read pulse.json (", broken.Message); + Assert.EndsWith("Nothing changed: the server is still running the config it booted with.", broken.Message); + + CommandResult unchanged = await World.ExecuteCommand("/pulse attribution status"); + Assert.StartsWith("Attribution is on: bursts of 7 ticks every 1s,", unchanged.Message); + } +} diff --git a/Pulse.Scenarios/HotToggleScenarios.cs b/Pulse.Scenarios/HotToggleScenarios.cs new file mode 100644 index 0000000..f59cbf7 --- /dev/null +++ b/Pulse.Scenarios/HotToggleScenarios.cs @@ -0,0 +1,97 @@ +using Atlas.Api; +using Atlas.XUnit; +using Xunit; + +namespace Pulse.Scenarios; + +/// Switching attribution on and off against a real engine, which is the only place the +/// interesting half can be proven: that a server which booted with attribution off can still turn +/// the engine's frame profiler on part-way through its life without dying, and turn it back off +/// again. The unit suite can check the state machine; only a live server can check that the +/// priming done at startup is what makes the later switch safe. +/// One scenario rather than several, because scenarios in a class share a world and this one +/// is a sequence: off, on, measuring, off again. +[AtlasDataFiles("data/hottoggle/pulse.json", TargetPath = "ModConfig")] +public class HotToggleScenarios : AtlasScenarioBase +{ + private const int Port = 39473; + + [AtlasScenario] + public async Task Attribution_SwitchesOnAndOff_WithoutARestart() + { + await World.Ticks(5); + + // Armed, not running. The four families are registered so the switch has something to + // record into, and an instrument nothing has recorded into is not a series: a server that + // never asks for attribution serves the exposition it always did. + string idle = await Scrape.Metrics(Port); + Assert.DoesNotContain("pulse_mod_tick_share", idle); + Assert.DoesNotContain("pulse_attribution_ticks_total", idle); + + CommandResult off = await World.ExecuteCommand("/pulse attribution status"); + Assert.True(off.Ok, off.Message); + Assert.Equal( + "Attribution is off. It would run bursts of 5 ticks every 1s; 0 ticks profiled so far.", + off.Message); + + CommandResult on = await World.ExecuteCommand("/pulse attribution on"); + Assert.True(on.Ok, on.Message); + Assert.Equal( + "Attribution is on: bursts of 5 ticks every 1s. pulse.json was not changed, so the " + + "file decides again after a restart.", + on.Message); + + // Seeded the moment it is switched on, rather than a burst later: a family that shows up + // mid-scrape is a family no dashboard plots. + string armed = await Scrape.Metrics(Port); + Assert.Contains("pulse_mod_tick_share{modid=\"engine\"} ", armed); + Assert.Equal(0, Scrape.Value(armed, "pulse_attribution_ticks_total")); + + string body = await Burst(); + + // The server survived a profiler switched on mid-life, the marks parsed, and Pulse found + // itself in its own numbers. + Assert.InRange(Share(body, "pulse"), double.Epsilon, 1.0); + + CommandResult stop = await World.ExecuteCommand("/pulse attribution off"); + Assert.True(stop.Ok, stop.Message); + Assert.StartsWith("Attribution is off, and the engine's frame profiler with it.", stop.Message); + + await World.Ticks(5); + + // The flag actually went back down. Leaving it up would charge every later tick a few + // percent for a tree nobody reads. + Assert.False(World.Api.World.FrameProfiler.Enabled); + + long profiled = (long)Scrape.Value(await Scrape.Metrics(Port), "pulse_attribution_ticks_total"); + await World.Ticks(300); + Assert.Equal(profiled, (long)Scrape.Value(await Scrape.Metrics(Port), "pulse_attribution_ticks_total")); + + CommandResult after = await World.ExecuteCommand("/pulse attribution status"); + Assert.Equal( + $"Attribution is off. It would run bursts of 5 ticks every 1s; {profiled} ticks profiled so far.", + after.Message); + } + + /// 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 async Task Burst() + { + 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; + } + + private static double Share(string exposition, string modid) + => Scrape.Value(exposition, $"pulse_mod_tick_share{{modid=\"{modid}\"}}"); +} diff --git a/Pulse.Scenarios/data/hottoggle/pulse.json b/Pulse.Scenarios/data/hottoggle/pulse.json new file mode 100644 index 0000000..2d9d91b --- /dev/null +++ b/Pulse.Scenarios/data/hottoggle/pulse.json @@ -0,0 +1,12 @@ +{ + "Enabled": true, + "Bind": "127.0.0.1", + "Port": 39473, + "RuntimeMetrics": false, + "ChunksRefreshSeconds": 30, + "Attribution": { + "Enabled": false, + "BurstTicks": 5, + "IntervalSeconds": 1 + } +} diff --git a/Pulse.Scenarios/data/reload/pulse.json b/Pulse.Scenarios/data/reload/pulse.json new file mode 100644 index 0000000..202bf68 --- /dev/null +++ b/Pulse.Scenarios/data/reload/pulse.json @@ -0,0 +1,12 @@ +{ + "Enabled": true, + "Bind": "127.0.0.1", + "Port": 39474, + "RuntimeMetrics": false, + "ChunksRefreshSeconds": 30, + "Attribution": { + "Enabled": false, + "BurstTicks": 5, + "IntervalSeconds": 1 + } +} diff --git a/Pulse.Tests/PulseCommandsTests.cs b/Pulse.Tests/PulseCommandsTests.cs new file mode 100644 index 0000000..0a2df02 --- /dev/null +++ b/Pulse.Tests/PulseCommandsTests.cs @@ -0,0 +1,126 @@ +using Xunit; + +namespace Pulse.Tests; + +/// The replies an operator reads off their console, and the comparison behind the one +/// sentence that could quietly mislead them: which keys the file has moved away from and a reload +/// cannot do anything about. +public class PulseCommandsTests +{ + private static PulseConfig Config() => new() + { + Enabled = true, + Bind = "127.0.0.1", + Port = 9464, + RuntimeMetrics = true, + ChunksRefreshSeconds = 30, + }; + + [Fact] + public void RestartKeys_Reports_Nothing_WhenTheFileMatchesTheRunningServer() + => Assert.Empty(PulseCommands.RestartKeys(Config(), Config())); + + /// The Attribution block is the one part a reload does apply, so a change there is + /// not a reason to restart and must not be named as one. + [Fact] + public void RestartKeys_Ignores_TheAttributionBlock() + { + PulseConfig loaded = Config(); + loaded.Attribution = new AttributionConfig { Enabled = true, BurstTicks = 7, IntervalSeconds = 2 }; + + Assert.Empty(PulseCommands.RestartKeys(Config(), loaded)); + } + + [Fact] + public void RestartKeys_Names_EveryKeyThatIsReadOnlyAtStartup() + { + PulseConfig loaded = Config(); + loaded.Enabled = false; + loaded.Bind = "0.0.0.0"; + loaded.Port = 9999; + loaded.RuntimeMetrics = false; + loaded.ChunksRefreshSeconds = 5; + + Assert.Equal( + ["Enabled", "Bind", "Port", "RuntimeMetrics", "ChunksRefreshSeconds"], + PulseCommands.RestartKeys(Config(), loaded)); + } + + [Fact] + public void RestartKeys_Names_OnlyTheKeysThatActuallyDiffer() + { + PulseConfig loaded = Config(); + loaded.Port = 9999; + + Assert.Equal(["Port"], PulseCommands.RestartKeys(Config(), loaded)); + } + + /// Switching attribution deliberately never writes the file, and the reply has to say + /// so: an operator who took a ten minute look must not find it still running next month. + [Fact] + public void Switched_Says_TheFileWasNotTouched() + { + Assert.Contains("pulse.json was not changed", PulseCommands.Switched(true, 30, 10)); + Assert.Contains("pulse.json was not changed", PulseCommands.Switched(false, 30, 10)); + } + + [Fact] + public void Switched_Reports_TheDutyCycleItStarted() + => Assert.StartsWith("Attribution is on: bursts of 30 ticks every 10s.", PulseCommands.Switched(true, 30, 10)); + + [Fact] + public void Switched_Reports_TheProfilerGoingOffToo() + => Assert.StartsWith("Attribution is off, and the engine's frame profiler with it.", PulseCommands.Switched(false, 30, 10)); + + [Fact] + public void Status_Reports_TheCycle_TheTicksProfiled_AndTheBurstInProgress() + => Assert.Equal( + "Attribution is on: bursts of 30 ticks every 10s, 120 ticks profiled so far, profiling right now.", + PulseCommands.Status(true, 30, 10, 120, inBurst: true)); + + [Fact] + public void Status_Distinguishes_IdlingFromProfiling() + => Assert.Equal( + "Attribution is on: bursts of 30 ticks every 10s, 120 ticks profiled so far, waiting for the next burst.", + PulseCommands.Status(true, 30, 10, 120, inBurst: false)); + + /// Off, the cycle is what it would use, not what it is using, and the count is what a + /// previous stretch of profiling left behind. + [Fact] + public void Status_Reports_TheCycleItWouldUse_WhenItIsOff() + => Assert.Equal( + "Attribution is off. It would run bursts of 5 ticks every 1s; 40 ticks profiled so far.", + PulseCommands.Status(false, 5, 1, 40, inBurst: false)); + + [Fact] + public void Reloaded_Says_WhatItApplied_AndThatNothingElseMoved() + => Assert.Equal( + "Reloaded pulse.json. Attribution is on: bursts of 7 ticks every 2s. " + + "Nothing else in the file differs from what the server is running.", + PulseCommands.Reloaded(true, 7, 2, [])); + + [Fact] + public void Reloaded_Names_TheOneKeyThatNeedsARestart() + => Assert.EndsWith( + "Port differs from what the server is running and needs a restart.", + PulseCommands.Reloaded(false, 30, 10, ["Port"])); + + [Fact] + public void Reloaded_Lists_SeveralKeysThatNeedARestart() + => Assert.EndsWith( + "Port, Bind differ from what the server is running and need a restart.", + PulseCommands.Reloaded(false, 30, 10, ["Port", "Bind"])); + + /// The engine runs a command reply through string.Format on its way to whoever asked, + /// so the parse error goes in as a parameter. A sentence that interpolated it would throw on + /// the very typo it is reporting: a stray brace in the JSON. + [Fact] + public void ReloadFailed_Keeps_TheErrorAsAFormatParameter() + { + Assert.Contains("{0}", PulseCommands.ReloadFailed); + Assert.Equal( + "Pulse could not read pulse.json (Unexpected character: }). Nothing changed: the server " + + "is still running the config it booted with.", + string.Format(PulseCommands.ReloadFailed, "Unexpected character: }")); + } +} diff --git a/Pulse.Tests/TickAttributionTests.cs b/Pulse.Tests/TickAttributionTests.cs index c7024d0..ae27081 100644 --- a/Pulse.Tests/TickAttributionTests.cs +++ b/Pulse.Tests/TickAttributionTests.cs @@ -221,6 +221,100 @@ public void Take_Keeps_ReportingAModThatWentQuiet() Assert.Equal(0, Share(second, "mymod")); } + [Fact] + public void Constructor_Starts_Disabled_WhenTheConfigSaysSo() + { + TickAttribution attribution = new(1, 1, enabled: false); + + for (int tick = 0; tick < 100; tick++) + { + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); + } + + Assert.False(attribution.Enabled); + Assert.False(attribution.Profiling); + Assert.Equal(0, attribution.TicksProfiled); + } + + /// The whole point of arming attribution on a server that did not ask for it: it can + /// be switched on later, and then it works exactly as if the config had said so. + [Fact] + public void Apply_Starts_TheCycle_OnAServerThatBootedWithItOff() + { + TickAttribution attribution = new(2, 1, enabled: false); + attribution.OnTick(1.0, Tick(), Owners); + + attribution.Apply(true, 2, 1); + AttributionBurst burst = Cycle(attribution, Tick(), Owners); + + Assert.Equal(2, burst.Ticks); + Assert.Equal(200.0 / 600.0, Share(burst, "mymod"), 6); + } + + /// Switching it off part-way through a burst must not publish the half of a sample it + /// had: the profiler goes off, the accumulators go back to zero, and the tick count stays at + /// what completed bursts actually measured. + [Fact] + public void Apply_Drops_ABurstInProgress_WhenItIsSwitchedOff() + { + TickAttribution attribution = new(30, 1); + for (int tick = 0; tick < 5; tick++) + { + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); + } + + Assert.True(attribution.Profiling); + + attribution.Apply(false, 30, 1); + + Assert.False(attribution.Profiling); + Assert.Equal(0, attribution.TicksProfiled); + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); + Assert.False(attribution.Profiling); + } + + /// Re-enabling starts a fresh cycle, so the stale tree the profiler left behind while + /// it was off is discarded rather than folded into the first burst. + [Fact] + public void Apply_Discards_TheStaleSample_WhenItIsSwitchedBackOn() + { + TickAttribution attribution = new(1, 1); + Cycle(attribution, Tick(), Owners); + attribution.Apply(false, 1, 1); + + attribution.Apply(true, 1, 1); + Assert.Null(attribution.OnTick(1.0, Tick(), Owners)); // the interval passes, profiler 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 Apply_Takes_ANewDutyCycle_AndClampsItTheSameWay() + { + TickAttribution attribution = new(30, 10); + + attribution.Apply(true, 100000, 0); + + Assert.Equal(TickAttribution.MaximumBurstTicks, attribution.BurstTicks); + Assert.Equal(TickAttribution.MinimumIntervalSeconds, attribution.IntervalSeconds); + } + + /// What /pulse attribution status reports, and it has to match the tick counter + /// on the wire: both count the ticks completed bursts folded. + [Fact] + public void TicksProfiled_Accumulates_AcrossBursts() + { + TickAttribution attribution = new(3, 1); + + Cycle(attribution, Tick(), Owners); + Assert.Equal(3, attribution.TicksProfiled); + + Cycle(attribution, Tick(), Owners); + Assert.Equal(6, attribution.TicksProfiled); + } + [Fact] public void Take_Orders_TheBucketsStably() { diff --git a/Pulse/PulseCommands.cs b/Pulse/PulseCommands.cs new file mode 100644 index 0000000..3ed14b3 --- /dev/null +++ b/Pulse/PulseCommands.cs @@ -0,0 +1,69 @@ +namespace Pulse; + +/// What /pulse says back, and which config keys a reload cannot apply to a running +/// server. +/// Text and comparison only: no state, no server, no file. That is what makes every reply +/// an operator will read assertable from a unit test. +internal static class PulseCommands +{ + /// The reply to a reload that could not read the file. The error arrives as a message + /// parameter rather than baked into the sentence: the engine runs a reply through + /// string.Format on its way to whoever asked, and a JSON error quoting a stray brace + /// would blow that up. + public const string ReloadFailed = + "Pulse could not read pulse.json ({0}). Nothing changed: the server is still running the " + + "config it booted with."; + + public const string Unavailable = + "Attribution is not available this run: Pulse could not read the engine's frame profiler."; + + /// Said after every switch, because the whole point is that it does not persist. + private const string NotWritten = + "pulse.json was not changed, so the file decides again after a restart."; + + /// Keys whose value on disk differs from the value the server is running on. + /// Everything outside the Attribution block is read once in StartServerSide and + /// wired into a socket, a meter or a listener interval, so a difference here is something the + /// operator has to restart for. Compared against the config the server booted with rather than + /// the last file read, so a second reload still names a port that is still wrong. + public static IReadOnlyList RestartKeys(PulseConfig running, PulseConfig loaded) => + new (string Key, bool Changed)[] + { + (nameof(PulseConfig.Enabled), running.Enabled != loaded.Enabled), + (nameof(PulseConfig.Bind), running.Bind != loaded.Bind), + (nameof(PulseConfig.Port), running.Port != loaded.Port), + (nameof(PulseConfig.RuntimeMetrics), running.RuntimeMetrics != loaded.RuntimeMetrics), + (nameof(PulseConfig.ChunksRefreshSeconds), running.ChunksRefreshSeconds != loaded.ChunksRefreshSeconds), + } + .Where(key => key.Changed) + .Select(key => key.Key) + .ToList(); + + public static string Switched(bool on, int burstTicks, int intervalSeconds) => + on + ? $"Attribution is on: {Cycle(burstTicks, intervalSeconds)}. {NotWritten}" + : $"Attribution is off, and the engine's frame profiler with it. {NotWritten}"; + + public static string Status(bool on, int burstTicks, int intervalSeconds, long ticksProfiled, bool inBurst) => + on + ? $"Attribution is on: {Cycle(burstTicks, intervalSeconds)}, {ticksProfiled} ticks profiled so far, " + + (inBurst ? "profiling right now." : "waiting for the next burst.") + : $"Attribution is off. It would run {Cycle(burstTicks, intervalSeconds)}; " + + $"{ticksProfiled} ticks profiled so far."; + + public static string Reloaded(bool on, int burstTicks, int intervalSeconds, IReadOnlyList restartKeys) + { + string attribution = on ? $"Attribution is on: {Cycle(burstTicks, intervalSeconds)}." : "Attribution is off."; + string rest = restartKeys.Count switch + { + 0 => "Nothing else in the file differs from what the server is running.", + 1 => $"{restartKeys[0]} differs from what the server is running and needs a restart.", + _ => $"{string.Join(", ", restartKeys)} differ from what the server is running and need a restart.", + }; + + return $"Reloaded pulse.json. {attribution} {rest}"; + } + + private static string Cycle(int burstTicks, int intervalSeconds) + => $"bursts of {burstTicks} ticks every {intervalSeconds}s"; +} diff --git a/Pulse/PulseModSystem.cs b/Pulse/PulseModSystem.cs index d8384a8..10913df 100644 --- a/Pulse/PulseModSystem.cs +++ b/Pulse/PulseModSystem.cs @@ -69,6 +69,11 @@ public sealed class PulseModSystem : ModSystem private volatile EngineSample? engine; private ICoreServerAPI? sapi; + + /// The config the server booted on, kept so a reload can say which keys the file has + /// moved away from and a restart is now the only way to pick up. + private PulseConfig? booted; + private Meter? meter; private MetricsAggregator? aggregator; private MetricsHttpServer? http; @@ -116,6 +121,7 @@ public override void StartServerSide(ICoreServerAPI api) return; } + booted = config; meter = new Meter(MeterName); tickBookkeeper = new TickBookkeeper( meter.CreateCounter( @@ -173,7 +179,8 @@ 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. + // Armed whether or not the operator asked for it, so /pulse attribution on has something + // to switch. Nothing is measured until it is switched on. StartAttribution(api, meter, config.Attribution ?? new AttributionConfig()); // The runtime publishes System.Runtime itself, so listening to it is the whole of the @@ -211,6 +218,7 @@ public override void StartServerSide(ICoreServerAPI api) api.Event.ServerSuspend += OnServerSuspend; api.Event.ServerResume += OnServerResume; + RegisterCommands(api); StartEndpoint(api, config); } @@ -368,18 +376,16 @@ 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. + /// Publishes the attribution families and arms the duty cycle. + /// All of it runs whether or not Attribution.Enabled is set, priming included, + /// because that is what makes switching attribution on later structurally safe rather than + /// merely likely to work: see PrimeFrameProfiler for what happens to a server whose profiler is + /// enabled part-way through a tick having never completed one. The cost of arming an operator + /// never uses is two profiled ticks at startup and four instruments nothing records into, and + /// an instrument with no measurement is not a series: an idle server serves the same exposition + /// it did before. 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) { @@ -399,7 +405,7 @@ private void StartAttribution(ICoreServerAPI api, Meter attributionMeter, Attrib api.Logger.Warning(ListenerWalkWarning, e.Message); } - attribution = new TickAttribution(config.BurstTicks, config.IntervalSeconds); + attribution = new TickAttribution(config.BurstTicks, config.IntervalSeconds, config.Enabled); 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."); @@ -415,9 +421,107 @@ private void StartAttribution(ICoreServerAPI api, Meter attributionMeter, Attrib // 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); + if (config.Enabled) + { + api.Logger.Notification( + "Pulse attributes the tick per mod: bursts of {0} ticks every {1}s.", + attribution.BurstTicks, attribution.IntervalSeconds); + } + else + { + api.Logger.Notification( + "Pulse is ready to attribute the tick per mod but is not measuring: /pulse attribution on starts it."); + } + } + + /// Registers /pulse, which is how attribution gets switched on while the + /// server is the thing you wanted to look at. + /// controlserver rather than a privilege of its own, so the admins and the + /// hosting panel console that already run /stats can run this too. Every handler here + /// reaches the runtime state on the main thread: chat commands are dispatched while the server + /// is handling packets, and the console reader enqueues its line as a main thread task. + private void RegisterCommands(ICoreServerAPI api) + { + api.ChatCommands.Create("pulse") + .WithDescription("Per-mod tick attribution and config reload, without restarting the server.") + .RequiresPrivilege(Privilege.controlserver) + .BeginSubCommand("attribution") + .WithDescription("Per-mod tick attribution on the running server.") + .BeginSubCommand("on") + .WithDescription("Start the attribution duty cycle now. Does not write pulse.json.") + .HandleWith(_ => SwitchAttribution(true)) + .EndSubCommand() + .BeginSubCommand("off") + .WithDescription("Stop it, and switch the engine's frame profiler back off.") + .HandleWith(_ => SwitchAttribution(false)) + .EndSubCommand() + .BeginSubCommand("status") + .WithDescription("Say whether attribution is running, and what it has measured.") + .HandleWith(_ => AttributionStatus()) + .EndSubCommand() + .EndSubCommand() + .BeginSubCommand("reload") + .WithDescription("Re-read pulse.json and apply what can change without a restart.") + .HandleWith(_ => Reload(api)) + .EndSubCommand(); + } + + private TextCommandResult SwitchAttribution(bool on) + { + if (attribution == null) + { + return TextCommandResult.Error(PulseCommands.Unavailable); + } + + attribution.Apply(on, attribution.BurstTicks, attribution.IntervalSeconds); + SeedAttribution(); + return TextCommandResult.Success( + PulseCommands.Switched(on, attribution.BurstTicks, attribution.IntervalSeconds)); + } + + private TextCommandResult AttributionStatus() + => attribution == null + ? TextCommandResult.Error(PulseCommands.Unavailable) + : TextCommandResult.Success(PulseCommands.Status( + attribution.Enabled, + attribution.BurstTicks, + attribution.IntervalSeconds, + attribution.TicksProfiled, + attribution.Profiling)); + + /// Re-reads the config file and applies the part of it a running server can take. + /// The same load and upgrade path startup uses, so a file that gained keys since it + /// was written is completed here as well. A file that does not parse leaves everything exactly + /// as it was: the reply carries the parse error and the server keeps running on what it + /// booted with. + private TextCommandResult Reload(ICoreServerAPI api) + { + PulseConfig loaded; + try + { + loaded = api.LoadModConfig(ConfigFile) + ?? throw new FileNotFoundException(ConfigFile + " is not in ModConfig"); + ConfigUpgrade.Upgrade(api, loaded, ConfigFile, "Pulse"); + } + catch (Exception e) + { + return new TextCommandResult + { + Status = EnumCommandStatus.Error, + StatusMessage = PulseCommands.ReloadFailed, + MessageParams = [e.Message], + }; + } + + AttributionConfig cycle = loaded.Attribution ?? new AttributionConfig(); + attribution?.Apply(cycle.Enabled, cycle.BurstTicks, cycle.IntervalSeconds); + SeedAttribution(); + + return TextCommandResult.Success(PulseCommands.Reloaded( + attribution?.Enabled ?? false, + attribution?.BurstTicks ?? cycle.BurstTicks, + attribution?.IntervalSeconds ?? cycle.IntervalSeconds, + PulseCommands.RestartKeys(booted!, loaded))); } /// Turns the engine's frame profiler on once, before the server starts ticking. @@ -467,6 +571,7 @@ private void OnAttributionTick(double elapsedSeconds) if (++unprimedTicks > UnprimedTickLimit) { attribution = null; + profiler.Enabled = false; sapi.Logger.Warning(AttributionWarning, "the engine's profiler never completed a primed tick"); } @@ -530,10 +635,13 @@ private void PublishBurst(AttributionBurst burst) /// 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. + /// which mods eat tick time until one has been profiled. + /// Only once attribution is actually running, which is also what keeps a server that + /// never switches it on free of four families that would never move. Called again by the + /// command that switches it on, so the families reach the wire there too. private void SeedAttribution() { - if (attribution == null) + if (attribution is not { Enabled: true }) { return; } diff --git a/Pulse/TickAttribution.cs b/Pulse/TickAttribution.cs index 452842d..297454c 100644 --- a/Pulse/TickAttribution.cs +++ b/Pulse/TickAttribution.cs @@ -56,24 +56,45 @@ internal sealed class TickAttribution private long dropped; private bool warm; - public TickAttribution(int burstTicks, int intervalSeconds) - { - BurstTicks = Math.Clamp(burstTicks, 1, MaximumBurstTicks); - IntervalSeconds = Math.Max(MinimumIntervalSeconds, intervalSeconds); - } + public TickAttribution(int burstTicks, int intervalSeconds, bool enabled = true) + => Apply(enabled, burstTicks, intervalSeconds); + + /// Whether the duty cycle runs at all. + public bool Enabled { get; private set; } - public int BurstTicks { get; } + public int BurstTicks { get; private set; } - public int IntervalSeconds { get; } + public int IntervalSeconds { get; private set; } /// Whether the engine's frame profiler has to be enabled when the current tick ends. public bool Profiling { get; private set; } + /// Ticks folded into a completed burst since the server booted, which is the number + /// pulse_attribution_ticks_total reports. + public long TicksProfiled { get; private set; } + + /// Takes a duty cycle, clamped the way the config file's is, and starts it over. + /// Restarting rather than adjusting in place is what makes switching this off + /// mid-burst safe: the half-folded sample is dropped instead of published, the profiler goes + /// back off on the next tick, and a later switch-on begins from a clean burst. + public void Apply(bool enabled, int burstTicks, int intervalSeconds) + { + Enabled = enabled; + BurstTicks = Math.Clamp(burstTicks, 1, MaximumBurstTicks); + IntervalSeconds = Math.Max(MinimumIntervalSeconds, intervalSeconds); + Restart(); + } + /// 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 (!Enabled) + { + return null; + } + if (!Profiling) { idleSeconds += elapsedSeconds; @@ -110,7 +131,6 @@ public TickAttribution(int burstTicks, int intervalSeconds) return null; } - Profiling = false; return Take(); } @@ -210,11 +230,25 @@ private AttributionBurst Take() } AttributionBurst burst = new(seconds, busyTicks / frequency, sampled, dropped); + TicksProfiled += sampled; + Restart(); + return burst; + } + + /// Back to idle with nothing accumulated, and the profiler off from the next tick. + /// Everything a burst gathers is dropped here, but seenMods is not: a mod that + /// has been measured once keeps publishing a zero rather than freezing its gauge, whether the + /// burst ended on its own or an operator cut it short. + private void Restart() + { + Profiling = false; + idleSeconds = 0; + burstTicksElapsed = 0; + warm = false; ticksByMod.Clear(); busyTicks = 0; sampled = 0; dropped = 0; - return burst; } } diff --git a/README.md b/README.md index 2ced3d6..4812e49 100644 --- a/README.md +++ b/README.md @@ -128,6 +128,33 @@ It is off by default, because it is not free. Add an `Attribution` block to `Mod 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. +### Turning it on without a restart + +The moment you want attribution is usually while the server is struggling, and restarting it throws +away the thing you wanted to look at. So the config file is not the only way in. Four commands, all +behind the `controlserver` privilege, so admins and a panel console can run them: + +- `/pulse attribution on` starts the duty cycle straight away, on whatever `BurstTicks` and + `IntervalSeconds` are in force. The first burst lands one interval later. +- `/pulse attribution off` stops it and puts the engine's frame profiler back down. A burst in + progress is dropped rather than published half-measured. +- `/pulse attribution status` reports whether it is running, the cycle it is using, how many ticks + it has profiled and whether it is inside a burst right now. +- `/pulse reload` re-reads `pulse.json` and applies the `Attribution` block live. The reply names + any other key whose value in the file has drifted from what the server is running, since those + still need a restart, and a file that does not parse changes nothing at all. + +`on` and `off` act on the running server and never write `pulse.json`, which is deliberate: a ten +minute look should not become permanent because somebody forgot to turn it off. Restart the server +and the file decides again. To make a change stick, edit the file and either restart or run +`/pulse reload`. + +This works even on a server that booted with `Attribution.Enabled` false. Pulse registers the four +families and primes the engine's profiler at startup either way, because a profiler switched on +part-way through a tick that has never completed one takes the server down with it (there is more +on that below). Priming costs two profiled ticks at boot and nothing after; an instrument nothing +has recorded into is not a series, so an idle server serves exactly the exposition it did before. + Four families appear once it is on: - `pulse_mod_tick_share{modid}` (gauge): the fraction of profiled main-thread busy time that went @@ -217,8 +244,11 @@ socket, no meter. `RuntimeMetrics` false drops the `dotnet_*` families and keeps 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. `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. +because it costs tick time. + +Everything outside the `Attribution` block takes a server restart. The block itself does not: +`/pulse reload` applies it live, and `/pulse attribution on` and `off` switch it without touching +the file at all. Upgrading does not mean editing the file by hand. Each mod checks its config file at startup and writes back any key it knows about that the file is missing, with that key's default; the values diff --git a/tools/mutation-check.sh b/tools/mutation-check.sh index 5cac9b2..d1614e3 100755 --- a/tools/mutation-check.sh +++ b/tools/mutation-check.sh @@ -47,7 +47,7 @@ mutate() { #