Split direct-write mutation phases

Author: Arbousier1

common/src/main/java/com/loohp/interactionvisualizer/Commands.java

@@ -46,6 +46,7 @@
 
 import java.util.LinkedList;
 import java.util.List;
+import java.util.Locale;
 import java.util.UUID;
 
 public class Commands implements CommandExecutor, TabCompleter {
@@ -474,7 +475,10 @@ private static void mutatePerformanceBlockScene(CommandSender sender, String[] a
                     "state=invalid reason=online_player_or_owner_uuid_required");
             return;
         }
+        long mutationCommandStartNanos = System.nanoTime();
         PerformanceBlockScene.Snapshot current = PerformanceBlockScene.snapshot(owner.ownerId());
+        long mutationPreflightElapsedNanos = Math.max(
+                0L, System.nanoTime() - mutationCommandStartNanos);
         if (current.state() == PerformanceBlockScene.SceneState.ABSENT) {
             sendBlockSceneRecordForOwner(sender, "mutate", owner.displayName(), current.summary());
             return;
@@ -495,7 +499,14 @@ private static void mutatePerformanceBlockScene(CommandSender sender, String[] a
             snapshot = PerformanceBlockScene.mutate(owner.ownerId(),
                     count == null ? current.placedCount() : count);
         }
-        sendBlockSceneRecordForOwner(sender, "mutate", owner.displayName(), snapshot.summary());
+        long mutationCommandElapsedNanos = Math.max(
+                0L, System.nanoTime() - mutationCommandStartNanos);
+        String commandTiming = " mutationPreflightMs="
+                + String.format(Locale.ROOT, "%.6f", mutationPreflightElapsedNanos / 1_000_000.0D)
+                + " mutationCommandMs="
+                + String.format(Locale.ROOT, "%.6f", mutationCommandElapsedNanos / 1_000_000.0D);
+        sendBlockSceneRecordForOwner(sender, "mutate", owner.displayName(),
+                snapshot.summary() + commandTiming);
     }
 
     private static void inspectPerformanceBlockScene(CommandSender sender, String[] args, boolean clear) {

common/src/main/java/com/loohp/interactionvisualizer/debug/PerformanceBlockScene.java

@@ -127,6 +127,8 @@ public record Snapshot(
             long lastMutationStartBukkitTick,
             long lastMutationEndBukkitTick,
             long lastMutationElapsedNanos,
+            long lastMutationWriteElapsedNanos,
+            long lastMutationInspectionElapsedNanos,
             int restoredCount,
             int skippedExternalCount,
             int restoreFailureCount,
@@ -156,6 +158,8 @@ public String summary() {
                     + " mutationStartBukkitTick=" + lastMutationStartBukkitTick
                     + " mutationEndBukkitTick=" + lastMutationEndBukkitTick
                     + " mutationElapsedMs=" + String.format(Locale.ROOT, "%.6f", lastMutationElapsedNanos / 1_000_000.0D)
+                    + " mutationWriteMs=" + String.format(Locale.ROOT, "%.6f", lastMutationWriteElapsedNanos / 1_000_000.0D)
+                    + " mutationInspectionMs=" + String.format(Locale.ROOT, "%.6f", lastMutationInspectionElapsedNanos / 1_000_000.0D)
                     + " restored=" + restoredCount
                     + " skippedExternal=" + skippedExternalCount
                     + " restoreFailures=" + restoreFailureCount
@@ -482,6 +486,10 @@ private static Snapshot mutate(Session session, int requestedOperations, Mode mo
                 applied++;
             }
         }
+        // Keep the synchronous write loop separate from the ownership/PDC
+        // verification performed by snapshot(). Total mutation time still
+        // includes the small bookkeeping gap between both phases.
+        long writeEndNanos = System.nanoTime();
         session.lastMutationRequested = operations;
         session.lastMutationApplied = applied;
         session.skippedExternalCount = skipped;
@@ -492,7 +500,7 @@ private static Snapshot mutate(Session session, int requestedOperations, Mode mo
                 mode == Mode.ACTIVE ? "vanilla_furnace_events_primed"
                         : mode == Mode.DIRECT_WRITE ? "eventless_direct_write"
                         : "idle_normalized",
-                true, startTick, startNanos);
+                true, startTick, startNanos, writeEndNanos);
     }
 
     private static List<Entry> plan(Player owner, int count) {
@@ -762,14 +770,16 @@ private static List<Block> blocks(List<Entry> entries) {
     }
 
     private static Snapshot snapshot(Session session, SceneState state, String detail) {
-        return snapshot(session, state, detail, false, NO_MUTATION_TICK, 0L);
+        return snapshot(session, state, detail, false, NO_MUTATION_TICK, 0L, 0L);
     }
 
     private static Snapshot snapshot(Session session, SceneState state, String detail,
                                      boolean captureMutationTiming,
-                                     long mutationStartBukkitTick, long mutationStartNanos) {
+                                     long mutationStartBukkitTick, long mutationStartNanos,
+                                     long mutationWriteEndNanos) {
         int owned = 0;
         int unloaded = 0;
+        long inspectionStartNanos = captureMutationTiming ? System.nanoTime() : 0L;
         try {
             for (Entry entry : session.entries) {
                 if (!isLoaded(entry)) {
@@ -780,9 +790,12 @@ private static Snapshot snapshot(Session session, SceneState state, String detai
             }
         } finally {
             if (captureMutationTiming) {
+                long endNanos = System.nanoTime();
                 session.lastMutationStartBukkitTick = mutationStartBukkitTick;
                 session.lastMutationEndBukkitTick = Bukkit.getCurrentTick();
-                session.lastMutationElapsedNanos = Math.max(0L, System.nanoTime() - mutationStartNanos);
+                session.lastMutationElapsedNanos = Math.max(0L, endNanos - mutationStartNanos);
+                session.lastMutationWriteElapsedNanos = Math.max(0L, mutationWriteEndNanos - mutationStartNanos);
+                session.lastMutationInspectionElapsedNanos = Math.max(0L, endNanos - inspectionStartNanos);
             }
         }
         Counts counts = session.counts;
@@ -791,14 +804,15 @@ private static Snapshot snapshot(Session session, SceneState state, String detai
                 owned, unloaded, counts.furnace, counts.blastFurnace, counts.smoker,
                 counts.beeHive, counts.beeNest, session.revision, session.lastMutationRequested,
                 session.lastMutationApplied, session.lastMutationStartBukkitTick, session.lastMutationEndBukkitTick,
-                session.lastMutationElapsedNanos, session.restoredCount, session.skippedExternalCount,
+                session.lastMutationElapsedNanos, session.lastMutationWriteElapsedNanos,
+                session.lastMutationInspectionElapsedNanos, session.restoredCount, session.skippedExternalCount,
                 session.restoreFailureCount, session.inspectionFailureCount, detail);
     }
 
     private static Snapshot absent(UUID ownerId, String detail) {
         return new Snapshot(ownerId, SceneState.ABSENT, null, 0, 0, 0, 0, 0, 0,
                 0, 0, 0, 0, 0, 0L, 0, 0, NO_MUTATION_TICK, NO_MUTATION_TICK,
-                0L, 0, 0, 0, 0, detail);
+                0L, 0L, 0L, 0, 0, 0, 0, detail);
     }
 
     private static Session requireSession(UUID ownerId) {
@@ -877,6 +891,8 @@ private static final class Session {
         private long lastMutationStartBukkitTick;
         private long lastMutationEndBukkitTick;
         private long lastMutationElapsedNanos;
+        private long lastMutationWriteElapsedNanos;
+        private long lastMutationInspectionElapsedNanos;
         private int restoredCount;
         private int skippedExternalCount;
         private int restoreFailureCount;

common/src/test/java/com/loohp/interactionvisualizer/debug/PerformanceBlockSceneSnapshotTest.java

@@ -24,36 +24,45 @@ class PerformanceBlockSceneSnapshotTest {
 
     @Test
     void summaryPublishesLastMutationTickWindowAndElapsedNanos() {
-        PerformanceBlockScene.Snapshot snapshot = snapshot(410L, 411L, 12_345_678L);
+        PerformanceBlockScene.Snapshot snapshot = snapshot(
+                410L, 411L, 12_345_678L, 8_000_000L, 3_000_000L);
 
         assertEquals(410L, snapshot.lastMutationStartBukkitTick());
         assertEquals(411L, snapshot.lastMutationEndBukkitTick());
         assertEquals(12_345_678L, snapshot.lastMutationElapsedNanos());
+        assertEquals(8_000_000L, snapshot.lastMutationWriteElapsedNanos());
+        assertEquals(3_000_000L, snapshot.lastMutationInspectionElapsedNanos());
 
         Map<String, String> fields = summaryFields(snapshot);
         assertEquals("410", fields.get("mutationStartBukkitTick"));
         assertEquals("411", fields.get("mutationEndBukkitTick"));
         assertEquals("12.345678", fields.get("mutationElapsedMs"));
+        assertEquals("8.000000", fields.get("mutationWriteMs"));
+        assertEquals("3.000000", fields.get("mutationInspectionMs"));
     }
 
     @Test
     void summaryKeepsNoMutationSentinelsObservable() {
-        Map<String, String> fields = summaryFields(snapshot(-1L, -1L, 0L));
+        Map<String, String> fields = summaryFields(snapshot(-1L, -1L, 0L, 0L, 0L));
 
         assertEquals("-1", fields.get("mutationStartBukkitTick"));
         assertEquals("-1", fields.get("mutationEndBukkitTick"));
         assertEquals("0.000000", fields.get("mutationElapsedMs"));
+        assertEquals("0.000000", fields.get("mutationWriteMs"));
+        assertEquals("0.000000", fields.get("mutationInspectionMs"));
     }
 
-    private static PerformanceBlockScene.Snapshot snapshot(long startTick, long endTick, long elapsedNanos) {
+    private static PerformanceBlockScene.Snapshot snapshot(long startTick, long endTick, long elapsedNanos,
+                                                           long writeElapsedNanos,
+                                                           long inspectionElapsedNanos) {
         return new PerformanceBlockScene.Snapshot(
                 UUID.fromString("11111111-2222-3333-4444-555555555555"),
                 PerformanceBlockScene.SceneState.READY,
                 PerformanceBlockScene.Mode.DIRECT_WRITE,
                 5, 5, 5, 0, 5, 0,
                 1, 1, 1, 1, 1,
                 7L, 5, 5,
-                startTick, endTick, elapsedNanos,
+                startTick, endTick, elapsedNanos, writeElapsedNanos, inspectionElapsedNanos,
                 0, 0, 0, 0,
                 "eventless_direct_write");
     }

tools/perf/run-phase2-runtime-once.sh

@@ -828,26 +828,68 @@ if scenario == "block-direct-write":
     mutation_start_tick = int(mutate["fields"]["mutationStartBukkitTick"])
     mutation_end_tick = int(mutate["fields"]["mutationEndBukkitTick"])
     mutation_elapsed_ms = float(mutate["fields"]["mutationElapsedMs"])
+    mutation_write_ms = float(mutate["fields"]["mutationWriteMs"])
+    mutation_inspection_ms = float(mutate["fields"]["mutationInspectionMs"])
+    mutation_preflight_ms = float(mutate["fields"]["mutationPreflightMs"])
+    mutation_command_ms = float(mutate["fields"]["mutationCommandMs"])
     if mutation_start_tick < 0 or mutation_end_tick != mutation_start_tick:
         raise SystemExit(
             f"direct-write mutation did not complete synchronously in one Bukkit tick: "
             f"start={mutation_start_tick} end={mutation_end_tick}"
         )
     if not math.isfinite(mutation_elapsed_ms) or mutation_elapsed_ms <= 0:
         raise SystemExit(f"invalid direct-write mutationElapsedMs={mutation_elapsed_ms!r}")
-    for field in ("mutationStartBukkitTick", "mutationEndBukkitTick", "mutationElapsedMs"):
+    if (not math.isfinite(mutation_write_ms) or mutation_write_ms <= 0
+            or mutation_write_ms > mutation_elapsed_ms):
+        raise SystemExit(f"invalid direct-write mutationWriteMs={mutation_write_ms!r}")
+    if (not math.isfinite(mutation_inspection_ms) or mutation_inspection_ms <= 0
+            or mutation_inspection_ms > mutation_elapsed_ms):
+        raise SystemExit(f"invalid direct-write mutationInspectionMs={mutation_inspection_ms!r}")
+    if (not math.isfinite(mutation_command_ms) or mutation_command_ms <= 0
+            or mutation_elapsed_ms > mutation_command_ms):
+        raise SystemExit(f"invalid direct-write mutationCommandMs={mutation_command_ms!r}")
+    if (not math.isfinite(mutation_preflight_ms) or mutation_preflight_ms <= 0
+            or mutation_preflight_ms > mutation_command_ms):
+        raise SystemExit(f"invalid direct-write mutationPreflightMs={mutation_preflight_ms!r}")
+    timing_fields = (
+        "mutationStartBukkitTick",
+        "mutationEndBukkitTick",
+        "mutationElapsedMs",
+        "mutationWriteMs",
+        "mutationInspectionMs",
+    )
+    for field in timing_fields:
         if clear["fields"].get(field) != mutate["fields"].get(field):
             raise SystemExit(f"clear record did not preserve direct-write timing field {field}")
     slowest_tick = int(metrics["msptMaxBukkitTick"])
     slowest_epoch_ms = int(metrics["msptMaxEndEpochMillis"])
     slowest_block_checks = int(metrics["msptMaxBlockUpdateChecks"])
     slowest_block_ms = float(metrics["msptMaxBlockUpdateMs"])
     slowest_ms = float(metrics["msptMax"])
+    if not math.isfinite(slowest_ms) or slowest_ms <= 0:
+        raise SystemExit(f"invalid direct-write msptMax={slowest_ms!r}")
+    if mutation_command_ms > slowest_ms:
+        raise SystemExit(
+            f"direct-write command duration exceeds its completed tick: "
+            f"command={mutation_command_ms!r} tick={slowest_ms!r}"
+        )
+    mutation_unattributed_ms = max(
+        0.0, mutation_elapsed_ms - mutation_write_ms - mutation_inspection_ms
+    )
+    mutation_command_unattributed_ms = max(
+        0.0, mutation_command_ms - mutation_preflight_ms - mutation_elapsed_ms
+    )
     direct_write_diagnostics = {
-        "schemaVersion": 1,
+        "schemaVersion": 2,
         "mutationStartBukkitTick": mutation_start_tick,
         "mutationEndBukkitTick": mutation_end_tick,
         "mutationElapsedMs": mutation_elapsed_ms,
+        "mutationWriteMs": mutation_write_ms,
+        "mutationInspectionMs": mutation_inspection_ms,
+        "mutationUnattributedMs": mutation_unattributed_ms,
+        "mutationPreflightMs": mutation_preflight_ms,
+        "mutationCommandMs": mutation_command_ms,
+        "mutationCommandUnattributedMs": mutation_command_unattributed_ms,
         "slowestBukkitTick": slowest_tick,
         "slowestTickEndEpochMillis": slowest_epoch_ms,
         "slowestTickMs": slowest_ms,
@@ -857,6 +899,18 @@ if scenario == "block-direct-write":
         "mutationFractionOfSlowestTick": (
             mutation_elapsed_ms / slowest_ms if slowest_ms > 0 else None
         ),
+        "mutationWriteFractionOfSlowestTick": (
+            mutation_write_ms / slowest_ms if slowest_ms > 0 else None
+        ),
+        "mutationInspectionFractionOfSlowestTick": (
+            mutation_inspection_ms / slowest_ms if slowest_ms > 0 else None
+        ),
+        "mutationPreflightFractionOfSlowestTick": (
+            mutation_preflight_ms / slowest_ms if slowest_ms > 0 else None
+        ),
+        "mutationCommandFractionOfSlowestTick": (
+            mutation_command_ms / slowest_ms if slowest_ms > 0 else None
+        ),
         "blockUpdateFractionOfSlowestTick": (
             slowest_block_ms / slowest_ms if slowest_ms > 0 else None
         ),
@@ -869,7 +923,7 @@ elif clear_revision != create_revision:
     )
 
 evidence = {
-    "schemaVersion": 2,
+    "schemaVersion": 3,
     "scenario": scenario,
     "formalEvidenceReady": True,
     "records": {"create": create, "mutate": mutate, "clear": clear},