Attribute the tick to the mods eating it - #50
Merged
Merged
Conversation
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #22.
The route
The engine already contains a per-mod tick attributor and simply never switches it on. With
sapi.World.FrameProfiler.Enabledtrue the server swaps toEventManager.TriggerGameTickDebug,which stamps a marker after every game tick listener, every delayed callback and every main-thread
entity behaviour, and leaves the completed tree on the public
PrevRootEntryfield. Pulse readsthat tree from its own tick listener, folds it into seconds per mod, and hands the numbers to the
meter. No Harmony, no engine patch, no new dependency, and the whole read path is public API.
Mapping a marker key back to a mod id is two sources.
api.ModLoader.ModsplusMod.Systemsgivesassembly to mod id and covers every listener a mod registered from its own
ModSystem, which ismost of them; a read-only walk of the listener lists on both event managers sharpens the rest,
because
GameTickListener.Handleris a public field and its target's assembly is the mod's. Entitybehaviours needed a third bridge that the issue's plan did not anticipate, described below.
Four families, only present when the config asks for them:
pulse_mod_tick_share{modid}(gauge), fraction of profiled main-thread busy time over the lastcompleted burst. Shares add to 1 across every
modid.pulse_mod_tick_seconds_total{modid}(counter), sampled seconds, said out loud in the help textand the README because it is time inside the bursts, not since startup.
pulse_attribution_ticks_total(counter), so the sampled seconds can be normalised.pulse_attribution_dropped_samples_total(counter), the wrapped readings thrown away.The duty cycle
Off by default behind a new
Attributionblock inpulse.json(Enabled,BurstTicks30,IntervalSeconds10). A profiled tick costs roughly 2.8% of the budget on a 20-player, 4000-entityserver, because the marker count scales with entities times behaviours rather than with mod count.
Bursts bring that to about 0.3% amortised. Both knobs are clamped on read: the interval floors at a
second and the burst caps at 300 ticks, so a config typo cannot turn a duty cycle into an
always-on profiler.
The hazards
The crash.
FrameProfilerUtil.End()dereferences the root range that the matchingBegin()creates, and
ServerMain.ProcesscallsEnd()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). Flipping theflag part way through a tick on a server whose profiler has never run means
End()runs with noBegin()before it, and the NullReferenceException takes the process down. The profiler is primedonce from
ServerRunPhase(RunGame), whileLaunchis still running and beforeServerProgramenters its loop.
I added a second guard on top of that, because a comment is not a safety mechanism: the duty cycle
refuses to enable the profiler until
PrevRootEntryis non-null. OnlyEnd()sets that field, andit sets it after the dereference that would have thrown, so a non-null value is proof the same
dereference is safe next time. That makes the crash structurally unreachable rather than merely
avoided, and it means a priming that never took (a fork that runs the run phase on another thread,
say) degrades to one warning and no attribution instead of a dead server.
The int wrap.
ProfileEntry.ElapsedTicksis anintwhile the stopwatch behind it ticks at ananosecond, so one marker wraps negative past about 2.147 seconds inside a single tick, which is
exactly the pathological tick an operator wants explained. Negative readings are clamped to zero
and counted in
pulse_attribution_dropped_samples_total, because a wrapped value is garbage ratherthan a large number.
Degradation. The listener walk is the only reflection, it lives in
AttributionProbeunder thesame
NoInliningplus try/catch contract asEngineProbe, and losing it costs precision in themap rather than the feature: the mod loader's own type list keeps working and unmapped markers
report as
unattributed. Losing the profiler read gives one warning, puts the flag back and stopsfor the run.
Two deviations from the proposed design, and why
The fold walks the whole tree, not just the root markers. Entering a child range moves the
parent's last-marker cursor past the child on the way out, so a child range's time is charged to no
root marker at all.
tickentities,behaviorsandphysicsmanager-servertickare child ranges,and they are where the time on a busy server actually goes. A root-only fold would have reported a
modded server as almost entirely
engine. The fold recurses, and whatever the markers still do notname is charged to
engineas a remainder, which is what makes the shares add to 1.Entity behaviours are keyed by behaviour code, not by type name.
EntityBehavior.ProfilerNameis
"done-behavior-" + PropertyName(), so the type-name table the issue describes cannot resolvethem. They go through
IClassRegistryAPI.GetEntityBehaviorClass, on first sight of each name andthen remembered, misses included. This is public API and worth the five lines: without it every
vanilla and modded behaviour reads as
engine. On the scenario world it is what putsgameandsurvivalon the wire.One extra family beyond the three proposed:
pulse_attribution_dropped_samples_total, which isthe meta counter the int wrap needs to be honest about itself.
Tests
dotnet test Pulse.slnx -c Release, 152 to 183 tests, all green:The 26 new unit tests cover the duty cycle, the fold, the wrap clamp, the mapping table and the
gauge retirement. The 5 new Atlas scenarios boot a real server with attribution on, and are the
only place the engine-side half can be proven: that priming does not kill the server, that a burst
completes, that the marker prefixes still parse, that the shares add to 1, and that Pulse finds
itself in its own numbers as
modid="pulse". On the scenario world the exposition readsengine,unattributed,atlasbridge,game,pulseandsurvival, which is every mod loaded.tools/mutation-check.shgrows from 32 to 38 mutations, all killed: the wrap clamp boundary, thestale first sample, the sleep exclusion, the nested walk, the gauge retirement and the registry
memo.
Coverage exclusion
Pulse/AttributionProbe.csis added tosonar.coverage.exclusions. It is the engine-internal file,the counterpart to
Pulse/EngineProbe.cswhich is already excluded for the same reason: every linein it names a VintagestoryLib type or reflects onto an assembly-scoped field, so it cannot be
driven from a unit test with no server, and the scenarios exercise it out of process. Nothing else
new is excluded.
TickAttributionandModOwnerscarry the logic and are unit tested directly.Not in scope
Broadcast event handlers carry no markers at all in the engine (about forty of them,
PlayerJoin,DidBreakBlockand the rest), and thread-safe physics behaviours are marked for the main-threadslice only. Both are written up in the README's Attribution section rather than papered over, along
with the cost figures and the fact that the engine logs its physics overrun warning only while the
profiler is running.