Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
57 changes: 53 additions & 4 deletions argus-cli/src/main/java/io/argus/cli/command/GcLogCommand.java
Original file line number Diff line number Diff line change
Expand Up @@ -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<GcEvent> events;
List<GcPhaseEvent> 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;
Expand Down Expand Up @@ -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 {
Expand All @@ -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<GcEvent> events, Path file, boolean c) {
private void printRich(GcLogAnalysis a, List<GcEvent> events,
List<GcPhaseEvent> 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,
Expand Down Expand Up @@ -271,10 +282,48 @@ private void printRich(GcLogAnalysis a, List<GcEvent> 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));
Expand Down
53 changes: 53 additions & 0 deletions argus-cli/src/main/java/io/argus/cli/gclog/GcLogParser.java
Original file line number Diff line number Diff line change
Expand Up @@ -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<GcEvent> events, List<GcPhaseEvent> 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<GcEvent> events = new ArrayList<>();
List<GcPhaseEvent> 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.
*/
Expand Down
54 changes: 54 additions & 0 deletions argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseAnalyzer.java
Original file line number Diff line number Diff line change
@@ -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<GcPhaseEvent> phases) {
if (phases.isEmpty()) {
return new PhaseAnalysis(List.of(), 0);
}

// Aggregate per-phase: sum, max, count across all GC IDs
Map<String, double[]> 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<Integer> 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<PhaseStat> stats = new ArrayList<>();
for (Map.Entry<String, double[]> 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<PhaseStat> phases, int gcCount) {}

public record PhaseStat(String phase, double avgMs, double maxMs, double percentOfTotal) {}
}
22 changes: 22 additions & 0 deletions argus-cli/src/main/java/io/argus/cli/gclog/GcPhaseEvent.java
Original file line number Diff line number Diff line change
@@ -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; }
}
114 changes: 114 additions & 0 deletions argus-cli/src/test/java/io/argus/cli/gclog/GcPhaseAnalyzerTest.java
Original file line number Diff line number Diff line change
@@ -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<GcPhaseEvent> 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());
}
}
Loading