diff --git a/docs/telemetry.md b/docs/telemetry.md index 698c9703..f4e575ce 100644 --- a/docs/telemetry.md +++ b/docs/telemetry.md @@ -66,7 +66,7 @@ Player identity is always the UUID in `cygnus.player.uuid`. No address of a play | `cygnus.player.kick` | A kick, including the wait for the client to drop the ResourcePack. Child of the phase running at the kick; a root when no round runs. | `cygnus.player.uuid`, `cygnus.kick.reason`, `cygnus.kick.completed_by` (`ack`, `timeout`, `immediate`) | | `cygnus.shutdown` | The request until the server stopped, ended before the JVM is told to exit. Its own trace, linked to the running (or last) round. | | | `cygnus.tick.slow` | A server tick that took at least the threshold, created after the fact. Child of the current phase; a root when no round runs. | `cygnus.tick.duration_ms`, `cygnus.tick.acquisition_ms`, `cygnus.tick.threshold_ms` | -| `cygnus.tick.section` | Child of a slow tick: the share of one measured service (`creek`, `slender-gaze`, `tunnel-vision`). | `cygnus.tick.section.name`, `cygnus.tick.section.duration_ms` | +| `cygnus.tick.section` | Child of a slow tick: the share of one measured service, see [Slow ticks](#slow-ticks). | `cygnus.tick.section.name`, `cygnus.tick.section.duration_ms` | A span that fails is marked `ERROR` and carries the exception. @@ -95,7 +95,33 @@ There is no span per tick. When a tick takes at least `telemetry.slowTickThresho Minestom's tick budget), a `cygnus.tick.slow` span is created after the fact: it ends now and started as long ago as the tick took. The services measured through `TickSections` appear as children. They all start at the start of the tick and last as long as the service took in total, so they show who was in the tick, not -when. A share below one millisecond is left out. +when. A share below 0.1 ms is left out, and a service that did not run in the tick has no child, so the lobby +tick shows `lobby-waiting` and `lobby-time` where a game tick shows the creek. + +The measured services, with the name each reports as `cygnus.tick.section.name` (the constants are in +`TickSectionNames`; one name per service, never per player): + +| Name | Service | +| --- | --- | +| `lobby-waiting` | The lobby's waiting action bar | +| `lobby-time` | The lobby's slide of the world time | +| `creek` | The creek's step | +| `glow-reveal` | The betrayal glow resend | +| `slender-gaze` | The slender's gaze check | +| `tunnel-vision` | The tunnel vision overlay | +| `page-glitch` | The page glitch overlay | +| `blood-splatter` | The fade of blood splatters | +| `page-proximity` | The page proximity hint | +| `ambient` | Ambient sounds and blackouts | +| `adrenaline` | The adrenaline rush | +| `slender-takeover` | The takeover countdown after the slender left | +| `stamina` | The survivors' stamina bars, added up | +| `slender-bar` | The slender's stamina bar | +| `jump-scare` | The despawn of a jump scare | + +Only what is scheduled through the Minestom scheduler can be measured. Time the server spends outside of +it (entity and chunk ticking, packet handling) is not a section, so a slow tick can still have a gap between the +sum of its children and its own duration; that gap is the engine. ```properties # config.properties @@ -104,6 +130,79 @@ telemetry.slowTickThresholdMillis=50 A value below 1 is rejected and the service refuses to start. +## Tick metrics + +Spans exist only for slow ticks, so a trace cannot say how long a lobby tick usually takes. Metrics are +recorded for every tick (`ServerTickMonitorEvent`) and every measured section, per phase. The javaagent exports +them over OTLP together with its own metrics; without the agent they are no-ops. + +| Instrument | Kind | Unit | Attributes | +| --- | --- | --- | --- | +| `cygnus.tick.duration` | histogram | `ms` | `cygnus.phase.name` | +| `cygnus.tick.section.duration` | histogram | `ms` | `cygnus.tick.section.name`, `cygnus.phase.name` | +| `cygnus.tick.slow` | counter | `{tick}` | `cygnus.phase.name` | + +- `cygnus.phase.name` is `lobby`, `waiting`, `gamephase`, `restart`, or `none` (no round or between phases). +- `cygnus.tick.section.name` is one of the names in [Slow ticks](#slow-ticks). A section is recorded for a tick + only if it ran in it, with the total of its runs. +- `cygnus.tick.slow` counts ticks at or above `telemetry.slowTickThresholdMillis`, the same rule as the span. +- Unit is milliseconds, not the seconds the semantic conventions prefer: Minestom's budget, the threshold and the + span attributes are in milliseconds, and a bucket at `50` reads as 50. +- Explicit buckets (ms): 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 15, 20, 25, 30, 40, 50, 75, 100, 150, 200. The SDK + default starts at 5 and would put the whole lobby in one bucket. +- The hot path allocates nothing of its own: attributes per phase and per section/phase pair are built once and + reused, values are recorded as primitives. + +### In Mimir / Grafana + +OTLP to Prometheus translation appends the unit and, for counters, `_total` (checked against the existing +`jvm_gc_duration_seconds_*` and `jvm_cpu_time_seconds_total` in Mimir). Dots become underscores: + +| OTel | Prometheus | +| --- | --- | +| `cygnus.tick.duration` | `cygnus_tick_duration_milliseconds_bucket` / `_sum` / `_count` | +| `cygnus.tick.section.duration` | `cygnus_tick_section_duration_milliseconds_bucket` / `_sum` / `_count` | +| `cygnus.tick.slow` | `cygnus_tick_slow_total` | +| `cygnus.phase.name` | label `cygnus_phase_name` | +| `cygnus.tick.section.name` | label `cygnus_tick_section_name` | + +For the Kubernetes-FLUX dashboard `cygnus-traces`, the per-phase and sub-tick panels should query these metrics +rather than derive them from slow tick spans, which only cover the tail. For example the p99 tick per phase: + +```promql +histogram_quantile(0.99, sum by (le, cygnus_phase_name) (rate(cygnus_tick_duration_milliseconds_bucket[5m]))) +``` + +and the mean cost of a section: `sum by (cygnus_tick_section_name) (rate(..._section_duration_milliseconds_sum[5m])) +/ sum by (cygnus_tick_section_name) (rate(..._section_duration_milliseconds_count[5m]))`. + +## Hunts + +A hunt is the chase of one creek after one survivor. It gets a span of its own, `cygnus.action.creek.hunt`, and a +metric, so "how long are survivors hunted, and how does it end" can be answered per map. + +| Outcome | Meaning | +| --- | --- | +| `caught` | The creek caught the survivor (the catch is reported just before the hunt ends). | +| `timeout` | The hunt ran out of its maximum time. | +| `gone` | The survivor died, left or turned before it ended. | +| `escaped` | The creek was sent away for good while it hunted (only one survivor left). | +| `round_end` | The creek was removed, or the round ended with the hunt still going. Hunts still open when a round ends are closed as `round_end` before the phase span ends. | + +| Instrument | Kind | Unit | Attributes | +| --- | --- | --- | --- | +| `cygnus.creek.hunt.duration` | histogram | `ms` | `cygnus.creek.hunt.outcome`, `cygnus.map` | +| `cygnus.creek.hunts` | counter | `{hunt}` | `cygnus.creek.hunt.outcome`, `cygnus.map` | + +Buckets (ms): 500, 1000, 2500, 5000, 7500, 10000, 15000, 20000, 30000, 45000, 60000, 90000, 120000. There is no +player attribute on the metrics (one series per player); the UUID is on the span. In Prometheus: +`cygnus_creek_hunt_duration_milliseconds_bucket` and `cygnus_creek_hunts_total`, labels `cygnus_creek_hunt_outcome` +and `cygnus_map`. A hunt that starts while no round runs has no span but is still counted. + +The creek reports a hunt by the survivor only, not by itself. Two creeks hunting the same survivor are two spans, +and each end closes the oldest open one of that survivor: the count is right, which span belongs to which creek +may not be. + ## Shutdown `ServiceShutdown` ends the span before it calls `Runtime.exit`. The agent flushes its exporter from a JVM @@ -136,6 +235,7 @@ player at that moment as `cygnus.position.x/y/z` (rounded to 0.1), plus `cygnus. | `cygnus.action.blackout.player` | child of a blackout, one per player hit; the player attributes only | | `cygnus.action.sanity.threshold` | `cygnus.sanity.band.from`, `cygnus.sanity.band`, `cygnus.sanity.fear` (0 calm, 1 maximum), `cygnus.sanity.value` (1 - fear, as `/creek` shows it), `cygnus.sanity.source` (`page`, `sighting`, `caught`, `selected`, `death`, `stalk`) | | `cygnus.action.creek.sighted`, `.selected`, `.stalk` (first step of a stalk only), `.caught` | the survivor's attributes only | +| `cygnus.action.creek.hunt` | A hunt, from the creek taking the survivor as its target until it stops. Child of the phase it started in. The survivor's attributes at the start, `cygnus.map`, `cygnus.creek.hunt.outcome` (`caught`, `timeout`, `gone`, `escaped`, `round_end`) and `cygnus.creek.hunt.duration_ms`. | `cygnus.page.out_ms` counts from the moment the page was placed or moved on. A page that has to wait on its own spot (no other spot is free) is counted from the moment it was hidden. diff --git a/game/src/main/java/net/onelitefeather/cygnus/Cygnus.java b/game/src/main/java/net/onelitefeather/cygnus/Cygnus.java index c3869b3f..a26a957f 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/Cygnus.java +++ b/game/src/main/java/net/onelitefeather/cygnus/Cygnus.java @@ -111,6 +111,9 @@ import net.onelitefeather.cygnus.telemetry.RoundTracer; import net.onelitefeather.cygnus.telemetry.ShutdownTracer; import net.onelitefeather.cygnus.telemetry.SlowTickTracer; +import net.onelitefeather.cygnus.telemetry.HuntMetrics; +import net.onelitefeather.cygnus.telemetry.HuntTracer; +import net.onelitefeather.cygnus.telemetry.TickMetrics; import net.onelitefeather.cygnus.telemetry.TickSections; import net.onelitefeather.cygnus.telemetry.TraceStep; import net.onelitefeather.cygnus.telemetry.TracedPhaseSeries; @@ -125,7 +128,7 @@ /** * @author theEvilReaper - * @version 1.3.0 + * @version 1.6.0 * @since 1.0.0 **/ @SuppressWarnings("java:S3252") @@ -181,12 +184,13 @@ public Cygnus() { Path path = ServiceBootstrap.resolveWorkingDirectory(); this.teamService = TeamService.of(); this.linearPhaseSeries = new TracedPhaseSeries<>("game", this.roundTracer); - this.jumpscareManager = new JumpScareManager(); + this.jumpscareManager = new JumpScareManager(tickSections); try (TraceStep ignored = startup.child("cygnus.startup.config")) { this.gameConfig = new GameConfigReader(path).getConfig(); } - this.slowTickTracer = new SlowTickTracer(this.tracing, this.roundTracer, this.gameConfig.telemetry(), Clock.systemUTC(), tickSections); - this.staminaService = new StaminaService(this.gameConfig.stamina()); + this.slowTickTracer = new SlowTickTracer(this.tracing, this.roundTracer, this.gameConfig.telemetry(), Clock.systemUTC(), tickSections, + TickMetrics.fromGlobal(serviceVersion(), this.roundTracer::phaseLabel)); + this.staminaService = new StaminaService(this.gameConfig.stamina(), tickSections); // Set up as early as possible so anything that goes wrong while the rest of the game is // being wired up is already covered. Stays off entirely when no DSN is configured. SentrySupport.init(this.gameConfig.sentryDsn()); @@ -209,13 +213,14 @@ public Cygnus() { this.scoreboardDisplay = new ScoreboardDisplay(this.teamService.getTeams()); Team survivorTeam = this.teamService.getTeam(GameConfig.SURVIVOR_KEY) .orElseThrow(() -> new IllegalStateException("Survivor team not found")); - this.ambientProvider = new AmbientProvider(survivorTeam, this.actionTracer.blackoutObserver("survivor")); + this.ambientProvider = new AmbientProvider(survivorTeam, this.actionTracer.blackoutObserver("survivor"), tickSections); // Only survivors get the hint: the slender hearing it would turn every page into a place to // camp at, which is the opposite of what the hint is for. this.pageProximityService = new PageProximityService( this.gameConfig.pageProximity(), survivorTeam::getPlayers, - this.pageProvider::interactablePages + this.pageProvider::interactablePages, + tickSections ); Team spectatorTeam = this.teamService.getTeam(GameConfig.SPECTATOR_KEY) .orElseThrow(() -> new IllegalStateException("Spectator team not found")); @@ -228,10 +233,12 @@ public Cygnus() { System::currentTimeMillis, () -> TeamHelper.survivorsOf(this.teamService), this.actionTracer.sanityObserver(Cygnus::survivorActor)); - this.slenderTakeover = new SlenderTakeover(this.teamService, this.linearPhaseSeries::getCurrentPhase); + this.slenderTakeover = new SlenderTakeover(this.teamService, this.linearPhaseSeries::getCurrentPhase, tickSections); try (TraceStep ignored = startup.child("cygnus.startup.features")) { CreekModule creekModule = new CreekModule(this.gameConfig.creek(), this.teamService, this.mapProvider, - sanityService, new HuntedTabWitness(new TracingCreekWitness(sanityService, this.actionTracer, Cygnus::survivorActor), + sanityService, new HuntedTabWitness(new TracingCreekWitness(sanityService, this.actionTracer, Cygnus::survivorActor, + new HuntTracer(this.roundTracer, Clock.systemUTC(), this::activeMapName, + Cygnus::survivorActor, HuntMetrics.fromGlobal(serviceVersion()))), MinecraftServer.getConnectionManager()::getOnlinePlayerByUuid), this.jumpscareManager, this.staminaService, tickSections); this.features = Stream.concat(this.resourcePackService.stream(), Stream.of( new EpilepsyDisclaimer(), @@ -252,7 +259,8 @@ sanityService, new HuntedTabWitness(new TracingCreekWitness(sanityService, this. new AdrenalineService( this.gameConfig.adrenaline(), () -> TeamHelper.survivorsOf(this.teamService), - System::currentTimeMillis), + System::currentTimeMillis, + tickSections), new FootprintFeature(this.gameConfig.footprint(), () -> TeamHelper.slenderOf(this.teamService), System::currentTimeMillis), @@ -262,7 +270,7 @@ sanityService, new HuntedTabWitness(new TracingCreekWitness(sanityService, this. } this.wakeUpTransition = new WakeUpTransition(); try (TraceStep ignored = startup.child("cygnus.startup.phases")) { - this.initPhases(sanityService); + this.initPhases(sanityService, tickSections); } try (TraceStep ignored = startup.child("cygnus.startup.listeners")) { this.initCommands(); @@ -373,7 +381,7 @@ private void registerGameListener() { GameFeatures.register(handler, this.features); } - private void initPhases(DreadSource dreadSource) { + private void initPhases(DreadSource dreadSource, TickSections tickSections) { VoidConsumer instanceSwitch = this.mapProvider::switchToGameMap; VoidConsumer teamInitializer = () -> { Instance activeInstance = this.mapProvider.getActiveInstance().get(); @@ -387,7 +395,7 @@ private void initPhases(DreadSource dreadSource) { ); MinecraftServer.getSchedulerManager().scheduleNextTick(this.mapProvider::releasePreviousInstance); }; - LobbyPhase lobbyPhase = new LobbyPhase(this.gameConfig.round(), this.mapProvider.getActiveInstance()); + LobbyPhase lobbyPhase = new LobbyPhase(this.gameConfig.round(), this.mapProvider.getActiveInstance(), tickSections); this.linearPhaseSeries.add(lobbyPhase); this.linearPhaseSeries.add(new WaitingPhase(this.view, instanceSwitch, teamInitializer, this.mapProvider.getActiveInstance(), this.wakeUpTransition)); GamePhase gamePhase = new GamePhase(this.view, this.gameConfig.round().gameTime(), this.jumpscareManager, dreadSource); diff --git a/game/src/main/java/net/onelitefeather/cygnus/adrenaline/AdrenalineService.java b/game/src/main/java/net/onelitefeather/cygnus/adrenaline/AdrenalineService.java index 078e7bd3..be9efd6c 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/adrenaline/AdrenalineService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/adrenaline/AdrenalineService.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.adrenaline; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.sound.Sound; import net.minestom.server.coordinate.Pos; import net.minestom.server.entity.Player; @@ -40,7 +42,7 @@ *

* * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 2.16.0 */ public final class AdrenalineService implements GameFeature { @@ -62,7 +64,7 @@ public final class AdrenalineService implements GameFeature { private final AdrenalineConfig config; private final Supplier> survivors; private final LongSupplier clock; - private final RepeatingTask task = new RepeatingTask(this::tick); + private final RepeatingTask task; private final Set rushing = new HashSet<>(); private @Nullable Player visibleSlender; @@ -74,6 +76,21 @@ public final class AdrenalineService implements GameFeature { * @param clock supplies the current time in milliseconds */ public AdrenalineService(AdrenalineConfig config, Supplier> survivors, LongSupplier clock) { + this(config, survivors, clock, TickSections.NONE); + } + + /** + * Creates the service with its tick measured for the slow tick report. + * + * @param config the radius, the bonus, the duration and the cooldown + * @param survivors supplies the survivors of the round + * @param clock supplies the current time in milliseconds + * @param sections measures how long each run takes + * @since 2.15.0 + */ + public AdrenalineService(AdrenalineConfig config, Supplier> survivors, LongSupplier clock, + TickSections sections) { + this.task = new RepeatingTask(sections.wrap(TickSectionNames.ADRENALINE, this::tick)); this.config = config; this.survivors = survivors; this.clock = clock; diff --git a/game/src/main/java/net/onelitefeather/cygnus/ambient/AmbientProvider.java b/game/src/main/java/net/onelitefeather/cygnus/ambient/AmbientProvider.java index 1eefe1eb..200a2313 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/ambient/AmbientProvider.java +++ b/game/src/main/java/net/onelitefeather/cygnus/ambient/AmbientProvider.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.ambient; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.theevilreaper.xerus.api.team.Team; import net.kyori.adventure.sound.Sound; import net.minestom.server.entity.Player; @@ -37,7 +39,7 @@ * } * * @author theEvilReaper - * @version 3.0.0 + * @version 3.1.0 * @since 1.0.0 */ public final class AmbientProvider { @@ -57,7 +59,7 @@ public final class AmbientProvider { private final Team team; private final BlackoutObserver observer; - private final RepeatingTask task = new RepeatingTask(this::tick); + private final RepeatingTask task; private final RandomGenerator random; private int ticksSinceLastBlackout; private int nextBlackoutIn; @@ -81,6 +83,18 @@ public AmbientProvider(Team team, BlackoutObserver observer) { this(team, ThreadLocalRandom.current(), observer); } + /** + * Creates the provider with its tick measured for the slow tick report. + * + * @param team the team the lights go out for + * @param observer hears about every blackout + * @param sections measures how long each run takes + * @since 2.15.0 + */ + public AmbientProvider(Team team, BlackoutObserver observer, TickSections sections) { + this(team, ThreadLocalRandom.current(), observer, sections); + } + /** * Creates a new instance with an injectable random source, so tests can force a specific * blackout interval instead of depending on {@link ThreadLocalRandom}. @@ -93,6 +107,11 @@ public AmbientProvider(Team team, BlackoutObserver observer) { } AmbientProvider(Team team, RandomGenerator random, BlackoutObserver observer) { + this(team, random, observer, TickSections.NONE); + } + + AmbientProvider(Team team, RandomGenerator random, BlackoutObserver observer, TickSections sections) { + this.task = new RepeatingTask(sections.wrap(TickSectionNames.AMBIENT, this::tick)); this.team = team; this.observer = observer; this.random = random; diff --git a/game/src/main/java/net/onelitefeather/cygnus/blood/BloodSplatterService.java b/game/src/main/java/net/onelitefeather/cygnus/blood/BloodSplatterService.java index 652241bf..dd0f33da 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/blood/BloodSplatterService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/blood/BloodSplatterService.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.blood; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.key.Key; import net.minestom.server.entity.Player; import net.minestom.server.event.Event; @@ -27,7 +29,7 @@ *

* * @author TheMeinerLP - * @version 2.1.1 + * @version 2.2.0 * @since 2.7.0 */ public final class BloodSplatterService implements GameFeature { @@ -58,7 +60,7 @@ public final class BloodSplatterService implements GameFeature { private final PlayerState active = new PlayerState<>(); /** Fades every active splatter forward by one frame. Runs only while someone is bleeding. */ - final RepeatingTask fadeTask = new RepeatingTask(this::tick); + final RepeatingTask fadeTask; /** * Creates a new service. @@ -67,6 +69,19 @@ public final class BloodSplatterService implements GameFeature { * @param variantPicker picks a variant below the given bound */ public BloodSplatterService(ScreenOverlay overlay, IntUnaryOperator variantPicker) { + this(overlay, variantPicker, TickSections.NONE); + } + + /** + * Creates a new service with its fade measured for the slow tick report. + * + * @param overlay the overlay that owns the player's screen + * @param variantPicker picks a variant below the given bound + * @param sections measures how long each fade step takes + * @since 2.15.0 + */ + public BloodSplatterService(ScreenOverlay overlay, IntUnaryOperator variantPicker, TickSections sections) { + this.fadeTask = new RepeatingTask(sections.wrap(TickSectionNames.BLOOD_SPLATTER, this::tick)); this.overlay = overlay; this.variantPicker = variantPicker; this.registerListeners(); diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/Creek.java b/game/src/main/java/net/onelitefeather/cygnus/creek/Creek.java index ff5d8d5a..84e0026f 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/Creek.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/Creek.java @@ -4,6 +4,7 @@ import net.minestom.server.entity.Entity; import net.minestom.server.entity.Player; import net.onelitefeather.cygnus.creek.body.CreekBody; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; import net.onelitefeather.cygnus.creek.state.CreekActions; import net.onelitefeather.cygnus.creek.state.CreekContext; import net.onelitefeather.cygnus.creek.state.CreekState; @@ -31,7 +32,7 @@ *

* * @author theEvilReaper - * @version 1.1.0 + * @version 1.2.0 * @since 2.15.0 */ final class Creek { @@ -51,6 +52,7 @@ final class Creek { private boolean entered; private @Nullable UUID hunting; private volatile @Nullable CreekSight boostedSight; + private @Nullable HuntState huntState; /** * Sets up a creek. @@ -95,11 +97,11 @@ void tick(SurvivorSnapshot survivors, Set ignored, long now) { this.state.enter(ctx); this.entered = true; // A hunt the creek starts in may be over within this very step. - this.syncHunt(); + this.syncHunt(HuntEnd.TIMEOUT); } CreekState next = this.state.tick(ctx); if (next != this.state) this.switchTo(next, ctx); - this.syncHunt(); + this.syncHunt(HuntEnd.TIMEOUT); // Reported after the step, so a stalk that just ended or turned into a hunt is not counted. if (this.state instanceof StalkState stalk) this.round.witness().stalked(stalk.target()); } @@ -116,19 +118,28 @@ void vanishForGood(SurvivorSnapshot survivors, long now) { // The state it had so far is never entered now, and never needs to be. this.entered = true; this.switchTo(VanishState.forever(), ctx); - this.syncHunt(); + this.syncHunt(HuntEnd.SENT_AWAY); } /** * Tells the witness when the survivor this creek hunts changes: a hunt that starts, one that * ends, or a switch to another target. Called after every step, so each hunt is reported once. + * + * @param otherwise how a hunt ended that did not say so itself; the state a hunt leaves behind + * knows whether it was a catch, a timeout or the survivor being gone */ - private void syncHunt() { - UUID now = this.state instanceof HuntState hunt ? hunt.target() : null; + private void syncHunt(HuntEnd otherwise) { + HuntState hunt = this.state instanceof HuntState current ? current : null; + UUID now = hunt == null ? null : hunt.target(); UUID before = this.hunting; if (Objects.equals(now, before)) return; + HuntState ended = this.huntState; this.hunting = now; - if (before != null) this.round.witness().huntEnded(before); + this.huntState = hunt; + if (before != null) { + HuntEnd how = ended != null && ended.end() != null ? ended.end() : otherwise; + this.round.witness().huntEnded(before, how); + } if (now != null) this.round.witness().hunted(now); } @@ -240,7 +251,8 @@ RouteProvider route() { void remove() { UUID before = this.hunting; this.hunting = null; - if (before != null) this.round.witness().huntEnded(before); + this.huntState = null; + if (before != null) this.round.witness().huntEnded(before, HuntEnd.REMOVED); this.body.remove(); } diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/CreekModule.java b/game/src/main/java/net/onelitefeather/cygnus/creek/CreekModule.java index c97c0792..0e68c9a0 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/CreekModule.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/CreekModule.java @@ -101,7 +101,7 @@ public CreekModule(CreekConfig config, TeamService teamService, new CatchLaunch(this.config.catching().launchHeight(), new LandingDamage(this.config.catching().launchDamage())), this.config.catching().swapChance(), random), - new GlowReveal(this.config.catching().betrayalGlowSeconds()), + new GlowReveal(this.config.catching().betrayalGlowSeconds(), sections), () -> TeamHelper.slenderOf(teamService), this.config, random), diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/CreekService.java b/game/src/main/java/net/onelitefeather/cygnus/creek/CreekService.java index b2665349..6c731ad5 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/CreekService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/CreekService.java @@ -1,5 +1,6 @@ package net.onelitefeather.cygnus.creek; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.text.Component; import net.minestom.server.coordinate.Pos; @@ -54,7 +55,7 @@ *

* * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 2.15.0 */ public final class CreekService implements PossessionTarget { @@ -129,7 +130,7 @@ public CreekService(CreekConfig config, Supplier> survivors, BiFunction bodies, DreadSource dread, CreekWitness witness, CatchConsequence consequence, RoundClock clock, RandomGenerator random, CreekDebug debug, TickSections sections) { - this.task = new RepeatingTask(sections.wrap("creek", this::tick)); + this.task = new RepeatingTask(sections.wrap(TickSectionNames.CREEK, this::tick)); this.config = config; this.survivors = survivors; this.instance = instance; diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/consequence/GlowReveal.java b/game/src/main/java/net/onelitefeather/cygnus/creek/consequence/GlowReveal.java index c4865fe4..faddeb33 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/consequence/GlowReveal.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/consequence/GlowReveal.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.creek.consequence; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.key.Key; import net.kyori.adventure.sound.Sound; import net.kyori.adventure.text.Component; @@ -27,7 +29,7 @@ *

* * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 2.15.0 */ public final class GlowReveal implements SlenderReveal { @@ -44,6 +46,7 @@ public final class GlowReveal implements SlenderReveal { private final int durationTicks; private final Set running = ConcurrentHashMap.newKeySet(); + private final TickSections sections; /** * Sets up the reveal. @@ -51,7 +54,19 @@ public final class GlowReveal implements SlenderReveal { * @param seconds how long the glow lasts */ public GlowReveal(int seconds) { + this(seconds, TickSections.NONE); + } + + /** + * Sets up the reveal with its resends measured for the slow tick report. + * + * @param seconds how long the glow lasts + * @param sections measures how long the resends take + * @since 2.15.0 + */ + public GlowReveal(int seconds, TickSections sections) { this.durationTicks = seconds * 20; + this.sections = sections; } @Override @@ -66,7 +81,7 @@ public void reveal(Player survivor, Player slender) { this.running.add(reveal); slender.sendPacket(flagsPacket(survivor, true)); reveal.task = MinecraftServer.getSchedulerManager() - .buildTask(() -> this.step(reveal)) + .buildTask(this.sections.wrap(TickSectionNames.GLOW_REVEAL, () -> this.step(reveal))) .delay(TaskSchedule.tick(RESEND_TICKS)) .repeat(TaskSchedule.tick(RESEND_TICKS)) .schedule(); diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/dread/CreekWitness.java b/game/src/main/java/net/onelitefeather/cygnus/creek/dread/CreekWitness.java index 2339bc5a..81b81c1b 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/dread/CreekWitness.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/dread/CreekWitness.java @@ -90,4 +90,17 @@ default void hunted(UUID survivor) { default void huntEnded(UUID survivor) { // Nobody listens by default. } + + /** + * A creek stopped hunting a survivor, and how. The creek reports this one; by default it passes + * on to {@link #huntEnded(UUID)}, so a witness that does not care about the reason is unchanged. + * A witness that decorates another one has to forward this method, not the other. + * + * @param survivor the survivor who is no longer hunted + * @param how why the hunt ended + * @since 2.15.0 + */ + default void huntEnded(UUID survivor, HuntEnd how) { + this.huntEnded(survivor); + } } diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/dread/HuntEnd.java b/game/src/main/java/net/onelitefeather/cygnus/creek/dread/HuntEnd.java new file mode 100644 index 00000000..48865222 --- /dev/null +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/dread/HuntEnd.java @@ -0,0 +1,22 @@ +package net.onelitefeather.cygnus.creek.dread; + +/** + * How a creek's hunt of a survivor ended, as told to {@link CreekWitness#huntEnded(java.util.UUID, HuntEnd)}. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +public enum HuntEnd { + + /** The creek got close enough with nothing in between. */ + CAUGHT, + /** The hunt ran out of time. */ + TIMEOUT, + /** The survivor was no longer among the hunted, because they died, left or were turned. */ + GONE, + /** The creek was sent away for good while it hunted. */ + SENT_AWAY, + /** The creek was taken out of the world, which is what the end of a round does. */ + REMOVED +} diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/state/HuntState.java b/game/src/main/java/net/onelitefeather/cygnus/creek/state/HuntState.java index 40f336e3..99eef817 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/state/HuntState.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/state/HuntState.java @@ -2,6 +2,8 @@ import net.onelitefeather.cygnus.common.config.CreekConfig; import net.onelitefeather.cygnus.creek.body.CreekBody; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; +import org.jetbrains.annotations.Nullable; import java.util.List; import java.util.Optional; @@ -17,7 +19,7 @@ *

* * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 2.15.0 */ public final class HuntState implements CreekState { @@ -35,6 +37,7 @@ public final class HuntState implements CreekState { private final long endsAt; private double bestDistance = Double.MAX_VALUE; private long progressSince; + private @Nullable HuntEnd end; /** * Sets up the hunt. @@ -76,6 +79,16 @@ public long endsAt() { return this.endsAt; } + /** + * Tells how the hunt ended. + * + * @return the reason, or {@code null} while the hunt goes on or when it was cut short from outside + * @since 2.15.0 + */ + public @Nullable HuntEnd end() { + return this.end; + } + @Override public void enter(CreekContext ctx) { CreekBody body = ctx.body(); @@ -88,7 +101,8 @@ public void enter(CreekContext ctx) { @Override public CreekState tick(CreekContext ctx) { Optional found = ctx.survivor(this.target); - if (found.isEmpty() || ctx.now() >= this.endsAt) return this.over(ctx); + if (found.isEmpty()) return this.over(ctx, HuntEnd.GONE); + if (ctx.now() >= this.endsAt) return this.over(ctx, HuntEnd.TIMEOUT); SurvivorView view = found.get(); CreekConfig config = ctx.config(); @@ -105,7 +119,7 @@ public CreekState tick(CreekContext ctx) { double distance = body.position().distance(view.position()); if (distance <= config.hunt().catchDistance() && view.inSight()) { ctx.actions().caught(this.target); - return this.over(ctx); + return this.over(ctx, HuntEnd.CAUGHT); } if (distance < this.bestDistance - PROGRESS) { @@ -124,7 +138,8 @@ public CreekState tick(CreekContext ctx) { /** * Ends the hunt and starts the survivor's breather. */ - private CreekState over(CreekContext ctx) { + private CreekState over(CreekContext ctx, HuntEnd how) { + this.end = how; ctx.hunts().ended(this.target, ctx.now()); return DoneState.INSTANCE; } diff --git a/game/src/main/java/net/onelitefeather/cygnus/creek/tab/HuntedTabWitness.java b/game/src/main/java/net/onelitefeather/cygnus/creek/tab/HuntedTabWitness.java index 6b7d67b1..a86e72b6 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/creek/tab/HuntedTabWitness.java +++ b/game/src/main/java/net/onelitefeather/cygnus/creek/tab/HuntedTabWitness.java @@ -4,6 +4,7 @@ import net.kyori.adventure.text.format.NamedTextColor; import net.minestom.server.entity.Player; import net.onelitefeather.cygnus.creek.dread.CreekWitness; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; import org.jetbrains.annotations.Nullable; import java.util.List; @@ -31,7 +32,7 @@ *

* * @author TheMeinerLP - * @version 1.1.0 + * @version 1.2.0 * @since 2.15.0 */ public final class HuntedTabWitness implements CreekWitness { @@ -92,9 +93,19 @@ public void hunted(UUID survivor) { }); } + @Override + public void huntEnded(UUID survivor, HuntEnd how) { + this.delegate.huntEnded(survivor, how); + this.unmark(survivor); + } + @Override public void huntEnded(UUID survivor) { this.delegate.huntEnded(survivor); + this.unmark(survivor); + } + + private void unmark(UUID survivor) { this.marks.computeIfPresent(survivor, (_, mark) -> { if (mark.hunts() > 1) return mark.fewer(); Player player = this.players.apply(survivor); diff --git a/game/src/main/java/net/onelitefeather/cygnus/gaze/SlenderGazeService.java b/game/src/main/java/net/onelitefeather/cygnus/gaze/SlenderGazeService.java index 9d70ba25..13208486 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/gaze/SlenderGazeService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/gaze/SlenderGazeService.java @@ -1,5 +1,6 @@ package net.onelitefeather.cygnus.gaze; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.entity.Player; import net.minestom.server.event.Event; @@ -34,7 +35,7 @@ *

* * @author TheMeinerLP - * @version 3.1.0 + * @version 3.2.0 * @since 2.7.0 */ public final class SlenderGazeService implements GameFeature { @@ -80,7 +81,7 @@ public SlenderGazeService(GazeSink sink, SlenderGaze gaze, Supplier<@Nullable Pl */ public SlenderGazeService(GazeSink sink, SlenderGaze gaze, Supplier<@Nullable Player> slender, Supplier> survivors, TickSections sections) { - this.task = new RepeatingTask(sections.wrap("slender-gaze", this::tick)); + this.task = new RepeatingTask(sections.wrap(TickSectionNames.SLENDER_GAZE, this::tick)); this.sink = sink; this.gaze = gaze; this.slender = slender; diff --git a/game/src/main/java/net/onelitefeather/cygnus/glitch/PageGlitchService.java b/game/src/main/java/net/onelitefeather/cygnus/glitch/PageGlitchService.java index 2ccf8dd6..8638aaf1 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/glitch/PageGlitchService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/glitch/PageGlitchService.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.glitch; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.entity.Player; import net.minestom.server.event.Event; import net.minestom.server.event.EventNode; @@ -57,7 +59,7 @@ * } * * @author TheMeinerLP - * @version 1.1.0 + * @version 1.2.0 * @since 2.15.0 */ public final class PageGlitchService implements GameFeature { @@ -71,7 +73,7 @@ public final class PageGlitchService implements GameFeature { private final GazeSink sink; private final Supplier<@Nullable Player> slender; private final Predicate invisible; - private final RepeatingTask task = new RepeatingTask(this::tick); + private final RepeatingTask task; /** How far the round has got, between {@code 0} and {@code 1}. */ private float progress; @@ -109,6 +111,23 @@ public final class PageGlitchService implements GameFeature { */ public PageGlitchService(GameConfig.PageGlitch config, GazeSink sink, Supplier<@Nullable Player> slender, Predicate invisible) { + this(config, sink, slender, invisible, TickSections.NONE); + } + + /** + * Creates a new instance of the {@link PageGlitchService} with its tick measured for the slow + * tick report. + * + * @param config the configuration holding the switch, the pulse and the cap + * @param sink where the level is signalled to + * @param slender supplies the current slender, or {@code null} while there is none + * @param invisible tells whether the given slender is invisible right now + * @param sections measures how long each run takes + * @since 2.15.0 + */ + public PageGlitchService(GameConfig.PageGlitch config, GazeSink sink, Supplier<@Nullable Player> slender, + Predicate invisible, TickSections sections) { + this.task = new RepeatingTask(sections.wrap(TickSectionNames.PAGE_GLITCH, this::tick)); this.config = config; this.sink = sink; this.slender = slender; diff --git a/game/src/main/java/net/onelitefeather/cygnus/jumpscare/JumpScareManager.java b/game/src/main/java/net/onelitefeather/cygnus/jumpscare/JumpScareManager.java index e4e784de..4d16f572 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/jumpscare/JumpScareManager.java +++ b/game/src/main/java/net/onelitefeather/cygnus/jumpscare/JumpScareManager.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.jumpscare; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.key.Key; import net.kyori.adventure.sound.Sound; import net.minestom.server.MinecraftServer; @@ -33,7 +35,7 @@ * Manages dead player mannequins and turnaround scare for surviving players. * * @author theEvilReaper - * @version 1.1.0 + * @version 1.2.0 * @since 2.7.0 */ public final class JumpScareManager { @@ -50,11 +52,23 @@ public final class JumpScareManager { private final Map playerLastYaws; private final Map> corpseHiddenFromViewers; private final Random random; + private final TickSections sections; /** * Creates a new instance of the service. */ public JumpScareManager() { + this(TickSections.NONE); + } + + /** + * Creates a new instance of the service with its delayed despawn measured for the slow tick report. + * + * @param sections measures how long the despawn of a jump scare takes + * @since 2.15.0 + */ + public JumpScareManager(TickSections sections) { + this.sections = sections; this.activeMannequins = new CopyOnWriteArrayList<>(); this.jumpScareCooldowns = new ConcurrentHashMap<>(); this.playerLastYaws = new ConcurrentHashMap<>(); @@ -182,7 +196,7 @@ private boolean execute(Player player) { )); // Schedule smooth despawn transition after 2.5 seconds (50 ticks) - MinecraftServer.getSchedulerManager().buildTask(() -> { + MinecraftServer.getSchedulerManager().buildTask(this.sections.wrap(TickSectionNames.JUMP_SCARE, () -> { if (player.isOnline()) { // Smoke & Poof particle burst covering full body height player.sendPacket(new ParticlePacket( @@ -205,7 +219,7 @@ private boolean execute(Player player) { player.sendPacket(new DestroyEntitiesPacket(phantomEntityId)); } restoreCorpseVisibility(sampleCorpse, player); - }).delay(TaskSchedule.tick(50)).schedule(); + })).delay(TaskSchedule.tick(50)).schedule(); return true; } diff --git a/game/src/main/java/net/onelitefeather/cygnus/listener/game/SlenderTakeover.java b/game/src/main/java/net/onelitefeather/cygnus/listener/game/SlenderTakeover.java index 87f152cf..c6462aaf 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/listener/game/SlenderTakeover.java +++ b/game/src/main/java/net/onelitefeather/cygnus/listener/game/SlenderTakeover.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.listener.game; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.key.Key; import net.kyori.adventure.sound.Sound; import net.kyori.adventure.text.Component; @@ -48,7 +50,7 @@ *

* * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 2.16.0 */ public final class SlenderTakeover implements GameFeature { @@ -81,7 +83,7 @@ public final class SlenderTakeover implements GameFeature { private final TeamService teamService; private final Supplier phaseSupplier; - private final RepeatingTask task = new RepeatingTask(this::tick); + private final RepeatingTask task; private int takeovers; private @Nullable Player chosen; private int secondsLeft; @@ -93,6 +95,19 @@ public final class SlenderTakeover implements GameFeature { * @param phaseSupplier supplies the current phase, a takeover only runs during the {@link GamePhase} */ public SlenderTakeover(TeamService teamService, Supplier phaseSupplier) { + this(teamService, phaseSupplier, TickSections.NONE); + } + + /** + * Creates the takeover with its countdown measured for the slow tick report. + * + * @param teamService the teams of the round + * @param phaseSupplier supplies the current phase, a takeover only runs during the {@link GamePhase} + * @param sections measures how long each run takes + * @since 2.15.0 + */ + public SlenderTakeover(TeamService teamService, Supplier phaseSupplier, TickSections sections) { + this.task = new RepeatingTask(sections.wrap(TickSectionNames.SLENDER_TAKEOVER, this::tick)); this.teamService = teamService; this.phaseSupplier = phaseSupplier; this.registerListeners(); diff --git a/game/src/main/java/net/onelitefeather/cygnus/overlay/OverlayModule.java b/game/src/main/java/net/onelitefeather/cygnus/overlay/OverlayModule.java index 7eb5239b..d67e108a 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/overlay/OverlayModule.java +++ b/game/src/main/java/net/onelitefeather/cygnus/overlay/OverlayModule.java @@ -83,10 +83,12 @@ public OverlayModule(GameConfig.Glitch glitch, GameConfig.PageGlitch pageGlitch, pageGlitch, this.gazeSignal, () -> TeamHelper.slenderOf(teamService), - VisibilityRules::isHidden); + VisibilityRules::isHidden, + sections); this.bloodSplatterService = new BloodSplatterService( screenOverlay, - bound -> ThreadLocalRandom.current().nextInt(bound) + bound -> ThreadLocalRandom.current().nextInt(bound), + sections ); this.tunnelVisionService = new TunnelVisionService( new OverlayTunnelVisionRenderer(screenOverlay), diff --git a/game/src/main/java/net/onelitefeather/cygnus/page/PageProximityService.java b/game/src/main/java/net/onelitefeather/cygnus/page/PageProximityService.java index 4dbdf674..cb27b4e3 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/page/PageProximityService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/page/PageProximityService.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.page; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.key.Key; import net.kyori.adventure.sound.Sound; import net.minestom.server.coordinate.Pos; @@ -32,7 +34,7 @@ * * @author TheMeinerLP * @author theEvilReaper - * @version 1.2.0 + * @version 1.3.0 * @since 2.12.0 */ public final class PageProximityService { @@ -56,7 +58,7 @@ public final class PageProximityService { public static final int SERVICE_TICK_RATE = 5; - private final RepeatingTask task = new RepeatingTask(this::tick); + private final RepeatingTask task; private final GameConfig.PageProximity config; private final Supplier> listeners; private final Supplier> pageSupplier; @@ -78,6 +80,25 @@ public PageProximityService( Supplier> listeners, Supplier> pageSupplier ) { + this(config, listeners, pageSupplier, TickSections.NONE); + } + + /** + * Creates the service with its tick measured for the slow tick report. + * + * @param config the configuration holding range and sound + * @param listeners supplies the players the hint is played to + * @param pageSupplier supplies the proximity page targets that can currently be collected + * @param sections measures how long each run takes + * @since 2.15.0 + */ + public PageProximityService( + GameConfig.PageProximity config, + Supplier> listeners, + Supplier> pageSupplier, + TickSections sections + ) { + this.task = new RepeatingTask(sections.wrap(TickSectionNames.PAGE_PROXIMITY, this::tick)); this.config = config; this.listeners = listeners; this.pageSupplier = pageSupplier; diff --git a/game/src/main/java/net/onelitefeather/cygnus/phase/LobbyPhase.java b/game/src/main/java/net/onelitefeather/cygnus/phase/LobbyPhase.java index 28cad718..0e66311d 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/phase/LobbyPhase.java +++ b/game/src/main/java/net/onelitefeather/cygnus/phase/LobbyPhase.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.phase; +import net.onelitefeather.cygnus.common.util.Helper; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.MinecraftServer; import net.minestom.server.entity.Player; import net.minestom.server.event.EventDispatcher; @@ -29,7 +31,7 @@ *

* * @author theEvilReaper - * @version 1.4.0 + * @version 1.5.0 * @since 1.0.0 */ public final class LobbyPhase extends TimedPhase { @@ -59,6 +61,18 @@ public LobbyPhase(GameConfig.Round round) { * @param instanceSupplier supplier for the active instance */ public LobbyPhase(GameConfig.Round round, Supplier instanceSupplier) { + this(round, instanceSupplier, TickSections.NONE); + } + + /** + * Constructs a new LobbyPhase whose per-tick tasks are measured for the slow tick report. + * + * @param round the configured player limits and timings + * @param instanceSupplier supplier for the active instance + * @param sections measures how long the waiting display and the time transition take + * @since 2.15.0 + */ + public LobbyPhase(GameConfig.Round round, Supplier instanceSupplier, TickSections sections) { super("Lobby", ChronoUnit.SECONDS, 1); this.lobbyTime = round.lobbyTime(); this.minPlayers = round.minPlayers(); @@ -67,9 +81,9 @@ public LobbyPhase(GameConfig.Round round, Supplier instanceSupplier) { this.setTickDirection(TickDirection.DOWN); // Instantiate the waiting display and time transition task - this.waitingDisplay = new LobbyWaitingTask(this.minPlayers); + this.waitingDisplay = new LobbyWaitingTask(this.minPlayers, sections); this.waitingDisplay.update(MinecraftServer.getConnectionManager().getOnlinePlayers().size()); - this.timeTransitionTask = new LobbyTimeTransitionTask(instanceSupplier, TIME_TRANSITION_START_SECONDS); + this.timeTransitionTask = new LobbyTimeTransitionTask(instanceSupplier, Helper.MIDNIGHT_TIME, TIME_TRANSITION_START_SECONDS, sections); this.countdownSoundTask = new LobbyCountdownSoundTask(); } diff --git a/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyTimeTransitionTask.java b/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyTimeTransitionTask.java index 56e60703..6b8ace07 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyTimeTransitionTask.java +++ b/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyTimeTransitionTask.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.phase.task; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.MinecraftServer; import net.minestom.server.instance.Instance; import net.onelitefeather.cygnus.common.util.Helper; @@ -11,7 +13,7 @@ * over a specified duration in seconds using tick-aligned linear interpolation. * * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 2.7.0 */ public final class LobbyTimeTransitionTask { @@ -46,10 +48,27 @@ public LobbyTimeTransitionTask(Supplier instanceSupplier, int duration * @param durationSeconds duration of the transition in seconds */ public LobbyTimeTransitionTask(Supplier instanceSupplier, long targetTime, int durationSeconds) { + this(instanceSupplier, targetTime, durationSeconds, TickSections.NONE); + } + + /** + * Creates a new instance of {@link LobbyTimeTransitionTask} with its ticks measured for the slow + * tick report. + * + * @param instanceSupplier supplier for the target instance + * @param targetTime the target world time in ticks + * @param durationSeconds duration of the transition in seconds + * @param sections measures how long each tick of the transition takes + * @since 2.15.0 + */ + public LobbyTimeTransitionTask(Supplier instanceSupplier, long targetTime, int durationSeconds, + TickSections sections) { this.instanceSupplier = instanceSupplier; this.targetTime = targetTime; this.totalTicks = Math.max(1, durationSeconds * TICKS_PER_SECOND); + Runnable step = sections.wrap(TickSectionNames.LOBBY_TIME, this::advanceTime); + this.tickRunnable = new Runnable() { @Override public void run() { @@ -57,17 +76,7 @@ public void run() { return; } - Instance instance = instanceSupplier.get(); - - if (!initialized) { - initialTime = instance.getTime(); - initialized = true; - } - - currentTick++; - double progress = Math.min(1.0, (double) currentTick / totalTicks); - long calculatedTime = (long) (initialTime + (progress * (targetTime - initialTime))); - instance.setTime(calculatedTime); + step.run(); if (currentTick < totalTicks && running) { MinecraftServer.getSchedulerManager().scheduleNextTick(this); @@ -78,6 +87,23 @@ public void run() { }; } + /** + * Moves the world time one tick closer to the target. + */ + private void advanceTime() { + Instance instance = this.instanceSupplier.get(); + + if (!this.initialized) { + this.initialTime = instance.getTime(); + this.initialized = true; + } + + this.currentTick++; + double progress = Math.min(1.0, (double) this.currentTick / this.totalTicks); + long calculatedTime = (long) (this.initialTime + (progress * (this.targetTime - this.initialTime))); + instance.setTime(calculatedTime); + } + /** * Starts the smooth time transition if not already running. */ diff --git a/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyWaitingTask.java b/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyWaitingTask.java index ad9945c7..5e1e72c2 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyWaitingTask.java +++ b/game/src/main/java/net/onelitefeather/cygnus/phase/task/LobbyWaitingTask.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.phase.task; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.kyori.adventure.text.Component; import net.kyori.adventure.text.format.NamedTextColor; import net.minestom.server.MinecraftServer; @@ -16,7 +18,7 @@ *

* * @author theEvilReaper - * @version 1.3.0 + * @version 1.4.0 * @since 1.0.0 **/ public final class LobbyWaitingTask { @@ -40,6 +42,17 @@ public final class LobbyWaitingTask { * @param minPlayers the minimum number of players required to start the game */ public LobbyWaitingTask(int minPlayers) { + this(minPlayers, TickSections.NONE); + } + + /** + * Creates a new instance of the waiting display with its ticks measured for the slow tick report. + * + * @param minPlayers the minimum number of players required to start the game + * @param sections measures how long each tick of the display takes + * @since 2.15.0 + */ + public LobbyWaitingTask(int minPlayers, TickSections sections) { this.minPlayers = minPlayers; this.cachedComponents = new Component[minPlayers + 1]; @@ -52,6 +65,8 @@ public LobbyWaitingTask(int minPlayers) { .append(SUFFIX_TO_START); } + Runnable step = sections.wrap(TickSectionNames.LOBBY_WAITING, this::refreshDisplay); + // Define the self-scheduling tick task this.tickRunnable = new Runnable() { @Override @@ -60,10 +75,7 @@ public void run() { return; // Gracefully exit the loop when stopped } - // Send the action bar only at the specified tick interval - if (tickCounter++ % DISPLAY_REFRESH_INTERVAL_TICKS == 0) { - sendToAll(MinecraftServer.getConnectionManager().getOnlinePlayers()); - } + step.run(); // Schedule this task again for the next server tick MinecraftServer.getSchedulerManager().scheduleNextTick(this); @@ -74,6 +86,15 @@ public void run() { this.start(); } + /** + * Sends the action bar, but only at the specified tick interval. + */ + private void refreshDisplay() { + if (this.tickCounter++ % DISPLAY_REFRESH_INTERVAL_TICKS == 0) { + sendToAll(MinecraftServer.getConnectionManager().getOnlinePlayers()); + } + } + /** * Starts the tick-aligned display loop if it is not already running. */ diff --git a/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaBar.java b/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaBar.java index 7413aaa0..3786523f 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaBar.java +++ b/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaBar.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.stamina; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.MinecraftServer; import net.minestom.server.timer.ExecutionType; import net.minestom.server.timer.Task; @@ -15,7 +17,7 @@ * The core functionality of the class revolves around a timer that ticks at regular intervals defined by the provided period parameter. * * @author theEvilReaper - * @version 1.0.0 + * @version 1.1.0 * @since 1.0.0 **/ public abstract sealed class StaminaBar implements Runnable permits SlenderBar, FoodBar { @@ -26,6 +28,23 @@ public abstract sealed class StaminaBar implements Runnable permits SlenderBar, protected int period; protected State state; private @Nullable Task task; + private TickSections sections = TickSections.NONE; + private String sectionName = TickSectionNames.STAMINA; + + /** + * Has the periodic {@link #consume()} measured for the slow tick report. Takes effect the next + * time the bar is started. + * + * @param sections the sections to count the time in + * @param name the name the time is reported under + * @return this bar + * @since 2.15.0 + */ + public StaminaBar measuredBy(TickSections sections, String name) { + this.sections = sections; + this.sectionName = name; + return this; + } /** * Creates a new reference from an {@link StaminaBar}. @@ -51,7 +70,7 @@ public void start() { if (task != null) return; this.onStart(); task = MinecraftServer.getSchedulerManager() - .buildTask(this::consume) + .buildTask(this.sections.wrap(this.sectionName, this::consume)) .executionType(executionType) .repeat(this.period, this.chronoUnit).schedule(); } diff --git a/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaService.java b/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaService.java index a70f8cf9..91008390 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/stamina/StaminaService.java @@ -1,5 +1,7 @@ package net.onelitefeather.cygnus.stamina; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; +import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.entity.Player; import net.minestom.server.utils.validate.Check; import net.onelitefeather.cygnus.common.config.StaminaConfig; @@ -15,12 +17,13 @@ * The class has some abilities to manage all {@link StaminaBar} references which are required in the game. * * @author theEvilReaper - * @version 1.1.0 + * @version 1.2.0 * @since 1.0.0 */ public final class StaminaService { private final StaminaConfig config; + private final TickSections sections; private final Map staminaBars; private @Nullable StaminaBar slenderBar; @@ -37,7 +40,19 @@ public StaminaService() { * @param config the settings every bar is created with */ public StaminaService(StaminaConfig config) { + this(config, TickSections.NONE); + } + + /** + * Creates a new instance from this class with its bars measured for the slow tick report. + * + * @param config the settings every bar is created with + * @param sections measures how long the bars take, the survivors' together and the slender's apart + * @since 2.15.0 + */ + public StaminaService(StaminaConfig config, TickSections sections) { this.config = config; + this.sections = sections; this.staminaBars = new HashMap<>(); } @@ -61,7 +76,8 @@ public void setSlenderBar(Player player, boolean forceStart) { this.slenderBar.stop(); } - this.slenderBar = StaminaFactory.createSlenderStamina((CygnusPlayer) player, this.config, System::currentTimeMillis); + this.slenderBar = StaminaFactory.createSlenderStamina((CygnusPlayer) player, this.config, System::currentTimeMillis) + .measuredBy(this.sections, TickSectionNames.SLENDER_BAR); if (!forceStart) return; this.slenderBar.start(); } @@ -75,7 +91,8 @@ public void createStaminaBars(Set team) { Check.argCondition(!staminaBars.isEmpty(), "Unable to load stamina bars twice"); Check.argCondition(team.isEmpty(), "Can't add players from a team without teams"); for (Player player : team) { - this.staminaBars.put(player.getUuid(), StaminaFactory.createFoodStamina((CygnusPlayer) player, this.config)); + this.staminaBars.put(player.getUuid(), StaminaFactory.createFoodStamina((CygnusPlayer) player, this.config) + .measuredBy(this.sections, TickSectionNames.STAMINA)); } } diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/ActionTracer.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/ActionTracer.java index 5c0f9d00..66e0d6cd 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/telemetry/ActionTracer.java +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/ActionTracer.java @@ -49,7 +49,7 @@ *

* * @author TheMeinerLP - * @version 1.0.0 + * @version 1.1.0 * @since 2.15.0 */ public final class ActionTracer { @@ -439,7 +439,7 @@ private long outMillis(Spawn spawn) { return Duration.between(spawn.at, this.clock.instant()).toMillis(); } - private static void position(TraceStep step, double x, double y, double z) { + static void position(TraceStep step, double x, double y, double z) { step.set(CygnusAttributes.POSITION_X, round(x)); step.set(CygnusAttributes.POSITION_Y, round(y)); step.set(CygnusAttributes.POSITION_Z, round(z)); diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/CygnusAttributes.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/CygnusAttributes.java index d1225bc1..910da2b0 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/telemetry/CygnusAttributes.java +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/CygnusAttributes.java @@ -11,7 +11,7 @@ *

* * @author TheMeinerLP - * @version 1.0.0 + * @version 1.1.0 * @since 2.15.0 */ public final class CygnusAttributes { @@ -58,6 +58,8 @@ public final class CygnusAttributes { public static final String ACTION_CREEK_SELECTED = "cygnus.action.creek.selected"; public static final String ACTION_CREEK_STALK = "cygnus.action.creek.stalk"; public static final String ACTION_CREEK_CAUGHT = "cygnus.action.creek.caught"; + /** A creek hunting a survivor, from the start of the hunt to its end. */ + public static final String ACTION_CREEK_HUNT = "cygnus.action.creek.hunt"; // --- Events on the round span -------------------------------------------------------------- @@ -115,6 +117,8 @@ public final class CygnusAttributes { public static final AttributeKey SANITY_BAND = AttributeKey.stringKey("cygnus.sanity.band"); public static final AttributeKey SANITY_BAND_FROM = AttributeKey.stringKey("cygnus.sanity.band.from"); public static final AttributeKey SANITY_SOURCE = AttributeKey.stringKey("cygnus.sanity.source"); + public static final AttributeKey HUNT_OUTCOME = AttributeKey.stringKey("cygnus.creek.hunt.outcome"); + public static final AttributeKey HUNT_DURATION_MS = AttributeKey.longKey("cygnus.creek.hunt.duration_ms"); public static final AttributeKey LINK_KIND = AttributeKey.stringKey("cygnus.link.kind"); /** The link points at the round trace a player's cookie remembered. */ @@ -126,6 +130,19 @@ public final class CygnusAttributes { /** Link kind: from the shutdown to the round it cut short. */ public static final String LINK_ROUND = "round"; + // --- Values of creek.hunt.outcome ---------------------------------------------------------- + + /** The creek caught the survivor. */ + public static final String HUNT_CAUGHT = "caught"; + /** The creek was sent away while it hunted. */ + public static final String HUNT_ESCAPED = "escaped"; + /** The hunt ran out of time. */ + public static final String HUNT_TIMEOUT = "timeout"; + /** The survivor died or left. */ + public static final String HUNT_GONE = "gone"; + /** The round ended with the hunt still going. */ + public static final String HUNT_ROUND_END = "round_end"; + // --- Values of kick.completed_by ----------------------------------------------------------- /** The client confirmed it dropped the pack. */ diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/HuntMetrics.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/HuntMetrics.java new file mode 100644 index 00000000..eb2cd505 --- /dev/null +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/HuntMetrics.java @@ -0,0 +1,125 @@ +package net.onelitefeather.cygnus.telemetry; + +import io.opentelemetry.api.GlobalOpenTelemetry; +import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.api.metrics.DoubleHistogram; +import io.opentelemetry.api.metrics.LongCounter; +import io.opentelemetry.api.metrics.Meter; +import org.jetbrains.annotations.Nullable; + +import java.util.List; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; + +/** + * The metrics of the creek's hunts: how many there were and how long they lasted, by how they ended. + *

+ * The attributes are the outcome and the map only. A player is deliberately not one: the UUID is the + * span's job, on a metric it would make a series per player. The unit is milliseconds, like the tick + * metrics in {@link TickMetrics}. + *

+ * + * + * + * + * + * + * + *
The instruments
NameKindUnitAttributes
{@value #HUNT_DURATION}histogramms{@code cygnus.creek.hunt.outcome}, {@code cygnus.map}
{@value #HUNTS}counter{hunt}{@code cygnus.creek.hunt.outcome}, {@code cygnus.map}
+ * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +public final class HuntMetrics { + + /** Histogram of how long a hunt lasted. */ + public static final String HUNT_DURATION = "cygnus.creek.hunt.duration"; + /** Counter of the hunts that ended. */ + public static final String HUNTS = "cygnus.creek.hunts"; + + /** The value of the map attribute while no map is loaded. */ + public static final String NO_MAP = "none"; + + /** Boundaries in milliseconds: a hunt lasts from a few seconds up to its configured maximum. */ + public static final List BUCKETS_MS = List.of( + 500.0D, 1_000.0D, 2_500.0D, 5_000.0D, 7_500.0D, 10_000.0D, 15_000.0D, 20_000.0D, 30_000.0D, 45_000.0D, + 60_000.0D, 90_000.0D, 120_000.0D); + + /** Metrics that record nothing. */ + public static final HuntMetrics NONE = new HuntMetrics(null); + + private final @Nullable DoubleHistogram duration; + private final @Nullable LongCounter hunts; + private final Map> attributes = new ConcurrentHashMap<>(); + + private HuntMetrics(@Nullable Meter meter) { + if (meter == null) { + this.duration = null; + this.hunts = null; + return; + } + this.duration = meter.histogramBuilder(HUNT_DURATION) + .setDescription("How long a creek hunted a survivor, by how the hunt ended") + .setUnit("ms") + .setExplicitBucketBoundariesAdvice(BUCKETS_MS) + .build(); + this.hunts = meter.counterBuilder(HUNTS) + .setDescription("Hunts that ended, by how they ended") + .setUnit("{hunt}") + .build(); + } + + /** + * Builds the metrics from the global OpenTelemetry instance. Called once, by the composition root. + * + * @param version the version of the running service, reported with the instrumentation scope + * @return the metrics + */ + public static HuntMetrics fromGlobal(String version) { + return of(GlobalOpenTelemetry.get().getMeterProvider() + .meterBuilder(CygnusAttributes.INSTRUMENTATION_NAME) + .setInstrumentationVersion(version) + .build()); + } + + /** + * Wraps a meter, for tests and for callers that already hold one. + * + * @param meter the meter the instruments are created on + * @return the metrics + */ + public static HuntMetrics of(Meter meter) { + return new HuntMetrics(meter); + } + + /** + * Records a hunt that ended. + * + * @param outcome how it ended, one of the {@code HUNT_*} values of {@link CygnusAttributes} + * @param map the map being played, or {@code null} when none is loaded + * @param millis how long it lasted + */ + void record(String outcome, @Nullable String map, long millis) { + if (this.duration == null || this.hunts == null) { + return; + } + Attributes cached = attributes(outcome, map == null ? NO_MAP : map); + this.duration.record(millis, cached); + this.hunts.add(1L, cached); + } + + /** + * Returns the attributes of an outcome on a map. The same instance for the same pair, every time. + */ + Attributes attributes(String outcome, String map) { + Map byMap = this.attributes.computeIfAbsent(outcome, _ -> new ConcurrentHashMap<>()); + Attributes cached = byMap.get(map); + if (cached != null) { + return cached; + } + return byMap.computeIfAbsent(map, name -> Attributes.of( + CygnusAttributes.HUNT_OUTCOME, outcome, + CygnusAttributes.MAP, name)); + } +} diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/HuntTracer.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/HuntTracer.java new file mode 100644 index 00000000..5b66689c --- /dev/null +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/HuntTracer.java @@ -0,0 +1,158 @@ +package net.onelitefeather.cygnus.telemetry; + +import net.onelitefeather.cygnus.creek.dread.HuntEnd; +import org.jetbrains.annotations.Nullable; + +import java.time.Clock; +import java.util.ArrayDeque; +import java.util.ArrayList; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.UUID; +import java.util.function.Function; +import java.util.function.Supplier; + +/** + * Measures how long a survivor is hunted: one span per hunt from its start to its end, and the + * duration as a metric. + *

+ * The creek reports a hunt by the survivor only, not by itself, so two creeks hunting the same + * survivor cannot be told apart here. Each start opens its own span and each end closes the + * oldest open one of that survivor - the count stays right, which creek a span belongs to + * may not. + *

+ *

+ * The outcome comes from {@link HuntEnd}: a catch is {@code caught}, a hunt out of time + * {@code timeout}, a survivor who left or died {@code gone}, a creek sent away {@code escaped}, and + * the end of the round {@code round_end}. Hunts still open when the round ends are closed as + * {@code round_end} before the round span ends. A start while no round runs has no span but is still + * counted, so the metric does not depend on tracing being on. + *

+ * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +public final class HuntTracer { + + private final RoundTracer rounds; + private final Clock clock; + private final Supplier<@Nullable String> mapName; + private final Function survivors; + private final HuntMetrics metrics; + private final Map> open = new HashMap<>(); + + /** + * Creates the tracer. + * + * @param rounds owns the round the spans are children of + * @param clock dates the start and the end of a hunt + * @param mapName supplies the name of the map being played, or {@code null} while none is loaded + * @param survivors resolves a survivor's UUID to who and where they are, or {@code null} if gone + * @param metrics where the duration of a hunt goes + */ + public HuntTracer(RoundTracer rounds, Clock clock, Supplier<@Nullable String> mapName, + Function survivors, HuntMetrics metrics) { + this.rounds = rounds; + this.clock = clock; + this.mapName = mapName; + this.survivors = survivors; + this.metrics = metrics; + rounds.onRoundEnding(this::endAll); + } + + /** + * A creek started to hunt a survivor. + * + * @param survivor the survivor + */ + public synchronized void started(UUID survivor) { + long now = this.clock.millis(); + String map = this.mapName.get(); + TraceStep step = null; + try { + step = this.rounds.actionSpan(CygnusAttributes.ACTION_CREEK_HUNT); + if (step != null) { + ActionTracer.Actor actor = this.survivors.apply(survivor); + step.set(CygnusAttributes.PLAYER_UUID, survivor.toString()); + if (actor != null) { + step.set(CygnusAttributes.PLAYER_ROLE, actor.role()); + ActionTracer.position(step, actor.x(), actor.y(), actor.z()); + } + if (map != null) { + step.set(CygnusAttributes.MAP, map); + } + } + } catch (RuntimeException exception) { + // observing must not change what happens; the hunt is still counted + if (step != null) { + step.fail(exception); + } + } + this.open.computeIfAbsent(survivor, _ -> new ArrayDeque<>()).addLast(new Hunt(step, now, map)); + } + + /** + * A creek stopped hunting a survivor. + * + * @param survivor the survivor + * @param how how the hunt ended + */ + public synchronized void ended(UUID survivor, HuntEnd how) { + ArrayDeque hunts = this.open.get(survivor); + if (hunts == null) { + return; + } + Hunt hunt = hunts.pollFirst(); + if (hunts.isEmpty()) { + this.open.remove(survivor); + } + if (hunt != null) { + finish(hunt, outcome(how)); + } + } + + /** + * Closes every hunt still open, because the round is ending. + */ + private synchronized void endAll() { + List hunts = new ArrayList<>(); + this.open.values().forEach(hunts::addAll); + this.open.clear(); + hunts.forEach(hunt -> finish(hunt, CygnusAttributes.HUNT_ROUND_END)); + } + + private void finish(Hunt hunt, String outcome) { + long millis = Math.max(0L, this.clock.millis() - hunt.startedAt); + TraceStep step = hunt.step; + try { + if (step != null) { + step.set(CygnusAttributes.HUNT_OUTCOME, outcome); + step.set(CygnusAttributes.HUNT_DURATION_MS, millis); + } + this.metrics.record(outcome, hunt.map, millis); + } catch (RuntimeException exception) { + if (step != null) { + step.fail(exception); + } + } finally { + if (step != null) { + step.close(); + } + } + } + + static String outcome(HuntEnd how) { + return switch (how) { + case CAUGHT -> CygnusAttributes.HUNT_CAUGHT; + case TIMEOUT -> CygnusAttributes.HUNT_TIMEOUT; + case GONE -> CygnusAttributes.HUNT_GONE; + case SENT_AWAY -> CygnusAttributes.HUNT_ESCAPED; + case REMOVED -> CygnusAttributes.HUNT_ROUND_END; + }; + } + + private record Hunt(@Nullable TraceStep step, long startedAt, @Nullable String map) { + } +} diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/RoundTracer.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/RoundTracer.java index a8307019..427c6fc4 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/telemetry/RoundTracer.java +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/RoundTracer.java @@ -36,11 +36,14 @@ *

* * @author TheMeinerLP - * @version 1.0.0 + * @version 1.2.0 * @since 2.15.0 */ public final class RoundTracer { + /** The phase label while no phase runs. */ + public static final String PHASE_NONE = "none"; + private final CygnusTracing tracing; private final Supplier roundIds; private @Nullable TraceStep round; @@ -49,6 +52,9 @@ public final class RoundTracer { // between phases, null with no round. Written only under the lock, on every change. private volatile @Nullable Context current; private volatile @Nullable SpanContext latestRound; + // The name of the running phase for metric labels; PHASE_NONE outside of one. Precomputed so the + // tick thread reads a reference instead of lower-casing a name sixty times a second. + private volatile String phaseLabel = PHASE_NONE; private @Nullable SpanContext startup; // The span API cannot be read back, so whether gameFinished already set the reason is kept here. private boolean endReasonSet; @@ -58,6 +64,7 @@ public final class RoundTracer { private final Set linked = new HashSet<>(); private int droppedLinks; private final List boundaryListeners = new CopyOnWriteArrayList<>(); + private final List endingListeners = new CopyOnWriteArrayList<>(); /** * Creates the tracer. @@ -122,6 +129,16 @@ public synchronized void startupContext(SpanContext context) { return this.current; } + /** + * Returns the lower-cased name of the running phase, or {@value #PHASE_NONE} when none runs. + * A constant reference per phase, so reading it allocates nothing; safe from any thread. + * + * @return the label + */ + public String phaseLabel() { + return this.phaseLabel; + } + /** * Returns the context of the running round, or of the last one when none runs; for a span that * only links to it. @@ -142,9 +159,11 @@ synchronized void phaseStarted(String phaseName) { if (this.round == null) { return; } - TraceStep started = this.round.child(CygnusAttributes.SPAN_PHASE_PREFIX + phaseName.toLowerCase(Locale.ROOT)) + String label = phaseName.toLowerCase(Locale.ROOT); + TraceStep started = this.round.child(CygnusAttributes.SPAN_PHASE_PREFIX + label) .set(CygnusAttributes.PHASE_NAME, phaseName); this.phase = started; + this.phaseLabel = label; this.current = Context.root().with(started.span()); } @@ -172,6 +191,12 @@ synchronized void phaseFailed(Throwable throwable) { * Ends the round span after its last phase. */ synchronized void roundEnded() { + // Before the spans close, so whatever is still open ends below a parent that is still running. + if (this.round != null) { + for (Runnable listener : this.endingListeners) { + listener.run(); + } + } endPhase(); TraceStep current = this.round; this.round = null; @@ -194,6 +219,15 @@ void onBoundary(Runnable listener) { this.boundaryListeners.add(listener); } + /** + * Registers something that has to finish what it holds open before the round and its phase end. + * + * @param listener called when a running round ends, before its spans close; must be quick + */ + void onRoundEnding(Runnable listener) { + this.endingListeners.add(listener); + } + private void notifyBoundary() { for (Runnable listener : this.boundaryListeners) { listener.run(); @@ -355,6 +389,7 @@ private void addEvent(String name, Attributes attributes) { private void endPhase() { TraceStep ended = this.phase; this.phase = null; + this.phaseLabel = PHASE_NONE; TraceStep running = this.round; // Back to the round first, so nothing created from now on attaches to the closed phase. this.current = running == null ? null : Context.root().with(running.span()); diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/SlowTickTracer.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/SlowTickTracer.java index 8142647b..78902f83 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/telemetry/SlowTickTracer.java +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/SlowTickTracer.java @@ -34,15 +34,15 @@ *

* * @author TheMeinerLP - * @version 1.0.0 + * @version 1.2.0 * @since 2.15.0 */ public final class SlowTickTracer { /** - * A service that took less than a millisecond of a slow tick is not worth a span of its own. + * A service that took less than a tenth of a millisecond of a slow tick is not worth a span of its own. */ - static final long SECTION_MIN_NANOS = 1_000_000L; + static final long SECTION_MIN_NANOS = 100_000L; private static final double NANOS_PER_MILLI = 1_000_000.0D; @@ -51,6 +51,10 @@ public final class SlowTickTracer { private final Clock clock; private final TickSections sections; private final @Nullable RoundTracer rounds; + private final TickMetrics metrics; + // The time each section took in the tick being handled; grown when a section is registered, + // which happens at startup, so the tick thread does not allocate. + private long[] taken = new long[0]; /** * Creates the tracer. @@ -75,6 +79,23 @@ public SlowTickTracer(CygnusTracing tracing, TelemetryConfig config, Clock clock */ public SlowTickTracer(CygnusTracing tracing, @Nullable RoundTracer rounds, TelemetryConfig config, Clock clock, TickSections sections) { + this(tracing, rounds, config, clock, sections, TickMetrics.NONE); + } + + /** + * Creates the tracer so that every tick is also measured. + * + * @param tracing where the spans go + * @param rounds the round whose current phase is the parent, or {@code null} for roots only + * @param config the telemetry config + * @param clock the clock the end of the tick is read from + * @param sections the measured services + * @param metrics where the duration of every tick and section goes + * @since 2.15.0 + */ + public SlowTickTracer(CygnusTracing tracing, @Nullable RoundTracer rounds, TelemetryConfig config, + Clock clock, TickSections sections, TickMetrics metrics) { + this.metrics = metrics; this.rounds = rounds; this.tracing = tracing; this.thresholdMillis = config.slowTickThresholdMillis(); @@ -89,14 +110,30 @@ public SlowTickTracer(CygnusTracing tracing, @Nullable RoundTracer rounds, Telem * @param acquisitionMillis how much of it went into waiting for acquirable entities */ public void onTick(double tickMillis, double acquisitionMillis) { - if (tickMillis < this.thresholdMillis) { - // The counters of a fast tick must not leak into the next slow one. - for (int i = 0; i < this.sections.size(); i++) { - this.sections.takeNanos(i); + boolean slow = tickMillis >= this.thresholdMillis; + this.metrics.recordTick(tickMillis, slow); + takeSections(); + if (slow) { + report(tickMillis, acquisitionMillis); + } + } + + /** + * Reads and clears the counters of this tick, so the time of a fast tick cannot leak into the + * next slow one, and records every section that ran. + */ + private void takeSections() { + int size = this.sections.size(); + if (this.taken.length < size) { + this.taken = new long[size]; + } + for (int i = 0; i < size; i++) { + long nanos = this.sections.takeNanos(i); + this.taken[i] = nanos; + if (nanos > 0L) { + this.metrics.recordSection(this.sections.name(i), nanos / NANOS_PER_MILLI); } - return; } - report(tickMillis, acquisitionMillis); } private void report(double tickMillis, double acquisitionMillis) { @@ -119,8 +156,8 @@ private void report(double tickMillis, double acquisitionMillis) { private void reportSections(Span tick, Instant start, Instant end) { Context parent = Context.root().with(tick); - for (int i = 0; i < this.sections.size(); i++) { - long nanos = this.sections.takeNanos(i); + for (int i = 0; i < Math.min(this.sections.size(), this.taken.length); i++) { + long nanos = this.taken[i]; if (nanos < SECTION_MIN_NANOS) { continue; } diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/TickMetrics.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/TickMetrics.java new file mode 100644 index 00000000..a883f230 --- /dev/null +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/TickMetrics.java @@ -0,0 +1,184 @@ +package net.onelitefeather.cygnus.telemetry; + +import io.opentelemetry.api.GlobalOpenTelemetry; +import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.api.metrics.DoubleHistogram; +import io.opentelemetry.api.metrics.LongCounter; +import io.opentelemetry.api.metrics.Meter; +import org.jetbrains.annotations.Nullable; + +import java.util.List; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.function.Supplier; + +/** + * The metrics of the server tick: how long every tick and every measured section took, per phase. + *

+ * Spans only exist for a slow tick, so a trace cannot answer "how long does a lobby tick take + * usually". These metrics can: they are recorded for every tick, which is what makes a + * percentile per phase possible. + *

+ * + * + * + * + * + * + * + *
The instruments
NameKindUnitAttributes
{@value #TICK_DURATION}histogramms{@code cygnus.phase.name}
{@value #SECTION_DURATION}histogramms{@code cygnus.tick.section.name}, {@code cygnus.phase.name}
{@value #SLOW_TICKS}counter{tick}{@code cygnus.phase.name}
+ *

+ * The unit is milliseconds rather than the seconds the semantic conventions prefer: Minestom's budget + * (50 ms), the slow tick threshold and the span attributes are all in milliseconds, and a bucket + * boundary of {@code 50} should read as 50. + *

+ *

+ * The tick thread calls this sixty times a second, so the hot path allocates nothing of its own: the + * {@link Attributes} for every phase and every section/phase pair are built the first time they are + * seen and reused afterwards, and values are recorded as primitives. Cardinality is bounded by the + * four phases and the fixed section names of {@link TickSectionNames}. + *

+ * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +public final class TickMetrics { + + /** Histogram of the duration of every server tick. */ + public static final String TICK_DURATION = "cygnus.tick.duration"; + /** Histogram of the duration of a measured section, per tick it ran in. */ + public static final String SECTION_DURATION = "cygnus.tick.section.duration"; + /** Counter of the ticks at or above the slow tick threshold. */ + public static final String SLOW_TICKS = "cygnus.tick.slow"; + + /** + * The explicit bucket boundaries in milliseconds, from a hundredth of the budget up to four + * times it. The default boundaries of the SDK start at 5 and would put the whole lobby in the + * first bucket. + */ + public static final List BUCKETS_MS = List.of( + 0.1D, 0.25D, 0.5D, 1.0D, 2.5D, 5.0D, 10.0D, 15.0D, 20.0D, 25.0D, 30.0D, 40.0D, 50.0D, 75.0D, 100.0D, + 150.0D, 200.0D); + + /** Metrics that record nothing. */ + public static final TickMetrics NONE = new TickMetrics(null, () -> RoundTracer.PHASE_NONE); + + private final @Nullable DoubleHistogram tickDuration; + private final @Nullable DoubleHistogram sectionDuration; + private final @Nullable LongCounter slowTicks; + private final Supplier phase; + private final Map byPhase = new ConcurrentHashMap<>(); + private final Map> bySection = new ConcurrentHashMap<>(); + + private TickMetrics(@Nullable Meter meter, Supplier phase) { + this.phase = phase; + if (meter == null) { + this.tickDuration = null; + this.sectionDuration = null; + this.slowTicks = null; + return; + } + this.tickDuration = meter.histogramBuilder(TICK_DURATION) + .setDescription("How long a server tick took, per phase") + .setUnit("ms") + .setExplicitBucketBoundariesAdvice(BUCKETS_MS) + .build(); + this.sectionDuration = meter.histogramBuilder(SECTION_DURATION) + .setDescription("How long a measured service took in a tick it ran in, per phase") + .setUnit("ms") + .setExplicitBucketBoundariesAdvice(BUCKETS_MS) + .build(); + this.slowTicks = meter.counterBuilder(SLOW_TICKS) + .setDescription("Server ticks that took at least the slow tick threshold, per phase") + .setUnit("{tick}") + .build(); + } + + /** + * Builds the metrics from the global OpenTelemetry instance. Called once, by the composition root. + * Without the javaagent the global instance is a no-op and so is everything recorded here. + * + * @param version the version of the running service, reported with the instrumentation scope + * @param phase supplies the label of the running phase, see {@link RoundTracer#phaseLabel()} + * @return the metrics + */ + public static TickMetrics fromGlobal(String version, Supplier phase) { + return of(GlobalOpenTelemetry.get().getMeterProvider() + .meterBuilder(CygnusAttributes.INSTRUMENTATION_NAME) + .setInstrumentationVersion(version) + .build(), phase); + } + + /** + * Wraps a meter, for tests and for callers that already hold one. + * + * @param meter the meter the instruments are created on + * @param phase supplies the label of the running phase + * @return the metrics + */ + public static TickMetrics of(Meter meter, Supplier phase) { + return new TickMetrics(meter, phase); + } + + /** + * Records a finished tick. + * + * @param tickMillis how long the tick took + * @param slow whether it counts as slow + */ + void recordTick(double tickMillis, boolean slow) { + DoubleHistogram duration = this.tickDuration; + if (duration == null) { + return; + } + Attributes attributes = phaseAttributes(this.phase.get()); + duration.record(tickMillis, attributes); + if (slow && this.slowTicks != null) { + this.slowTicks.add(1L, attributes); + } + } + + /** + * Records the time one section took in a tick it ran in. + * + * @param section the section name + * @param millis how long it took in total in this tick + */ + void recordSection(String section, double millis) { + DoubleHistogram duration = this.sectionDuration; + if (duration == null) { + return; + } + duration.record(millis, sectionAttributes(section, this.phase.get())); + } + + /** + * Returns the attributes of a phase. The same instance for the same phase, every time. + */ + Attributes phaseAttributes(String phaseLabel) { + Attributes cached = this.byPhase.get(phaseLabel); + if (cached != null) { + return cached; + } + return this.byPhase.computeIfAbsent(phaseLabel, + label -> Attributes.of(CygnusAttributes.PHASE_NAME, label)); + } + + /** + * Returns the attributes of a section in a phase. The same instance for the same pair, every time. + */ + Attributes sectionAttributes(String section, String phaseLabel) { + Map phases = this.bySection.get(section); + if (phases == null) { + phases = this.bySection.computeIfAbsent(section, _ -> new ConcurrentHashMap<>()); + } + Attributes cached = phases.get(phaseLabel); + if (cached != null) { + return cached; + } + return phases.computeIfAbsent(phaseLabel, label -> Attributes.of( + CygnusAttributes.TICK_SECTION_NAME, section, + CygnusAttributes.PHASE_NAME, label)); + } +} diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/TickSectionNames.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/TickSectionNames.java new file mode 100644 index 00000000..0fafbd64 --- /dev/null +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/TickSectionNames.java @@ -0,0 +1,57 @@ +package net.onelitefeather.cygnus.telemetry; + +import java.util.List; + +/** + * The names of the pieces of work measured by {@link TickSections}. + *

+ * A name ends up as the {@code cygnus.tick.section.name} attribute of a slow tick's child span, so + * the set is fixed and small: one name per scheduled service, never per player or per round. A + * service that runs once per player (the stamina bars) reports the sum of all of them under one name. + *

+ * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +public final class TickSectionNames { + + /** The creek's step. */ + public static final String CREEK = "creek"; + /** The reveal that makes a betrayed survivor glow for the slender. */ + public static final String GLOW_REVEAL = "glow-reveal"; + /** The slender's gaze check. */ + public static final String SLENDER_GAZE = "slender-gaze"; + /** The tunnel vision overlay. */ + public static final String TUNNEL_VISION = "tunnel-vision"; + /** The page glitch overlay. */ + public static final String PAGE_GLITCH = "page-glitch"; + /** The fading of blood splatters. */ + public static final String BLOOD_SPLATTER = "blood-splatter"; + /** The hint that tells survivors a page is close. */ + public static final String PAGE_PROXIMITY = "page-proximity"; + /** The ambient sounds and blackouts. */ + public static final String AMBIENT = "ambient"; + /** The adrenaline rush of hunted survivors. */ + public static final String ADRENALINE = "adrenaline"; + /** Taking over the slender role when the slender leaves. */ + public static final String SLENDER_TAKEOVER = "slender-takeover"; + /** The stamina bars of the survivors, all added up. */ + public static final String STAMINA = "stamina"; + /** The stamina bar of the slender. */ + public static final String SLENDER_BAR = "slender-bar"; + /** The jump scare's despawn. */ + public static final String JUMP_SCARE = "jump-scare"; + /** The lobby's waiting action bar. */ + public static final String LOBBY_WAITING = "lobby-waiting"; + /** The lobby's slide of the world time. */ + public static final String LOBBY_TIME = "lobby-time"; + + /** Every name, for tests and documentation to check against. */ + public static final List ALL = List.of(CREEK, GLOW_REVEAL, SLENDER_GAZE, TUNNEL_VISION, PAGE_GLITCH, + BLOOD_SPLATTER, PAGE_PROXIMITY, AMBIENT, ADRENALINE, SLENDER_TAKEOVER, STAMINA, SLENDER_BAR, + JUMP_SCARE, LOBBY_WAITING, LOBBY_TIME); + + private TickSectionNames() { + } +} diff --git a/game/src/main/java/net/onelitefeather/cygnus/telemetry/TracingCreekWitness.java b/game/src/main/java/net/onelitefeather/cygnus/telemetry/TracingCreekWitness.java index 8f5e6778..3287169d 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/telemetry/TracingCreekWitness.java +++ b/game/src/main/java/net/onelitefeather/cygnus/telemetry/TracingCreekWitness.java @@ -1,6 +1,7 @@ package net.onelitefeather.cygnus.telemetry; import net.onelitefeather.cygnus.creek.dread.CreekWitness; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; import org.jetbrains.annotations.Nullable; import java.util.Set; @@ -21,7 +22,7 @@ *

* * @author TheMeinerLP - * @version 1.1.0 + * @version 1.2.0 * @since 2.15.0 */ public final class TracingCreekWitness implements CreekWitness { @@ -30,6 +31,7 @@ public final class TracingCreekWitness implements CreekWitness { private final ActionTracer actions; private final Function survivors; private final Set stalking = ConcurrentHashMap.newKeySet(); + private final @Nullable HuntTracer hunts; /** * Creates the decorator. @@ -41,6 +43,21 @@ public final class TracingCreekWitness implements CreekWitness { */ public TracingCreekWitness(CreekWitness delegate, ActionTracer actions, Function survivors) { + this(delegate, actions, survivors, null); + } + + /** + * Creates the decorator so that hunts are measured too. + * + * @param delegate the witness that still has to hear everything + * @param actions records the actions + * @param survivors resolves a survivor's UUID to who and where they are, or {@code null} if gone + * @param hunts measures the hunts, or {@code null} to leave them alone + * @since 2.15.0 + */ + public TracingCreekWitness(CreekWitness delegate, ActionTracer actions, + Function survivors, @Nullable HuntTracer hunts) { + this.hunts = hunts; this.delegate = delegate; this.actions = actions; this.survivors = survivors; @@ -78,6 +95,9 @@ public void selected(UUID survivor) { @Override public void hunted(UUID survivor) { + if (this.hunts != null) { + this.hunts.started(survivor); + } this.delegate.hunted(survivor); } @@ -86,6 +106,14 @@ public void huntEnded(UUID survivor) { this.delegate.huntEnded(survivor); } + @Override + public void huntEnded(UUID survivor, HuntEnd how) { + if (this.hunts != null) { + this.hunts.ended(survivor, how); + } + this.delegate.huntEnded(survivor, how); + } + /** * A tracing failure must never reach the creek, which is the part of the game that is being * observed. diff --git a/game/src/main/java/net/onelitefeather/cygnus/tunnelvision/TunnelVisionService.java b/game/src/main/java/net/onelitefeather/cygnus/tunnelvision/TunnelVisionService.java index 6fc526f7..44cc923c 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/tunnelvision/TunnelVisionService.java +++ b/game/src/main/java/net/onelitefeather/cygnus/tunnelvision/TunnelVisionService.java @@ -1,5 +1,6 @@ package net.onelitefeather.cygnus.tunnelvision; +import net.onelitefeather.cygnus.telemetry.TickSectionNames; import net.onelitefeather.cygnus.telemetry.TickSections; import net.minestom.server.entity.Player; import net.minestom.server.event.Event; @@ -45,7 +46,7 @@ *

* * @author TheMeinerLP - * @version 2.1.0 + * @version 2.2.0 * @since 2.7.0 */ public final class TunnelVisionService implements GameFeature { @@ -81,7 +82,7 @@ public TunnelVisionService(TunnelVisionRenderer renderer, ToDoubleFunction stamina, Supplier> survivors, TickSections sections) { - this.task = new RepeatingTask(sections.wrap("tunnel-vision", this::tick)); + this.task = new RepeatingTask(sections.wrap(TickSectionNames.TUNNEL_VISION, this::tick)); this.renderer = renderer; this.stamina = stamina; this.roundSurvivors = survivors; diff --git a/game/src/test/java/net/onelitefeather/cygnus/creek/CreekIntegrationTest.java b/game/src/test/java/net/onelitefeather/cygnus/creek/CreekIntegrationTest.java index c930518f..39f52b4a 100644 --- a/game/src/test/java/net/onelitefeather/cygnus/creek/CreekIntegrationTest.java +++ b/game/src/test/java/net/onelitefeather/cygnus/creek/CreekIntegrationTest.java @@ -12,6 +12,7 @@ import net.onelitefeather.cygnus.creek.consequence.PatrolHelper; import net.onelitefeather.cygnus.creek.consequence.StalkSounds; import net.onelitefeather.cygnus.creek.dread.CreekWitness; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; import net.onelitefeather.cygnus.creek.state.Contexts; import net.onelitefeather.cygnus.creek.state.DoneState; import net.onelitefeather.cygnus.creek.state.CreekContext; @@ -66,6 +67,13 @@ private static final class RecordingWitness implements CreekWitness { private final List selections = new ArrayList<>(); private final List hunts = new ArrayList<>(); private final List huntEnds = new ArrayList<>(); + private final List huntReasons = new ArrayList<>(); + + @Override + public void huntEnded(UUID survivor, HuntEnd how) { + this.huntReasons.add(how); + this.huntEnded(survivor); + } @Override public void hunted(UUID survivor) { @@ -381,6 +389,7 @@ void catchEndsTheHunt(Env env) { assertEquals(List.of(survivor.getUuid()), witness.hunts); assertEquals(List.of(survivor.getUuid()), witness.huntEnds); + assertEquals(List.of(HuntEnd.CAUGHT), witness.huntReasons); } @Test @@ -396,6 +405,7 @@ void timeoutEndsTheHunt(Env env) { creek.tick(survivors(survivor), 600L); assertEquals(List.of(survivor.getUuid()), witness.huntEnds); + assertEquals(List.of(HuntEnd.TIMEOUT), witness.huntReasons); } @Test @@ -412,6 +422,7 @@ void goneSurvivorEndsTheHunt(Env env) { creek.tick(survivors(other), 100L); assertEquals(List.of(target.getUuid()), witness.huntEnds); + assertEquals(List.of(HuntEnd.GONE), witness.huntReasons); } @Test @@ -428,6 +439,7 @@ void removingEndsTheHunt(Env env) { creek.remove(); assertEquals(List.of(survivor.getUuid()), witness.huntEnds); + assertEquals(List.of(HuntEnd.REMOVED), witness.huntReasons); } @Test @@ -443,6 +455,7 @@ void vanishingEndsTheHunt(Env env) { creek.vanishForGood(survivors(survivor), 100L); assertEquals(List.of(survivor.getUuid()), witness.huntEnds); + assertEquals(List.of(HuntEnd.SENT_AWAY), witness.huntReasons); } @Test diff --git a/game/src/test/java/net/onelitefeather/cygnus/creek/state/HuntStateEndTest.java b/game/src/test/java/net/onelitefeather/cygnus/creek/state/HuntStateEndTest.java new file mode 100644 index 00000000..017dc3c8 --- /dev/null +++ b/game/src/test/java/net/onelitefeather/cygnus/creek/state/HuntStateEndTest.java @@ -0,0 +1,70 @@ +package net.onelitefeather.cygnus.creek.state; + +import net.minestom.server.coordinate.Pos; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +import java.util.ArrayList; +import java.util.UUID; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNull; + +/** + * Covers how a hunt says why it ended, which is what the hunt outcome is made from. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +class HuntStateEndTest { + + private static final UUID TARGET = UUID.randomUUID(); + private static final Pos TARGET_POS = new Pos(0, 40, 0, 180, 0); + + private static CreekContext at(long now, RecordingBody body, UUID who) { + return Contexts.context(now, body, Contexts.route(), new ArrayList<>(), + new SurvivorView(who, TARGET_POS, 0.7D, false)); + } + + @Test + @DisplayName("A running hunt has no end yet") + void runningHuntHasNoEnd() { + HuntState hunt = new HuntState(TARGET, 30_000L); + + hunt.tick(at(0L, new RecordingBody(new Pos(0, 40, 10)), TARGET)); + + assertNull(hunt.end()); + } + + @Test + @DisplayName("A catch ends the hunt as caught") + void catchIsCaught() { + HuntState hunt = new HuntState(TARGET, 30_000L); + + hunt.tick(at(0L, new RecordingBody(new Pos(0, 40, 1)), TARGET)); + + assertEquals(HuntEnd.CAUGHT, hunt.end()); + } + + @Test + @DisplayName("Running out of time ends the hunt as a timeout") + void timeIsUp() { + HuntState hunt = new HuntState(TARGET, 30_000L); + + hunt.tick(at(30_000L, new RecordingBody(new Pos(0, 40, 10)), TARGET)); + + assertEquals(HuntEnd.TIMEOUT, hunt.end()); + } + + @Test + @DisplayName("A target that is no longer among the survivors ends the hunt as gone") + void targetIsGone() { + HuntState hunt = new HuntState(TARGET, 30_000L); + + hunt.tick(at(0L, new RecordingBody(new Pos(0, 40, 10)), UUID.randomUUID())); + + assertEquals(HuntEnd.GONE, hunt.end()); + } +} diff --git a/game/src/test/java/net/onelitefeather/cygnus/telemetry/HuntTracerTest.java b/game/src/test/java/net/onelitefeather/cygnus/telemetry/HuntTracerTest.java new file mode 100644 index 00000000..356e5856 --- /dev/null +++ b/game/src/test/java/net/onelitefeather/cygnus/telemetry/HuntTracerTest.java @@ -0,0 +1,237 @@ +package net.onelitefeather.cygnus.telemetry; + +import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.sdk.metrics.SdkMeterProvider; +import io.opentelemetry.sdk.metrics.data.HistogramPointData; +import io.opentelemetry.sdk.metrics.data.MetricData; +import io.opentelemetry.sdk.testing.exporter.InMemoryMetricReader; +import io.opentelemetry.sdk.trace.data.SpanData; +import net.onelitefeather.cygnus.creek.dread.HuntEnd; +import net.onelitefeather.cygnus.telemetry.ActionTracer.Actor; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.CsvSource; + +import java.time.Clock; +import java.time.Instant; +import java.time.ZoneId; +import java.time.ZoneOffset; +import java.util.List; +import java.util.UUID; +import java.util.concurrent.atomic.AtomicReference; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** + * Covers the hunt span and the hunt metrics. Time is a clock the test moves by hand, the SDK is a + * private in-memory one, nothing waits. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +class HuntTracerTest { + + private static final UUID SURVIVOR = UUID.fromString("00000000-0000-0000-0000-0000000000a1"); + + private TestTelemetry telemetry; + private InMemoryMetricReader reader; + private SdkMeterProvider meters; + private RoundTracer rounds; + private HuntMetrics metrics; + private HuntTracer hunts; + private AtomicReference now; + + @BeforeEach + void setUp() { + this.telemetry = new TestTelemetry(); + this.reader = InMemoryMetricReader.create(); + this.meters = SdkMeterProvider.builder().registerMetricReader(this.reader).build(); + this.metrics = HuntMetrics.of(this.meters.get("test")); + this.rounds = new RoundTracer(this.telemetry.tracing(), () -> "round-1"); + this.now = new AtomicReference<>(Instant.parse("2026-01-01T00:00:00Z")); + Clock clock = new Clock() { + @Override + public ZoneId getZone() { + return ZoneOffset.UTC; + } + + @Override + public Clock withZone(ZoneId zone) { + return this; + } + + @Override + public Instant instant() { + return now.get(); + } + }; + this.hunts = new HuntTracer(this.rounds, clock, () -> "Cabin", + id -> new Actor(id, "survivor", 1.04D, 40.0D, -3.0D), this.metrics); + } + + @AfterEach + void tearDown() { + this.meters.close(); + this.telemetry.close(); + } + + private void pass(long seconds) { + this.now.updateAndGet(instant -> instant.plusSeconds(seconds)); + } + + private List huntSpans() { + return this.telemetry.spans().stream() + .filter(span -> span.getName().equals(CygnusAttributes.ACTION_CREEK_HUNT)).toList(); + } + + private MetricData metric(String name) { + return this.reader.collectAllMetrics().stream().filter(data -> data.getName().equals(name)) + .findFirst().orElseThrow(() -> new AssertionError("no metric '" + name + "'")); + } + + @ParameterizedTest(name = "{0} ends the hunt as {1}") + @CsvSource({"CAUGHT,caught", "TIMEOUT,timeout", "GONE,gone", "SENT_AWAY,escaped", "REMOVED,round_end"}) + @DisplayName("Every way a hunt can end has its outcome") + void outcomePerEndPath(HuntEnd how, String outcome) { + this.rounds.roundStarted(); + this.hunts.started(SURVIVOR); + pass(12); + + this.hunts.ended(SURVIVOR, how); + + SpanData span = huntSpans().getFirst(); + assertEquals(outcome, span.getAttributes().get(CygnusAttributes.HUNT_OUTCOME)); + assertEquals(12_000L, span.getAttributes().get(CygnusAttributes.HUNT_DURATION_MS)); + } + + @Test + @DisplayName("A hunt span says who, where and on which map, and hangs below the phase") + void spanAttributes() { + this.rounds.roundStarted(); + this.rounds.phaseStarted("GamePhase"); + this.hunts.started(SURVIVOR); + + this.hunts.ended(SURVIVOR, HuntEnd.CAUGHT); + this.rounds.roundEnded(); + + SpanData span = huntSpans().getFirst(); + assertEquals(SURVIVOR.toString(), span.getAttributes().get(CygnusAttributes.PLAYER_UUID)); + assertEquals("survivor", span.getAttributes().get(CygnusAttributes.PLAYER_ROLE)); + assertEquals(1.0D, span.getAttributes().get(CygnusAttributes.POSITION_X)); + assertEquals(40.0D, span.getAttributes().get(CygnusAttributes.POSITION_Y)); + assertEquals("Cabin", span.getAttributes().get(CygnusAttributes.MAP)); + assertEquals(this.telemetry.span("cygnus.phase.gamephase").getSpanId(), span.getParentSpanId()); + } + + @Test + @DisplayName("The hunt duration is recorded with the outcome and the map") + void histogramHasOutcomeAndMap() { + this.rounds.roundStarted(); + this.hunts.started(SURVIVOR); + pass(8); + this.hunts.ended(SURVIVOR, HuntEnd.TIMEOUT); + + MetricData data = metric(HuntMetrics.HUNT_DURATION); + assertEquals("ms", data.getUnit()); + HistogramPointData point = data.getHistogramData().getPoints().iterator().next(); + assertEquals(1, point.getCount()); + assertEquals(8_000.0D, point.getSum(), 1e-9); + assertEquals(Attributes.of(CygnusAttributes.HUNT_OUTCOME, "timeout", CygnusAttributes.MAP, "Cabin"), + point.getAttributes()); + assertEquals(1L, metric(HuntMetrics.HUNTS).getLongSumData().getPoints().iterator().next().getValue()); + } + + @Test + @DisplayName("No metric carries a player") + void metricsHaveNoPlayer() { + this.rounds.roundStarted(); + this.hunts.started(SURVIVOR); + this.hunts.ended(SURVIVOR, HuntEnd.CAUGHT); + + for (String name : List.of(HuntMetrics.HUNT_DURATION, HuntMetrics.HUNTS)) { + metric(name).getData().getPoints().forEach(point -> { + assertEquals(2, point.getAttributes().size(), "outcome and map only"); + assertNull(point.getAttributes().get(CygnusAttributes.PLAYER_UUID)); + }); + } + } + + @Test + @DisplayName("The ending of a round closes the hunts still open as round_end, below a phase that still runs") + void roundEndClosesOpenHunts() { + this.rounds.roundStarted(); + this.rounds.phaseStarted("GamePhase"); + this.hunts.started(SURVIVOR); + this.hunts.started(UUID.randomUUID()); + pass(5); + + this.rounds.roundEnded(); + + List spans = huntSpans(); + assertEquals(2, spans.size()); + SpanData phase = this.telemetry.span("cygnus.phase.gamephase"); + spans.forEach(span -> { + assertEquals("round_end", span.getAttributes().get(CygnusAttributes.HUNT_OUTCOME)); + assertEquals(5_000L, span.getAttributes().get(CygnusAttributes.HUNT_DURATION_MS)); + assertTrue(span.getEndEpochNanos() <= phase.getEndEpochNanos(), "ends before its parent"); + }); + assertEquals(2L, metric(HuntMetrics.HUNTS).getLongSumData().getPoints().iterator().next().getValue()); + } + + @Test + @DisplayName("Two creeks hunting one survivor are two spans, closed one by one") + void twoHuntsOfOneSurvivor() { + this.rounds.roundStarted(); + this.hunts.started(SURVIVOR); + pass(2); + this.hunts.started(SURVIVOR); + pass(3); + + this.hunts.ended(SURVIVOR, HuntEnd.CAUGHT); + assertEquals(1, huntSpans().size()); + this.hunts.ended(SURVIVOR, HuntEnd.TIMEOUT); + + assertEquals(2, huntSpans().size()); + } + + @Test + @DisplayName("An end without a start is ignored, and a hunt is counted even when no round runs") + void endWithoutStartAndHuntWithoutRound() { + this.hunts.ended(SURVIVOR, HuntEnd.CAUGHT); + assertTrue(this.reader.collectAllMetrics().isEmpty()); + + this.hunts.started(SURVIVOR); + pass(1); + this.hunts.ended(SURVIVOR, HuntEnd.GONE); + + assertTrue(huntSpans().isEmpty(), "no round, no trace to belong to"); + assertEquals(1L, metric(HuntMetrics.HUNTS).getLongSumData().getPoints().iterator().next().getValue()); + } + + @Test + @DisplayName("The attributes of an outcome on a map are built once and reused") + void attributesAreReused() { + assertSame(this.metrics.attributes("caught", "Cabin"), this.metrics.attributes("caught", "Cabin")); + } + + @Test + @DisplayName("Metrics that record nothing leave the span working") + void noneMetrics() { + HuntTracer plain = new HuntTracer(this.rounds, Clock.fixed(Instant.EPOCH, ZoneOffset.UTC), () -> null, + id -> null, HuntMetrics.NONE); + this.rounds.roundStarted(); + + plain.started(SURVIVOR); + plain.ended(SURVIVOR, HuntEnd.CAUGHT); + + assertEquals(1, huntSpans().size()); + assertNull(huntSpans().getFirst().getAttributes().get(CygnusAttributes.MAP)); + } +} diff --git a/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickLobbyTest.java b/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickLobbyTest.java new file mode 100644 index 00000000..fb8080f0 --- /dev/null +++ b/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickLobbyTest.java @@ -0,0 +1,74 @@ +package net.onelitefeather.cygnus.telemetry; + +import io.opentelemetry.sdk.trace.data.SpanData; +import net.onelitefeather.cygnus.common.config.TelemetryConfig; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +import java.time.Clock; +import java.time.Instant; +import java.time.ZoneOffset; +import java.util.List; +import java.util.concurrent.atomic.AtomicLong; + +import static org.junit.jupiter.api.Assertions.assertEquals; + +/** + * Covers the slow tick in the lobby, where neither the creek nor the gaze nor the tunnel vision run: + * the tick still has to say who was in it. Time is a hand-driven counter, nothing waits. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +class SlowTickLobbyTest { + + private static final long MILLI = 1_000_000L; + + private TestTelemetry telemetry; + private AtomicLong nanos; + private TickSections sections; + private RoundTracer rounds; + private SlowTickTracer tracer; + + @BeforeEach + void setUp() { + this.telemetry = new TestTelemetry(); + this.nanos = new AtomicLong(); + this.sections = TickSections.measuring(this.nanos::get); + this.rounds = new RoundTracer(this.telemetry.tracing(), () -> "round-1"); + this.tracer = new SlowTickTracer(this.telemetry.tracing(), this.rounds, new TelemetryConfig(50), + Clock.fixed(Instant.parse("2026-01-01T00:00:10Z"), ZoneOffset.UTC), this.sections); + } + + @AfterEach + void tearDown() { + this.telemetry.close(); + } + + @Test + @DisplayName("A slow lobby tick has the lobby's tasks as children and none of the game's") + void lobbyTickHasTheLobbyTasksAsChildren() { + // Every service registers once at startup, whether or not it runs in this phase. + TickSectionNames.ALL.forEach(name -> this.sections.wrap(name, () -> { + })); + this.rounds.roundStarted(); + this.rounds.phaseStarted("Lobby"); + this.sections.wrap(TickSectionNames.LOBBY_WAITING, () -> this.nanos.addAndGet(2 * MILLI)).run(); + this.sections.wrap(TickSectionNames.LOBBY_TIME, () -> this.nanos.addAndGet(MILLI / 2)).run(); + + this.tracer.onTick(59.0D, 0.0D); + this.rounds.roundEnded(); + + SpanData tick = this.telemetry.span(CygnusAttributes.SPAN_SLOW_TICK); + List children = this.telemetry.spans().stream() + .filter(span -> span.getName().equals(CygnusAttributes.SPAN_TICK_SECTION)).toList(); + assertEquals(List.of(TickSectionNames.LOBBY_WAITING, TickSectionNames.LOBBY_TIME), + children.stream().map(span -> span.getAttributes().get(CygnusAttributes.TICK_SECTION_NAME)).toList()); + children.forEach(child -> assertEquals(tick.getSpanId(), child.getParentSpanId())); + assertEquals(this.telemetry.span("cygnus.phase.lobby").getSpanId(), tick.getParentSpanId(), + "the slow tick stays parented to the phase it happened in"); + } +} diff --git a/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickTracerTest.java b/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickTracerTest.java index 88b5a2e6..251dd58a 100644 --- a/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickTracerTest.java +++ b/game/src/test/java/net/onelitefeather/cygnus/telemetry/SlowTickTracerTest.java @@ -23,7 +23,7 @@ * waits and none reads the real clock. * * @author TheMeinerLP - * @version 1.0.0 + * @version 1.1.0 * @since 2.15.0 */ class SlowTickTracerTest { @@ -109,6 +109,38 @@ void measuredServiceIsAChild() { assertEquals(tick.getStartEpochNanos(), section.getStartEpochNanos(), "a section starts with the tick"); } + @Test + @DisplayName("A service that took a few hundred microseconds still gets its child span") + void shortShareAboveTheFloorIsReported() { + this.sections.wrap("ambient", () -> this.nanos.addAndGet(300_000L)).run(); + + this.tracer.onTick(80.0D, 0.0D); + + assertEquals(0.3D, this.telemetry.span(CygnusAttributes.SPAN_TICK_SECTION) + .getAttributes().get(CygnusAttributes.TICK_SECTION_DURATION_MS)); + } + + @Test + @DisplayName("Every section that ran is a child with its own duration, the ones that did not are omitted") + void oneChildPerActiveSection() { + this.sections.wrap(TickSectionNames.AMBIENT, () -> { + }); + this.sections.wrap(TickSectionNames.CREEK, () -> { + }); + runFor(TickSectionNames.PAGE_PROXIMITY, 4); + runFor(TickSectionNames.STAMINA, 7); + + this.tracer.onTick(80.0D, 0.0D); + + List children = this.telemetry.spans().stream() + .filter(span -> span.getName().equals(CygnusAttributes.SPAN_TICK_SECTION)).toList(); + assertEquals(List.of(TickSectionNames.PAGE_PROXIMITY, TickSectionNames.STAMINA), + children.stream().map(span -> span.getAttributes().get(CygnusAttributes.TICK_SECTION_NAME)).toList(), + "only the sections that ran, in registration order"); + assertEquals(List.of(4.0D, 7.0D), children.stream() + .map(span -> span.getAttributes().get(CygnusAttributes.TICK_SECTION_DURATION_MS)).toList()); + } + @Test @DisplayName("A service that ran twice in the tick is reported once, with both runs added") void repeatedRunsAreAdded() { @@ -122,9 +154,9 @@ void repeatedRunsAreAdded() { } @Test - @DisplayName("A service under a millisecond is left out") + @DisplayName("A service under a tenth of a millisecond is left out") void tinyShareIsLeftOut() { - this.sections.wrap("tunnelvision", () -> this.nanos.addAndGet(MILLI - 1)).run(); + this.sections.wrap("tunnelvision", () -> this.nanos.addAndGet(SlowTickTracer.SECTION_MIN_NANOS - 1)).run(); this.tracer.onTick(80.0D, 0.0D); diff --git a/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickMetricsTest.java b/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickMetricsTest.java new file mode 100644 index 00000000..3f975f14 --- /dev/null +++ b/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickMetricsTest.java @@ -0,0 +1,254 @@ +package net.onelitefeather.cygnus.telemetry; + +import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.sdk.metrics.SdkMeterProvider; +import io.opentelemetry.sdk.metrics.data.HistogramPointData; +import io.opentelemetry.sdk.metrics.data.LongPointData; +import io.opentelemetry.sdk.metrics.data.MetricData; +import io.opentelemetry.sdk.testing.exporter.InMemoryMetricReader; +import net.onelitefeather.cygnus.common.config.TelemetryConfig; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +import java.time.Clock; +import java.time.Instant; +import java.time.ZoneOffset; +import java.util.List; +import java.util.concurrent.atomic.AtomicLong; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** + * Covers the tick metrics against a private in-memory SDK that is never registered globally. The + * phase is the real one of a {@link RoundTracer}, time is a hand-driven counter, nothing waits. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +class TickMetricsTest { + + private static final long MILLI = 1_000_000L; + private static final long THRESHOLD_MS = 50; + + private TestTelemetry telemetry; + private InMemoryMetricReader reader; + private SdkMeterProvider meters; + private RoundTracer rounds; + private AtomicLong nanos; + private TickSections sections; + private TickMetrics metrics; + private SlowTickTracer tracer; + + @BeforeEach + void setUp() { + this.telemetry = new TestTelemetry(); + this.reader = InMemoryMetricReader.create(); + this.meters = SdkMeterProvider.builder().registerMetricReader(this.reader).build(); + this.rounds = new RoundTracer(this.telemetry.tracing(), () -> "round-1"); + this.nanos = new AtomicLong(); + this.sections = TickSections.measuring(this.nanos::get); + this.metrics = TickMetrics.of(this.meters.get("test"), this.rounds::phaseLabel); + this.tracer = new SlowTickTracer(this.telemetry.tracing(), this.rounds, new TelemetryConfig((int) THRESHOLD_MS), + Clock.fixed(Instant.parse("2026-01-01T00:00:10Z"), ZoneOffset.UTC), this.sections, this.metrics); + } + + @AfterEach + void tearDown() { + this.meters.close(); + this.telemetry.close(); + } + + private MetricData metric(String name) { + return this.reader.collectAllMetrics().stream() + .filter(data -> data.getName().equals(name)) + .findFirst() + .orElseThrow(() -> new AssertionError("no metric '" + name + "' was recorded")); + } + + private HistogramPointData histogramPoint(String name, Attributes attributes) { + return metric(name).getHistogramData().getPoints().stream() + .filter(point -> point.getAttributes().equals(attributes)) + .findFirst() + .orElseThrow(() -> new AssertionError("no point " + attributes + " in " + name)); + } + + private static Attributes phase(String label) { + return Attributes.of(CygnusAttributes.PHASE_NAME, label); + } + + private void runFor(String name, long millis) { + this.sections.wrap(name, () -> this.nanos.addAndGet(millis * MILLI)).run(); + } + + private void startPhase(String name) { + this.rounds.roundStarted(); + this.rounds.phaseStarted(name); + } + + @Test + @DisplayName("Every tick is recorded, not only the slow ones") + void everyTickIsRecorded() { + startPhase("Lobby"); + + this.tracer.onTick(1.5D, 0.0D); + this.tracer.onTick(2.5D, 0.0D); + this.tracer.onTick(70.0D, 0.0D); + + HistogramPointData lobby = histogramPoint(TickMetrics.TICK_DURATION, phase("lobby")); + assertEquals(3, lobby.getCount()); + assertEquals(74.0D, lobby.getSum(), 1e-9); + } + + @Test + @DisplayName("A tick is recorded under the phase it ran in") + void tickIsRecordedPerPhase() { + startPhase("Lobby"); + this.tracer.onTick(3.0D, 0.0D); + this.rounds.phaseEnded(); + this.rounds.phaseStarted("GamePhase"); + this.tracer.onTick(7.0D, 0.0D); + this.tracer.onTick(9.0D, 0.0D); + + assertEquals(1, histogramPoint(TickMetrics.TICK_DURATION, phase("lobby")).getCount()); + HistogramPointData game = histogramPoint(TickMetrics.TICK_DURATION, phase("gamephase")); + assertEquals(2, game.getCount()); + assertEquals(16.0D, game.getSum(), 1e-9); + } + + @Test + @DisplayName("A tick with no phase running is recorded as none") + void tickWithoutAPhaseIsNone() { + this.tracer.onTick(4.0D, 0.0D); + + assertEquals(1, histogramPoint(TickMetrics.TICK_DURATION, phase(RoundTracer.PHASE_NONE)).getCount()); + } + + @Test + @DisplayName("Between two phases and after the round the label is none again") + void labelFallsBackToNone() { + startPhase("Waiting"); + assertEquals("waiting", this.rounds.phaseLabel()); + + this.rounds.phaseEnded(); + assertEquals(RoundTracer.PHASE_NONE, this.rounds.phaseLabel()); + + this.rounds.phaseStarted("Restart"); + this.rounds.roundEnded(); + assertEquals(RoundTracer.PHASE_NONE, this.rounds.phaseLabel()); + } + + @Test + @DisplayName("A section is recorded per tick it ran in, with its name and the phase") + void sectionIsRecordedPerPhase() { + startPhase("Lobby"); + runFor(TickSectionNames.LOBBY_WAITING, 2); + this.tracer.onTick(5.0D, 0.0D); + runFor(TickSectionNames.LOBBY_WAITING, 3); + this.tracer.onTick(5.0D, 0.0D); + this.rounds.phaseEnded(); + this.rounds.phaseStarted("GamePhase"); + runFor(TickSectionNames.CREEK, 4); + this.tracer.onTick(5.0D, 0.0D); + + HistogramPointData waiting = histogramPoint(TickMetrics.SECTION_DURATION, Attributes.of( + CygnusAttributes.TICK_SECTION_NAME, TickSectionNames.LOBBY_WAITING, + CygnusAttributes.PHASE_NAME, "lobby")); + assertEquals(2, waiting.getCount()); + assertEquals(5.0D, waiting.getSum(), 1e-9); + HistogramPointData creek = histogramPoint(TickMetrics.SECTION_DURATION, Attributes.of( + CygnusAttributes.TICK_SECTION_NAME, TickSectionNames.CREEK, + CygnusAttributes.PHASE_NAME, "gamephase")); + assertEquals(1, creek.getCount()); + assertEquals(4.0D, creek.getSum(), 1e-9); + } + + @Test + @DisplayName("A section that did not run in a tick is not recorded for it") + void idleSectionIsNotRecorded() { + startPhase("Lobby"); + this.sections.wrap(TickSectionNames.CREEK, () -> { + }); + runFor(TickSectionNames.AMBIENT, 1); + + this.tracer.onTick(5.0D, 0.0D); + + List recorded = metric(TickMetrics.SECTION_DURATION).getHistogramData().getPoints().stream() + .map(point -> point.getAttributes().get(CygnusAttributes.TICK_SECTION_NAME)).toList(); + assertEquals(List.of(TickSectionNames.AMBIENT), recorded); + } + + @Test + @DisplayName("The time of a fast tick is recorded once and does not show up in the next tick") + void sectionTimeDoesNotLeakIntoTheNextTick() { + startPhase("Lobby"); + runFor(TickSectionNames.AMBIENT, 6); + this.tracer.onTick(5.0D, 0.0D); + this.tracer.onTick(5.0D, 0.0D); + + HistogramPointData ambient = histogramPoint(TickMetrics.SECTION_DURATION, Attributes.of( + CygnusAttributes.TICK_SECTION_NAME, TickSectionNames.AMBIENT, + CygnusAttributes.PHASE_NAME, "lobby")); + assertEquals(1, ambient.getCount()); + } + + @Test + @DisplayName("The slow counter counts the ticks at or above the threshold and no others") + void slowCounterOnlyCountsSlowTicks() { + startPhase("Lobby"); + + this.tracer.onTick(49.9D, 0.0D); + this.tracer.onTick(50.0D, 0.0D); + this.tracer.onTick(120.0D, 0.0D); + + LongPointData point = metric(TickMetrics.SLOW_TICKS).getLongSumData().getPoints().iterator().next(); + assertEquals(2L, point.getValue()); + assertEquals(phase("lobby"), point.getAttributes()); + } + + @Test + @DisplayName("Without a slow tick the counter has no point at all") + void noSlowTickNoPoint() { + this.tracer.onTick(10.0D, 0.0D); + + assertTrue(this.reader.collectAllMetrics().stream() + .noneMatch(data -> data.getName().equals(TickMetrics.SLOW_TICKS) && !data.getLongSumData().getPoints().isEmpty())); + } + + @Test + @DisplayName("The histograms are in milliseconds with boundaries that resolve a tenth of a millisecond") + void histogramsUseMillisecondsAndFineBuckets() { + this.tracer.onTick(1.0D, 0.0D); + + MetricData data = metric(TickMetrics.TICK_DURATION); + assertEquals("ms", data.getUnit()); + assertEquals(TickMetrics.BUCKETS_MS, data.getHistogramData().getPoints().iterator().next().getBoundaries()); + assertEquals(0.1D, TickMetrics.BUCKETS_MS.getFirst()); + assertEquals(200.0D, TickMetrics.BUCKETS_MS.getLast()); + } + + @Test + @DisplayName("The attributes of a phase and of a section are built once and reused") + void attributesAreReused() { + assertSame(this.metrics.phaseAttributes("lobby"), this.metrics.phaseAttributes("lobby")); + assertSame(this.metrics.sectionAttributes("creek", "gamephase"), this.metrics.sectionAttributes("creek", "gamephase")); + assertTrue(this.metrics.phaseAttributes("lobby") != this.metrics.phaseAttributes("waiting")); + assertTrue(this.metrics.sectionAttributes("creek", "gamephase") != this.metrics.sectionAttributes("creek", "lobby")); + } + + @Test + @DisplayName("Metrics that record nothing leave the tracer working") + void noneRecordsNothing() { + SlowTickTracer plain = new SlowTickTracer(this.telemetry.tracing(), this.rounds, new TelemetryConfig((int) THRESHOLD_MS), + Clock.fixed(Instant.EPOCH, ZoneOffset.UTC), this.sections); + + plain.onTick(80.0D, 0.0D); + + this.telemetry.span(CygnusAttributes.SPAN_SLOW_TICK); + assertTrue(this.reader.collectAllMetrics().isEmpty()); + } +} diff --git a/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickSectionNamesTest.java b/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickSectionNamesTest.java new file mode 100644 index 00000000..f646e3b7 --- /dev/null +++ b/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickSectionNamesTest.java @@ -0,0 +1,32 @@ +package net.onelitefeather.cygnus.telemetry; + +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; + +import java.util.HashSet; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** + * Keeps the section names a small, stable set: they are span attribute values and metric labels. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +class TickSectionNamesTest { + + @Test + @DisplayName("No two sections share a name") + void namesAreUnique() { + assertEquals(TickSectionNames.ALL.size(), new HashSet<>(TickSectionNames.ALL).size()); + } + + @Test + @DisplayName("Every name is lower case words joined by dashes") + void namesAreKebabCase() { + TickSectionNames.ALL.forEach(name -> + assertTrue(name.matches("[a-z]+(-[a-z]+)*"), name + " is not kebab-case")); + } +} diff --git a/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickSectionWiringTest.java b/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickSectionWiringTest.java new file mode 100644 index 00000000..454cbf79 --- /dev/null +++ b/game/src/test/java/net/onelitefeather/cygnus/telemetry/TickSectionWiringTest.java @@ -0,0 +1,92 @@ +package net.onelitefeather.cygnus.telemetry; + +import io.opentelemetry.sdk.trace.data.SpanData; +import net.minestom.server.instance.Instance; +import net.minestom.testing.Env; +import net.minestom.testing.extension.MicrotusExtension; +import net.onelitefeather.cygnus.common.config.TelemetryConfig; +import net.onelitefeather.cygnus.common.util.Helper; +import net.onelitefeather.cygnus.phase.task.LobbyTimeTransitionTask; +import net.onelitefeather.cygnus.phase.task.LobbyWaitingTask; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.DisplayName; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.ExtendWith; + +import java.time.Clock; +import java.time.Instant; +import java.time.ZoneOffset; +import java.util.concurrent.atomic.AtomicLong; + +import static org.junit.jupiter.api.Assertions.assertEquals; + +/** + * Checks that the lobby's real tasks report to {@link TickSections} when the scheduler runs them. + * The clock moves a millisecond with every read, so one run is exactly one millisecond of clock + * and nothing depends on the machine. + * + * @author TheMeinerLP + * @version 1.0.0 + * @since 2.15.0 + */ +@ExtendWith(MicrotusExtension.class) +class TickSectionWiringTest { + + private static final long MILLI = 1_000_000L; + + private TestTelemetry telemetry; + private TickSections sections; + private SlowTickTracer tracer; + + @BeforeEach + void setUp() { + this.telemetry = new TestTelemetry(); + AtomicLong clock = new AtomicLong(); + this.sections = TickSections.measuring(() -> clock.addAndGet(MILLI)); + this.tracer = new SlowTickTracer(this.telemetry.tracing(), new TelemetryConfig(50), + Clock.fixed(Instant.parse("2026-01-01T00:00:10Z"), ZoneOffset.UTC), this.sections); + } + + @AfterEach + void tearDown() { + this.telemetry.close(); + } + + private SpanData section(String name) { + return this.telemetry.spans().stream() + .filter(span -> span.getName().equals(CygnusAttributes.SPAN_TICK_SECTION)) + .filter(span -> name.equals(span.getAttributes().get(CygnusAttributes.TICK_SECTION_NAME))) + .findFirst() + .orElseThrow(() -> new AssertionError("no section '" + name + "' among " + this.telemetry.spans())); + } + + @Test + @DisplayName("The lobby's waiting display shows up in a slow tick") + void waitingDisplayIsMeasured(Env env) { + LobbyWaitingTask display = new LobbyWaitingTask(2, this.sections); + + env.tick(); + this.tracer.onTick(80.0D, 0.0D); + display.stop(); + + assertEquals(1.0D, section(TickSectionNames.LOBBY_WAITING) + .getAttributes().get(CygnusAttributes.TICK_SECTION_DURATION_MS)); + } + + @Test + @DisplayName("The lobby's time transition shows up in a slow tick") + void timeTransitionIsMeasured(Env env) { + Instance instance = env.createFlatInstance(); + LobbyTimeTransitionTask task = new LobbyTimeTransitionTask(() -> instance, Helper.MIDNIGHT_TIME, 1, this.sections); + task.start(); + + env.tick(); + this.tracer.onTick(80.0D, 0.0D); + task.stop(); + + assertEquals(1.0D, section(TickSectionNames.LOBBY_TIME) + .getAttributes().get(CygnusAttributes.TICK_SECTION_DURATION_MS)); + env.destroyInstance(instance, true); + } +}