diff --git a/docs/telemetry.md b/docs/telemetry.md index cb4b2d39..f4e575ce 100644 --- a/docs/telemetry.md +++ b/docs/telemetry.md @@ -130,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 @@ -162,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 faad1713..896794e1 100644 --- a/game/src/main/java/net/onelitefeather/cygnus/Cygnus.java +++ b/game/src/main/java/net/onelitefeather/cygnus/Cygnus.java @@ -106,6 +106,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; @@ -120,7 +123,7 @@ /** * @author theEvilReaper - * @version 1.4.0 + * @version 1.6.0 * @since 1.0.0 **/ @SuppressWarnings("java:S3252") @@ -179,7 +182,8 @@ public Cygnus() { 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.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. @@ -233,7 +237,9 @@ public Cygnus() { // either way, and it needs neither the resource pack nor the overlay gate to be heard. new DamageSoundService(this.gameConfig.damageSound(), System::currentTimeMillis), 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), sanityService, new AdrenalineService( 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 035ec00b..37a2d484 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; @@ -30,7 +31,7 @@ *

* * @author theEvilReaper - * @version 1.1.0 + * @version 1.2.0 * @since 2.15.0 */ final class Creek { @@ -49,6 +50,7 @@ final class Creek { private Set seenLastStep = Set.of(); private boolean entered; private @Nullable UUID hunting; + private @Nullable HuntState huntState; /** * Sets up a creek. @@ -93,11 +95,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()); } @@ -114,19 +116,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); } @@ -219,7 +230,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/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 4ce2b953..64faa21a 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.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/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 fc252fbb..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,7 +34,7 @@ *

* * @author TheMeinerLP - * @version 1.1.0 + * @version 1.2.0 * @since 2.15.0 */ public final class SlowTickTracer { @@ -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/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/test/java/net/onelitefeather/cygnus/creek/CreekIntegrationTest.java b/game/src/test/java/net/onelitefeather/cygnus/creek/CreekIntegrationTest.java index 66bc9427..79419181 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/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()); + } +}