fix(telemetry): give slow ticks their section children

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.

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);

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 @@
  * </p>
  *
  * @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<Set<Player>> survivors;
     private final LongSupplier clock;
-    private final RepeatingTask task = new RepeatingTask(this::tick);
+    private final RepeatingTask task;
     private final Set<Player> 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<Set<Player>> 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<Set<Player>> survivors, LongSupplier clock,
+                             TickSections sections) {
+        this.task = new RepeatingTask(sections.wrap(TickSectionNames.ADRENALINE, this::tick));
         this.config = config;
         this.survivors = survivors;
         this.clock = clock;

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 @@
  * }</pre>
  *
  * @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;