Stream private JFR profiles and verify allocation counters across platforms

.github/workflows/ci.yml

@@ -42,6 +42,8 @@ jobs:
           java-version: '25'
       - name: Compile original mod and test metrics
         run: python tools/build_mod.py
+      - name: Verify streaming JFR analysis against the JDK exporter
+        run: python tools/test_jfr.py
       - name: Build pinned portable packs
         run: python tools/build_pack.py
       - name: Measure isolated worker pacing on this platform

README.md

@@ -60,6 +60,10 @@ Open `Compare-Benchmarks.html` from the starter ZIP or [the source file](tools/C
 
 The comparison flags captured setting differences, but cannot verify route, world, shader state or cache warm-up. See [validation evidence](docs/playable-validation.md). Software-renderer test FPS is not evidence of a Mac/GPU speedup.
 
+For CPU/allocation investigation, [capture and stream a private JFR summary](docs/profiling.md).
+It distinguishes directly observed allocation counters from sampled hot methods;
+profiling runs remain separate from normal timing comparisons.
+
 ## Build and run
 
 Requires Python 3.10+ and JDK 25. No Gradle, Rust or native compilation is required for playable packs.

docs/profiling.md

@@ -0,0 +1,81 @@
+# Find the next bottleneck
+
+Frame and tick recordings describe player-visible timings. A private Java Flight
+Recorder capture helps identify the code doing work or allocating objects. Use
+native Java 25, with `jcmd` and `java` from a JDK. Keep normal benchmark runs separate
+from profiling runs because sampling adds overhead.
+
+With the game running and your test world warmed up, find its Java process ID
+using Activity Monitor on macOS, Task Manager on Windows, or your process monitor
+on Linux. Create the `.local/profiles/` directory inside this checkout first.
+Then use a terminal inside the repository:
+
+```sh
+# Replace 12345 with the game's Java PID and use your own absolute .local path.
+jcmd 12345 JFR.start name=horizon settings=profile duration=120s filename=/absolute/path/to/repo/.local/profiles/mac.jfr
+```
+
+Keep the same route, resolution, heap, collector and video settings used for your
+timing tests. Wait for the capture to finish, then stream a selected summary:
+
+```sh
+java tools/JfrSummary.java .local/profiles/mac.jfr > .local/profiles/mac-summary.json
+```
+
+The tool needs only the JDK. It reads events sequentially without expanding every
+stack frame's class-loader metadata into a large intermediate JSON dump. Its
+selected output does not extract JVM command-line arguments, environment
+properties, file events or raw payloads. It includes thread and method labels.
+Raw JFR recordings can contain other private
+environment data; keep them and their summaries under gitignored `.local/`.
+
+## Interpret the fields
+
+`allocation_threads` contains directly observed per-thread allocation-counter
+differences. Each row has its own observation span and count. Thread startup,
+exit and intervals outside those counters are not included. A single observation
+or unusable interval produces null bytes/rate, rather than a manufactured zero.
+Compare observation spans before comparing allocation totals. Allocated bytes
+are temporary and retained objects together, not resident RAM or retained heap.
+
+`execution_threads` counts Java execution and native-method stack samples. Leaf
+methods locate the sampled frame; inclusive methods count a sample once for each
+method appearing anywhere in its stack, including recursion. Samples are hints
+for further profiling, not exact CPU time, GPU time or elapsed-time fractions.
+Missing/truncated stacks are counted. Method descriptors distinguish overloads.
+
+`allocation_sample_threads` locates allocation stacks by sample count. It does
+not sum JFR allocation sample weights. Earlier investigation found those weights
+misleading as a substitute for the directly observed thread counters. Different
+object types and sampling behavior make sample counts unsuitable for estimating
+allocated bytes or proving that one object type owns most of the allocation.
+
+GC pause totals/maximum use top-level `jdk.GCPhasePause`, excluding nested phases
+and concurrent collection-cycle duration. `gc_cycles` is a separate count.
+`heap_used_peak_at_gc_bytes` considers recorded GC heap summaries and can miss
+peaks between collections. It is separate from the game's once-per-second heap
+and process-RSS measurements.
+
+The reader ignores unselected event types and never extracts properties or
+arguments. `event_span_seconds` is the span of all observed event timestamps,
+which can differ from the requested capture duration; each allocation row reports
+its actual counter interval separately.
+
+## Verify the reader
+
+```sh
+python3 tools/test_jfr.py
+```
+
+This creates a real JDK recording of bounded allocations and GC, then compares
+the reader's counter differences, observation counts, GC counts and heap summaries
+against `jfr print --json`. It also verifies escaped thread names and that sampled
+weights do not appear as numeric allocation totals. CI runs it on Windows, Linux
+and Apple Silicon macOS. The reader was independently checked against the older
+real-game profile's JDK JSON export for 85 threads.
+
+The post-queue software-rendered profile confirms remaining allocations on the
+integrated-server and chunk-meshing threads. It is not a matched comparison with
+the older capture: world/cache state, heap and object-header flags differ. It
+cannot establish M2 frame gains. Mac captures are needed before choosing a larger
+renderer or native-kernel replacement.

tests/java/JfrFixture.java

@@ -0,0 +1,30 @@
+import java.nio.file.Path;
+import java.time.Duration;
+import jdk.jfr.Recording;
+
+/** Produces real JDK counter/GC events for the reader's independent integration check. */
+public final class JfrFixture {
+    private static volatile Object[] retained;
+    public static void main(String[] args) throws Exception {
+        Thread.currentThread().setName("Horizon JFR fixture \"quoted\"\tthread");
+        try (var recording = new Recording()) {
+            recording.enable("jdk.ThreadAllocationStatistics").withPeriod(Duration.ofMillis(100));
+            recording.enable("jdk.ExecutionSample").withPeriod(Duration.ofMillis(10));
+            recording.enable("jdk.ObjectAllocationSample").withStackTrace();
+            recording.enable("jdk.GarbageCollection");
+            recording.enable("jdk.GCPhasePause");
+            recording.enable("jdk.GCHeapSummary");
+            recording.start();
+            for (int batch = 0; batch < 12; batch++) {
+                Object[] objects = new Object[100_000];
+                for (int i = 0; i < objects.length; i++) objects[i] = new byte[32 + (i % 8)];
+                retained = objects;
+                Thread.sleep(120);
+            }
+            System.gc();
+            Thread.sleep(250);
+            recording.stop();
+            recording.dump(Path.of(args[0]));
+        }
+    }
+}

tests/test_lab.py

@@ -102,6 +102,10 @@ class PublicationTests(unittest.TestCase):
                      "mods/horizon-lab/src/main/java/dev/horizonlab/HorizonLab.java"]:
             self.assertFalse(check_public_tree.prohibited(path), path)
         self.assertTrue(check_public_tree.prohibited("mods/horizon-lab/src/main/java/net/minecraft/Client.java"))
+        for path in ["tools/JfrSummary.java", "tests/java/JfrFixture.java"]:
+            self.assertFalse(check_public_tree.prohibited(path), path)
+        for path in ["tools/Minecraft.java", "tests/java/Client.java", ".local/tools/JfrSummary.java"]:
+            self.assertTrue(check_public_tree.prohibited(path), path)
 
     def test_force_added_ignored_file_is_detected_in_index_and_history(self):
         with tempfile.TemporaryDirectory() as temp:

tools/JfrSummary.java

@@ -0,0 +1,178 @@
+import java.nio.file.Path;
+import java.time.Duration;
+import java.time.Instant;
+import java.util.ArrayList;
+import java.util.Comparator;
+import java.util.HashMap;
+import java.util.LinkedHashMap;
+import java.util.List;
+import java.util.Map;
+import jdk.jfr.consumer.RecordedEvent;
+import jdk.jfr.consumer.RecordedThread;
+import jdk.jfr.consumer.RecordingFile;
+
+/** Streams a private JFR without expanding class loaders or exporting command-line arguments. */
+public final class JfrSummary {
+    static final class Allocation {
+        String name;
+        Instant firstTime, lastTime;
+        long firstBytes, lastBytes, observations;
+        boolean invalid;
+        void add(Instant time, long bytes, String label) {
+            name = label;
+            observations++;
+            if (bytes < 0) invalid = true;
+            if (firstTime == null || time.isBefore(firstTime)) { firstTime = time; firstBytes = bytes; }
+            if (lastTime == null || time.isAfter(lastTime)) { lastTime = time; lastBytes = bytes; }
+            if (firstTime.equals(lastTime) && firstBytes != lastBytes) invalid = true;
+        }
+        Map<String, Object> result(long id) {
+            var row = new LinkedHashMap<String, Object>();
+            row.put("thread_id", id);
+            row.put("thread", name);
+            row.put("counter_observations", observations);
+            double span = Duration.between(firstTime, lastTime).toNanos() / 1e9;
+            row.put("observed_seconds", span);
+            boolean valid = !invalid && observations > 1 && span > 0 && lastBytes >= firstBytes;
+            row.put("observed_allocated_bytes", valid ? lastBytes - firstBytes : null);
+            row.put("observed_bytes_per_second", valid ? (lastBytes - firstBytes) / span : null);
+            return row;
+        }
+    }
+
+    static final class Samples {
+        String name;
+        long count, missingStacks, truncatedStacks;
+        final Map<String, Long> leaf = new HashMap<>(), inclusive = new HashMap<>();
+        void add(RecordedEvent event, String label) {
+            name = label;
+            count++;
+            var stack = event.getStackTrace();
+            if (stack == null || stack.getFrames().isEmpty()) { missingStacks++; return; }
+            if (stack.isTruncated()) truncatedStacks++;
+            var methods = new java.util.HashSet<String>();
+            for (var frame : stack.getFrames()) {
+                var method = frame.getMethod();
+                methods.add(method.getType().getName() + "." + method.getName() + method.getDescriptor());
+            }
+            for (String method : methods) inclusive.merge(method, 1L, Long::sum);
+            var method = stack.getFrames().getFirst().getMethod();
+            leaf.merge(method.getType().getName() + "." + method.getName() + method.getDescriptor(), 1L, Long::sum);
+        }
+        Map<String, Object> result(long id) {
+            return Map.of("thread_id", id, "thread", name, "samples", count,
+                "missing_stacks", missingStacks, "truncated_stacks", truncatedStacks,
+                "top_leaf_methods", top(leaf), "top_inclusive_methods", top(inclusive));
+        }
+    }
+
+    static long threadId(RecordedThread thread) {
+        return thread.getJavaThreadId() > 0 ? thread.getJavaThreadId() : -thread.getId();
+    }
+
+    static String threadName(RecordedThread thread) {
+        if (thread.getJavaName() != null) return thread.getJavaName();
+        return thread.getOSName() == null ? "unnamed thread" : thread.getOSName();
+    }
+
+    static List<Map<String, Object>> top(Map<String, Long> counts) {
+        return counts.entrySet().stream()
+            .sorted(Map.Entry.<String, Long>comparingByValue().reversed().thenComparing(Map.Entry.comparingByKey()))
+            .limit(15).map(e -> Map.<String, Object>of("method", e.getKey(), "samples", e.getValue())).toList();
+    }
+
+    static Map<String, Object> summarize(Path path) throws Exception {
+        Map<Long, Allocation> allocations = new HashMap<>();
+        Map<Long, Samples> execution = new HashMap<>(), allocationSamples = new HashMap<>();
+        long events = 0, gcCycles = 0, pauseCount = 0, heapPeak = 0;
+        double pauseMs = 0, longestPauseMs = 0;
+        Instant first = null, last = null;
+        try (var recording = new RecordingFile(path)) {
+            while (recording.hasMoreEvents()) {
+                var event = recording.readEvent();
+                events++;
+                Instant time = event.getStartTime();
+                if (first == null || time.isBefore(first)) first = time;
+                Instant end = event.getEndTime();
+                if (last == null || end.isAfter(last)) last = end;
+                switch (event.getEventType().getName()) {
+                    case "jdk.ThreadAllocationStatistics" -> {
+                        RecordedThread thread = event.getThread("thread");
+                        if (thread != null) allocations.computeIfAbsent(threadId(thread), k -> new Allocation())
+                            .add(time, event.getLong("allocated"), threadName(thread));
+                    }
+                    case "jdk.ExecutionSample", "jdk.NativeMethodSample", "jdk.ObjectAllocationSample" -> {
+                        boolean allocation = event.getEventType().getName().equals("jdk.ObjectAllocationSample");
+                        RecordedThread thread = event.getThread(allocation ? "eventThread" : "sampledThread");
+                        if (thread != null) (allocation ? allocationSamples : execution)
+                            .computeIfAbsent(threadId(thread), k -> new Samples()).add(event, threadName(thread));
+                    }
+                    case "jdk.GarbageCollection" -> gcCycles++;
+                    case "jdk.GCPhasePause" -> {
+                        double ms = event.getDuration().toNanos() / 1e6;
+                        pauseMs += ms;
+                        longestPauseMs = Math.max(longestPauseMs, ms);
+                        pauseCount++;
+                    }
+                    case "jdk.GCHeapSummary" -> heapPeak = Math.max(heapPeak, event.getLong("heapUsed"));
+                    default -> { }
+                }
+            }
+        }
+        List<Map<String, Object>> allocationRows = new ArrayList<>();
+        allocations.forEach((id, allocation) -> allocationRows.add(allocation.result(id)));
+        allocationRows.sort(Comparator.<Map<String, Object>>comparingLong(r ->
+            r.get("observed_allocated_bytes") instanceof Long bytes ? bytes : -1).reversed()
+            .thenComparingLong(r -> (Long) r.get("thread_id")));
+        var result = new LinkedHashMap<String, Object>();
+        result.put("schema", 1);
+        result.put("events_read", events);
+        result.put("event_span_seconds", first == null ? 0 : Duration.between(first, last).toNanos() / 1e9);
+        result.put("allocation_threads", allocationRows);
+        result.put("execution_threads", sampleRows(execution));
+        result.put("allocation_sample_threads", sampleRows(allocationSamples));
+        result.put("gc_cycles", gcCycles);
+        result.put("gc_pause_events", pauseCount);
+        result.put("gc_pause_total_ms", pauseMs);
+        result.put("gc_pause_longest_ms", longestPauseMs);
+        result.put("heap_used_peak_at_gc_bytes", heapPeak == 0 ? null : heapPeak);
+        result.put("notes", List.of(
+            "Allocation bytes are differences between directly observed per-thread counters, with separate observation spans. Thread startup/exit gaps are not covered; missing intervals are null.",
+            "Execution/native-method samples locate sampled stacks, not exact CPU time, GPU work or elapsed-time fractions. Inclusive methods count each sample once even during recursion.",
+            "Allocation stack samples are counts only. Sample weights are deliberately excluded; counts are not allocated bytes or retained RAM.",
+            "GC pause fields use top-level GCPhasePause events, excluding concurrent cycle duration and nested pause phases. GC heap peaks can miss between-GC peaks.",
+            "Profiling changes workload overhead. Keep raw recordings private; they may contain environment details beyond this selected summary."));
+        return result;
+    }
+
+    static List<Map<String, Object>> sampleRows(Map<Long, Samples> samples) {
+        return samples.entrySet().stream().sorted(Comparator.<Map.Entry<Long, Samples>>comparingLong(e -> e.getValue().count)
+            .reversed().thenComparingLong(Map.Entry::getKey)).map(e -> e.getValue().result(e.getKey())).toList();
+    }
+
+    static String json(Object value) {
+        if (value == null) return "null";
+        if (value instanceof String string) {
+            var out = new StringBuilder("\"");
+            for (int i = 0; i < string.length(); i++) {
+                char c = string.charAt(i);
+                if (c == '"' || c == '\\') out.append('\\').append(c);
+                else if (c < 32) out.append(String.format(java.util.Locale.ROOT, "\\u%04x", (int) c));
+                else out.append(c);
+            }
+            return out.append('"').toString();
+        }
+        if (value instanceof Number || value instanceof Boolean) return value.toString();
+        if (value instanceof Map<?, ?> map) return map.entrySet().stream()
+            .map(e -> json(e.getKey().toString()) + ":" + json(e.getValue()))
+            .collect(java.util.stream.Collectors.joining(",", "{", "}"));
+        if (value instanceof List<?> list) return list.stream().map(JfrSummary::json)
+            .collect(java.util.stream.Collectors.joining(",", "[", "]"));
+        throw new IllegalArgumentException("Unsupported JSON value");
+    }
+
+    public static void main(String[] args) throws Exception {
+        if (args.length != 1) throw new IllegalArgumentException("Usage: java tools/JfrSummary.java private-recording.jfr");
+        System.out.println(json(summarize(Path.of(args[0]))));
+    }
+}

tools/check_public_tree.py

@@ -8,11 +8,15 @@ import sys
 
 PRIVATE_ROOTS = {".local", "decompiled", "minecraft", "assets", "run", "logs"}
 PRIVATE_EXTENSIONS = {".jar", ".class", ".jfr", ".hprof", ".java"}
+ORIGINAL_JDK_TOOLS = {"tools/JfrSummary.java", "tests/java/JfrFixture.java"}
 
 
 def prohibited(path):
     parsed = PurePosixPath(path)
-    # Only original Horizon Lab sources may be tracked; recovered game Java stays private.
+    # Original JDK-only tools are an exact allowlist; recovered game Java stays private.
+    if path in ORIGINAL_JDK_TOOLS:
+        return False
+    # Original Horizon Lab mod sources may also be tracked.
     if parsed.suffix == ".java" and path.startswith("mods/horizon-lab/src/"):
         return not ("/dev/horizonlab/" in path)
     return bool(parsed.parts and parsed.parts[0] in PRIVATE_ROOTS) or parsed.suffix.lower() in PRIVATE_EXTENSIONS

tools/test_jfr.py

@@ -0,0 +1,68 @@
+#!/usr/bin/env python3
+"""Verify the streaming JFR reader against the JDK's own JSON exporter."""
+
+import json
+from pathlib import Path
+import subprocess
+
+ROOT = Path(__file__).resolve().parents[1]
+BUILD = ROOT / ".local/jfr-tests"
+
+
+def main():
+    BUILD.mkdir(parents=True, exist_ok=True)
+    fixture = BUILD / "fixture.jfr"
+    subprocess.run(["java", "-Xmx128M", str(ROOT / "tests/java/JfrFixture.java"), str(fixture)], check=True)
+    summary = json.loads(subprocess.check_output(
+        ["java", str(ROOT / "tools/JfrSummary.java"), str(fixture)], text=True))
+    events = json.loads(subprocess.check_output(
+        ["jfr", "print", "--json", "--stack-depth", "1", "--events",
+         "jdk.ThreadAllocationStatistics,jdk.GarbageCollection,jdk.GCPhasePause,jdk.GCHeapSummary,jdk.ExecutionSample,jdk.NativeMethodSample,jdk.ObjectAllocationSample", str(fixture)],
+        text=True))["recording"]["events"]
+    counters = {}
+    for event in events:
+        values = event["values"]
+        if event["type"] == "jdk.ThreadAllocationStatistics" and values["thread"]:
+            thread = values["thread"]
+            key = thread["javaThreadId"]
+            counters.setdefault(key, []).append((values["startTime"], values["allocated"]))
+    for row in summary["allocation_threads"]:
+        samples = sorted(counters[row["thread_id"]])
+        assert row["counter_observations"] == len(samples)
+        if len(samples) > 1 and samples[0][0] != samples[-1][0]:
+            assert row["observed_allocated_bytes"] == samples[-1][1] - samples[0][1]
+            assert row["observed_seconds"] > 0
+        else:
+            assert row["observed_allocated_bytes"] is None
+    fixture_row = next(row for row in summary["allocation_threads"] if row["thread"].startswith("Horizon JFR fixture"))
+    assert '"quoted"\tthread' in fixture_row["thread"]
+    assert fixture_row["observed_allocated_bytes"] > 1_000_000
+    assert summary["gc_cycles"] == sum(e["type"] == "jdk.GarbageCollection" for e in events)
+    assert summary["gc_pause_events"] == sum(e["type"] == "jdk.GCPhasePause" for e in events)
+    assert summary["heap_used_peak_at_gc_bytes"] == max(
+        e["values"]["heapUsed"] for e in events if e["type"] == "jdk.GCHeapSummary")
+    for key, types in [("execution_threads", {"jdk.ExecutionSample", "jdk.NativeMethodSample"}),
+                       ("allocation_sample_threads", {"jdk.ObjectAllocationSample"})]:
+        expected = {}
+        for event in events:
+            if event["type"] not in types:
+                continue
+            field = "eventThread" if event["type"] == "jdk.ObjectAllocationSample" else "sampledThread"
+            thread = event["values"][field]
+            if thread:
+                expected[thread["javaThreadId"]] = expected.get(thread["javaThreadId"], 0) + 1
+        assert {row["thread_id"]: row["samples"] for row in summary[key]} == expected
+    def no_weight_keys(value):
+        if isinstance(value, dict):
+            assert "weight" not in value and "weighted_bytes" not in value
+            for child in value.values():
+                no_weight_keys(child)
+        elif isinstance(value, list):
+            for child in value:
+                no_weight_keys(child)
+    no_weight_keys(summary)
+    print("Streaming JFR summary matches real JDK allocation counters, stack-sample counts, GC event counts, heap observations and escaped thread names.")
+
+
+if __name__ == "__main__":
+    main()