diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 4c78f12ca..dbcbf5cc5 100644 --- a/.github/workflows/ci.yml +++ b/.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 diff --git a/README.md b/README.md index 6ed597b72..dfe28d336 100644 --- a/README.md +++ b/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. diff --git a/docs/profiling.md b/docs/profiling.md new file mode 100644 index 000000000..5ec1f2009 --- /dev/null +++ b/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. diff --git a/tests/java/JfrFixture.java b/tests/java/JfrFixture.java new file mode 100644 index 000000000..43280794e --- /dev/null +++ b/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])); + } + } +} diff --git a/tests/test_lab.py b/tests/test_lab.py index 02f03e47b..7b2ae4c1f 100644 --- a/tests/test_lab.py +++ b/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: diff --git a/tools/JfrSummary.java b/tools/JfrSummary.java new file mode 100644 index 000000000..aa216bff7 --- /dev/null +++ b/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 result(long id) { + var row = new LinkedHashMap(); + 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 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(); + 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 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> top(Map counts) { + return counts.entrySet().stream() + .sorted(Map.Entry.comparingByValue().reversed().thenComparing(Map.Entry.comparingByKey())) + .limit(15).map(e -> Map.of("method", e.getKey(), "samples", e.getValue())).toList(); + } + + static Map summarize(Path path) throws Exception { + Map allocations = new HashMap<>(); + Map 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> allocationRows = new ArrayList<>(); + allocations.forEach((id, allocation) -> allocationRows.add(allocation.result(id))); + allocationRows.sort(Comparator.>comparingLong(r -> + r.get("observed_allocated_bytes") instanceof Long bytes ? bytes : -1).reversed() + .thenComparingLong(r -> (Long) r.get("thread_id"))); + var result = new LinkedHashMap(); + 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> sampleRows(Map samples) { + return samples.entrySet().stream().sorted(Comparator.>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])))); + } +} diff --git a/tools/check_public_tree.py b/tools/check_public_tree.py index 194108227..26c47f4e8 100644 --- a/tools/check_public_tree.py +++ b/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 diff --git a/tools/test_jfr.py b/tools/test_jfr.py new file mode 100644 index 000000000..d40bda06e --- /dev/null +++ b/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()