From 9f147a2733afdde69ab100be664103bd85513570 Mon Sep 17 00:00:00 2001 From: rlaope Date: Sun, 12 Apr 2026 21:45:01 +0900 Subject: [PATCH] feat: GC pause phase breakdown from debug logs (#115) Add phase-level timing extraction from JDK 17+ unified debug GC logs (-Xlog:gc*=debug). Parses [gc,phases] entries to show per-phase avg/max duration and percentage of total pause. - GcPhaseEvent: data class for phase timing per GC cycle - GcPhaseAnalyzer: aggregates phases across GCs into stats - GcLogParser.parseWithPhases(): extracts both events and phases - GcLogCommand --phases: renders bar-chart phase breakdown Signed-off-by: rlaope --- .../io/argus/cli/command/GcLogCommand.java | 57 ++++++++- .../java/io/argus/cli/gclog/GcLogParser.java | 53 ++++++++ .../io/argus/cli/gclog/GcPhaseAnalyzer.java | 54 +++++++++ .../java/io/argus/cli/gclog/GcPhaseEvent.java | 22 ++++ .../argus/cli/gclog/GcPhaseAnalyzerTest.java | 114 ++++++++++++++++++ 5 files changed, 296 insertions(+), 4 deletions(-) create mode 100644 argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseAnalyzer.java create mode 100644 argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseEvent.java create mode 100644 argus-cli/src/test/java/io/argus/cli/gclog/GcPhaseAnalyzerTest.java diff --git a/argus-cli/src/main/java/io/argus/cli/command/GcLogCommand.java b/argus-cli/src/main/java/io/argus/cli/command/GcLogCommand.java index 629a849..ac80f5a 100644 --- a/argus-cli/src/main/java/io/argus/cli/command/GcLogCommand.java +++ b/argus-cli/src/main/java/io/argus/cli/command/GcLogCommand.java @@ -54,16 +54,25 @@ public void execute(String[] args, CliConfig config, ProviderRegistry registry, boolean json = "json".equals(config.format()); boolean useColor = config.color(); boolean flagsOnly = false; + boolean showPhases = false; String exportHtml = null; for (int i = 1; i < args.length; i++) { if (args[i].equals("--format=json")) json = true; if (args[i].equals("--suggest-flags")) flagsOnly = true; if (args[i].startsWith("--export=")) exportHtml = args[i].substring(9); + if (args[i].equals("--phases")) showPhases = true; } List events; + List phaseEvents = List.of(); try { - events = GcLogParser.parse(logFile); + if (showPhases) { + GcLogParser.ParseResult result = GcLogParser.parseWithPhases(logFile); + events = result.events(); + phaseEvents = result.phases(); + } else { + events = GcLogParser.parse(logFile); + } } catch (IOException e) { System.err.println("Failed to read GC log: " + e.getMessage()); return; @@ -92,7 +101,7 @@ public void execute(String[] args, CliConfig config, ProviderRegistry registry, PrintStream original = System.out; ByteArrayOutputStream capture = new ByteArrayOutputStream(); System.setOut(new PrintStream(capture)); - printRich(analysis, events, logFile, true); + printRich(analysis, events, phaseEvents, logFile, true); System.setOut(original); String html = HtmlExporter.toHtml(capture.toString(), "Argus GC Log Analysis — " + logFile.getFileName()); try { @@ -105,10 +114,12 @@ public void execute(String[] args, CliConfig config, ProviderRegistry registry, return; } - printRich(analysis, events, logFile, useColor); + printRich(analysis, events, phaseEvents, logFile, useColor); } - private void printRich(GcLogAnalysis a, List events, Path file, boolean c) { + private void printRich(GcLogAnalysis a, List events, + List phaseEvents, + Path file, boolean c) { System.out.print(RichRenderer.brandedHeader(c, "gclog", "GC log analysis with tuning recommendations")); System.out.println(RichRenderer.boxHeader(c, "GC Log Analysis", WIDTH, @@ -271,10 +282,48 @@ private void printRich(GcLogAnalysis a, List events, Path file, boolean } } + // Phase Breakdown (only when --phases flag used and phase data available) + if (!phaseEvents.isEmpty()) { + GcPhaseAnalyzer.PhaseAnalysis phaseAnalysis = GcPhaseAnalyzer.analyze(phaseEvents); + if (!phaseAnalysis.phases().isEmpty()) { + printPhaseBreakdown(c, phaseAnalysis); + } + } + System.out.println(RichRenderer.boxFooter(c, a.pauseEvents() + " pauses, " + String.format("%.1f%%", a.throughputPercent()) + " throughput", WIDTH)); } + private void printPhaseBreakdown(boolean c, GcPhaseAnalyzer.PhaseAnalysis analysis) { + section(c, String.format("GC Pause Phase Breakdown (avg of %d GCs)", analysis.gcCount())); + + // Bar chart: max bar width = 20 chars for 100% + int BAR_WIDTH = 20; + for (GcPhaseAnalyzer.PhaseStat stat : analysis.phases()) { + int barLen = (int) Math.round(stat.percentOfTotal() / 100.0 * BAR_WIDTH); + String bar = AnsiStyle.style(c, AnsiStyle.CYAN) + + "\u2588".repeat(Math.max(0, barLen)) + + AnsiStyle.style(c, AnsiStyle.RESET); + String row = " " + + RichRenderer.padRight(RichRenderer.truncate(stat.phase(), 22), 22) + + String.format("%6.1fms ", stat.avgMs()) + + RichRenderer.padRight(bar, BAR_WIDTH + 20) // +20 for ANSI escape codes + + String.format("%3.0f%%", stat.percentOfTotal()); + System.out.println(RichRenderer.boxLine(row, WIDTH)); + } + + // Total row + double totalAvg = analysis.phases().stream() + .mapToDouble(GcPhaseAnalyzer.PhaseStat::avgMs).sum(); + System.out.println(RichRenderer.emptyLine(WIDTH)); + System.out.println(RichRenderer.boxLine( + " " + AnsiStyle.style(c, AnsiStyle.BOLD) + + RichRenderer.padRight("Total", 22) + + String.format("%6.1fms", totalAvg) + + AnsiStyle.style(c, AnsiStyle.RESET) + + RichRenderer.padLeft("100%", BAR_WIDTH + 25), WIDTH)); + } + private void section(boolean c, String title) { System.out.println(RichRenderer.emptyLine(WIDTH)); System.out.println(RichRenderer.boxSeparator(WIDTH)); diff --git a/argus-cli/src/main/java/io/argus/cli/gclog/GcLogParser.java b/argus-cli/src/main/java/io/argus/cli/gclog/GcLogParser.java index add12ad..105922a 100644 --- a/argus-cli/src/main/java/io/argus/cli/gclog/GcLogParser.java +++ b/argus-cli/src/main/java/io/argus/cli/gclog/GcLogParser.java @@ -45,6 +45,59 @@ public final class GcLogParser { private static final Pattern UNIFIED_CONCURRENT = Pattern.compile( "GC\\(\\d+\\)\\s+Concurrent\\s+(\\S+)\\s+(\\d+\\.?\\d*)ms"); + // JDK 17+ debug phase: [debug][gc,phases] GC(0) Pre Evacuate Collection Set: 0.1ms + private static final Pattern GC_PHASE = Pattern.compile( + "GC\\((\\d+)\\)\\s+(.+?):\\s+(\\d+\\.?\\d*)ms"); + + /** + * Result container for phase-aware parsing. + */ + public record ParseResult(List events, List phases) {} + + /** + * Parse GC log file and also extract phase breakdown from debug gc,phases lines. + * Requires -Xlog:gc*=debug output. Phase lines have [gc,phases] tag. + */ + public static ParseResult parseWithPhases(Path logFile) throws IOException { + List events = new ArrayList<>(); + List phases = new ArrayList<>(); + boolean unified = false; + boolean formatDetected = false; + + try (BufferedReader reader = Files.newBufferedReader(logFile)) { + String line; + while ((line = reader.readLine()) != null) { + if (!formatDetected && !line.isBlank()) { + unified = line.contains("[gc") || line.contains("[info]") + || line.startsWith("[") && (line.contains("s]") || line.contains("T")); + formatDetected = true; + } + + // Phase lines: must contain gc,phases tag + if (line.contains("gc,phases")) { + GcPhaseEvent phase = parsePhraseLine(line); + if (phase != null) { + phases.add(phase); + continue; + } + } + + GcEvent event = unified ? parseUnifiedLine(line) : parseLegacyLine(line); + if (event != null) events.add(event); + } + } + return new ParseResult(events, phases); + } + + private static GcPhaseEvent parsePhraseLine(String line) { + Matcher m = GC_PHASE.matcher(line); + if (!m.find()) return null; + int gcId = Integer.parseInt(m.group(1)); + String phase = m.group(2).trim(); + double durationMs = Double.parseDouble(m.group(3)); + return new GcPhaseEvent(gcId, phase, durationMs); + } + /** * Parse GC log file using streaming reader. Handles multi-GB files. */ diff --git a/argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseAnalyzer.java b/argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseAnalyzer.java new file mode 100644 index 0000000..6ca7db6 --- /dev/null +++ b/argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseAnalyzer.java @@ -0,0 +1,54 @@ +package io.argus.cli.gclog; + +import java.util.*; + +/** + * Aggregates GC phase events across multiple GC cycles and produces per-phase statistics. + * Groups by GC ID first, then aggregates across all GCs to produce avg/max duration and + * percentage of total pause time per phase. + */ +public final class GcPhaseAnalyzer { + + public static PhaseAnalysis analyze(List phases) { + if (phases.isEmpty()) { + return new PhaseAnalysis(List.of(), 0); + } + + // Aggregate per-phase: sum, max, count across all GC IDs + Map accumulator = new LinkedHashMap<>(); + // value: [sum, max, count] + for (GcPhaseEvent e : phases) { + double[] acc = accumulator.computeIfAbsent(e.phase(), k -> new double[3]); + acc[0] += e.durationMs(); + if (e.durationMs() > acc[1]) acc[1] = e.durationMs(); + acc[2] += 1; + } + + // Count distinct GC IDs to report "avg of N GCs" + Set gcIds = new HashSet<>(); + for (GcPhaseEvent e : phases) gcIds.add(e.gcId()); + int gcCount = gcIds.size(); + + // Total average pause across all phases for a single GC cycle + // = sum of per-phase averages + double totalAvgMs = 0; + for (double[] acc : accumulator.values()) { + totalAvgMs += acc[0] / acc[2]; // avg per GC for this phase + } + + List stats = new ArrayList<>(); + for (Map.Entry entry : accumulator.entrySet()) { + double[] acc = entry.getValue(); + double avg = acc[0] / acc[2]; + double max = acc[1]; + double pct = totalAvgMs > 0 ? avg / totalAvgMs * 100.0 : 0.0; + stats.add(new PhaseStat(entry.getKey(), avg, max, pct)); + } + + return new PhaseAnalysis(Collections.unmodifiableList(stats), gcCount); + } + + public record PhaseAnalysis(List phases, int gcCount) {} + + public record PhaseStat(String phase, double avgMs, double maxMs, double percentOfTotal) {} +} diff --git a/argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseEvent.java b/argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseEvent.java new file mode 100644 index 0000000..e37910e --- /dev/null +++ b/argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseEvent.java @@ -0,0 +1,22 @@ +package io.argus.cli.gclog; + +/** + * A single GC phase entry from JDK 17+ debug GC logs (-Xlog:gc*=debug). + * Example source line: + * [0.234s][debug][gc,phases] GC(0) Pre Evacuate Collection Set: 0.1ms + */ +public final class GcPhaseEvent { + private final int gcId; + private final String phase; + private final double durationMs; + + public GcPhaseEvent(int gcId, String phase, double durationMs) { + this.gcId = gcId; + this.phase = phase; + this.durationMs = durationMs; + } + + public int gcId() { return gcId; } + public String phase() { return phase; } + public double durationMs() { return durationMs; } +} diff --git a/argus-cli/src/test/java/io/argus/cli/gclog/GcPhaseAnalyzerTest.java b/argus-cli/src/test/java/io/argus/cli/gclog/GcPhaseAnalyzerTest.java new file mode 100644 index 0000000..1c548da --- /dev/null +++ b/argus-cli/src/test/java/io/argus/cli/gclog/GcPhaseAnalyzerTest.java @@ -0,0 +1,114 @@ +package io.argus.cli.gclog; + +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; + +import java.io.IOException; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.List; + +import static org.junit.jupiter.api.Assertions.*; + +class GcPhaseAnalyzerTest { + + @TempDir Path tempDir; + + @Test + void parsePhaseEvents_fromDebugLog() throws IOException { + String log = """ + [0.234s][debug][gc,phases] GC(0) Pre Evacuate Collection Set: 0.1ms + [0.234s][debug][gc,phases] GC(0) Merge Heap Roots: 0.3ms + [0.234s][debug][gc,phases] GC(0) Evacuate Collection Set: 5.2ms + [0.234s][debug][gc,phases] GC(0) Post Evacuate Collection Set: 1.1ms + [0.234s][debug][gc,phases] GC(0) Other: 0.8ms + [0.234s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 24M->8M(256M) 7.500ms + """; + Path file = tempDir.resolve("phases.log"); + Files.writeString(file, log); + + GcLogParser.ParseResult result = GcLogParser.parseWithPhases(file); + List phases = result.phases(); + + assertEquals(5, phases.size()); + assertEquals(0, phases.get(0).gcId()); + assertEquals("Pre Evacuate Collection Set", phases.get(0).phase()); + assertEquals(0.1, phases.get(0).durationMs(), 0.001); + + assertEquals("Evacuate Collection Set", phases.get(2).phase()); + assertEquals(5.2, phases.get(2).durationMs(), 0.001); + } + + @Test + void parsePhaseEvents_multipleGcCycles() throws IOException { + String log = """ + [0.234s][debug][gc,phases] GC(0) Evacuate Collection Set: 5.2ms + [0.234s][debug][gc,phases] GC(0) Other: 0.8ms + [0.500s][debug][gc,phases] GC(1) Evacuate Collection Set: 7.4ms + [0.500s][debug][gc,phases] GC(1) Other: 1.2ms + [0.234s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 24M->8M(256M) 6.0ms + [0.500s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 32M->10M(256M) 8.6ms + """; + Path file = tempDir.resolve("multi.log"); + Files.writeString(file, log); + + GcLogParser.ParseResult result = GcLogParser.parseWithPhases(file); + GcPhaseAnalyzer.PhaseAnalysis analysis = GcPhaseAnalyzer.analyze(result.phases()); + + assertEquals(2, analysis.gcCount()); + assertEquals(2, analysis.phases().size()); + + // "Evacuate Collection Set" avg = (5.2 + 7.4) / 2 = 6.3ms + GcPhaseAnalyzer.PhaseStat evacuate = analysis.phases().stream() + .filter(p -> p.phase().equals("Evacuate Collection Set")) + .findFirst().orElseThrow(); + assertEquals(6.3, evacuate.avgMs(), 0.01); + assertEquals(7.4, evacuate.maxMs(), 0.01); + } + + @Test + void percentageCalculation_sumsTo100() throws IOException { + String log = """ + [0.234s][debug][gc,phases] GC(0) Phase A: 3.0ms + [0.234s][debug][gc,phases] GC(0) Phase B: 7.0ms + [0.234s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 24M->8M(256M) 10.0ms + """; + Path file = tempDir.resolve("pct.log"); + Files.writeString(file, log); + + GcLogParser.ParseResult result = GcLogParser.parseWithPhases(file); + GcPhaseAnalyzer.PhaseAnalysis analysis = GcPhaseAnalyzer.analyze(result.phases()); + + double totalPct = analysis.phases().stream() + .mapToDouble(GcPhaseAnalyzer.PhaseStat::percentOfTotal) + .sum(); + assertEquals(100.0, totalPct, 0.01); + + GcPhaseAnalyzer.PhaseStat phaseA = analysis.phases().get(0); + assertEquals(30.0, phaseA.percentOfTotal(), 0.01); + + GcPhaseAnalyzer.PhaseStat phaseB = analysis.phases().get(1); + assertEquals(70.0, phaseB.percentOfTotal(), 0.01); + } + + @Test + void emptyPhaseList_returnsEmptyAnalysis() { + GcPhaseAnalyzer.PhaseAnalysis analysis = GcPhaseAnalyzer.analyze(List.of()); + assertTrue(analysis.phases().isEmpty()); + assertEquals(0, analysis.gcCount()); + } + + @Test + void nonPhaseLines_notParsedAsPhases() throws IOException { + String log = """ + [0.234s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 24M->8M(256M) 7.500ms + [0.235s][info][gc,heap] GC(0) Eden regions: 10->0(20) + """; + Path file = tempDir.resolve("nophases.log"); + Files.writeString(file, log); + + GcLogParser.ParseResult result = GcLogParser.parseWithPhases(file); + assertTrue(result.phases().isEmpty()); + assertEquals(1, result.events().size()); + } +}