Skip to content

Commit

Permalink
fix failed parsing for ShenandoahGC
Browse files Browse the repository at this point in the history
  • Loading branch information
cuiweilong committed Aug 22, 2022
1 parent b554b68 commit 59f7eb9
Show file tree
Hide file tree
Showing 10 changed files with 1,481 additions and 388 deletions.
38 changes: 33 additions & 5 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -117,6 +117,7 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
EXCLUDE_STRINGS_LINE_START.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
EXCLUDE_STRINGS_LINE_START.add("Uncommitted"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Cancelling GC"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Capacity"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
EXCLUDE_STRINGS_LINE_START.add("Periodic GC triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
EXCLUDE_STRINGS_LINE_START.add("Immediate Garbage"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
Expand All @@ -125,7 +126,6 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
EXCLUDE_STRINGS_LINE_START.add("Concurrent marking triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
EXCLUDE_STRINGS_LINE_START.add("Adjusting free threshold"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Predicted cset threshold"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Trigger"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Free"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Evacuation Reserve"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add("Pacer for "); // -XX:+UseShenandoahGC
Expand All @@ -134,6 +134,9 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
EXCLUDE_STRINGS_LINE_START.add(" Adaptive CSet Selection"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add(" Collectable Garbage"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add(" Immediate Garbage"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add(" Good progress for"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add(" Failed to"); // -XX:+UseShenandoahGC
EXCLUDE_STRINGS_LINE_START.add(" Cancelling GC"); // -XX:+UseShenandoahGC

EXCLUDE_STRINGS_LINE_CONTAIN.add(LOGFILE_ROLLING_BEGIN);
EXCLUDE_STRINGS_LINE_CONTAIN.add(LOGFILE_ROLLING_END);
Expand All @@ -154,6 +157,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
LOG_INFORMATION_STRINGS.add("Reference processing"); // -XX:+UseShenandoahGC
LOG_INFORMATION_STRINGS.add("Heuristics ergonomically sets"); // -XX:+UseShenandoahGC
LOG_INFORMATION_STRINGS.add("Initialize Shenandoah heap"); // -XX:+UseShenandoahGC
LOG_INFORMATION_STRINGS.add("Shenandoah GC mode"); // -XX:+UseShenandoahGC
LOG_INFORMATION_STRINGS.add("Soft Max Heap Size"); // -XX:+UseShenandoahGC
}

private static final String EVENT_YG_OCCUPANCY = "YG occupancy";
Expand Down Expand Up @@ -252,6 +257,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
private static final String SHENANDOAH_DETAILS_FINAL_MARK_SPLIT_START = "Total";

private static final String SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS = "Shenandoah Heap";
private static final String SHENANDOAH_GC_CYCLE_DETAILS_START = "All times are wall-clock times";
private static final String SHENANDOAH_GC_CYCLE_START = "Trigger: ";

// -XX:+PrintReferenceGC
private static final String PRINT_REFERENCE_GC_INDICATOR = "Reference";
Expand All @@ -265,7 +272,6 @@ public DataReaderSun1_6_0(GCResource gcResource, InputStream in, GcLogType gcLog

public GCModel read() throws IOException {
if (getLogger().isLoggable(Level.INFO)) getLogger().info("Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x / 1.7.x / 1.8.x format...");

try (LineNumberReader in = this.in) {
GCModel model = new GCModel();
model.setFormat(GCModel.Format.SUN_X_LOG_GC);
Expand Down Expand Up @@ -308,9 +314,17 @@ else if (startsWith(line, LOG_INFORMATION_STRINGS, false)) {
continue;
} else if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) {
// Assumption: As soon as the shenandoah gc statistics block starts, the vm is shutting down
skipAndLogToEndOfFile(in);
skipAndLogToEndOfFile(in, line);
continue;
} else if (line.startsWith(SHENANDOAH_GC_CYCLE_START)) {
// skip the start string of the first gc cycle
continue;
} else if (line.startsWith(SHENANDOAH_GC_CYCLE_DETAILS_START)) {
// ignore details of each gc cycle
skipGcCycleDetails(in);
continue;
}

if (line.indexOf(CMS_ABORT_PRECLEAN) >= 0) {
// line contains like " CMS: abort preclean due to time "
// -> remove the text
Expand Down Expand Up @@ -484,13 +498,27 @@ else if (beginningOfLine.size() > 0) {
}
}

private void skipAndLogToEndOfFile(LineNumberReader in) throws IOException {
String line;
private void skipAndLogToEndOfFile(LineNumberReader in, String line) throws IOException {
getLogger().info(line);
while ((line = in.readLine()) != null) {
getLogger().info(line);
}
}

private void skipGcCycleDetails(LineNumberReader in) throws IOException {
String line;
while ((line = in.readLine()) != null) {
// parse the events for the next GC cycle
if (line.startsWith(SHENANDOAH_GC_CYCLE_START)) {
break;
}
// the vm is shutting down
if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) {
skipAndLogToEndOfFile(in, line);
}
}
}

private boolean isPrintHeapAtGcStarting(String line) {
return line.startsWith(HEAP) // jdk 6 and before
|| line.indexOf(HEAP_SIZING_BEFORE) >= 0 // jdk 7 and after
Expand Down
12 changes: 9 additions & 3 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -197,7 +197,9 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
"Heap region size", // jdk 11
"Heap Region Size", // jdk 17
"Consider",
"Heuristics ergonomically sets");
"Heuristics ergonomically sets",
"Soft Max Heap Size" // ShenandoahGC
);

protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
super(gcResource, in);
Expand Down Expand Up @@ -320,12 +322,16 @@ private AbstractGCEvent<?> handleTagGcMetaspaceTail(ParseContext context, Abstra
// [1.182s][info][gc,metaspace] GC(0) Metaspace: 11M used, 12M committed, 1088M reserved
// G1:
// [5.537s][info][gc,metaspace] GC(0) Metaspace: 118K(320K)->118K(320K) NonClass: 113K(192K)->113K(192K) Class: 4K(128K)->4K(128K)

if (returnEvent.getExtendedType().getType().equals(Type.METASPACE) && tail != null) {
if (tail.contains("used,") && tail.contains("committed,")) {
return null;
}
}
// the event "Metaspace" in gc tag "[gc,metaspace]" for Shenandoah don't have GC number; ignore it
// [5.063s][info][gc,metaspace] Metaspace: 13104K(13376K)->13192K(13440K) NonClass: 11345K(11456K)->11431K(11520K) Class: 1758K(1920K)->1761K(1920K)
if (returnEvent.getNumber() < 0) {
return null;
}

returnEvent = parseTail(context, returnEvent, tail);
// the UJL "Old" event occurs often after the next STW events have taken place; ignore it for now
Expand Down Expand Up @@ -666,4 +672,4 @@ public String toString() {

}

}
}
37 changes: 24 additions & 13 deletions src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -318,7 +318,7 @@ public boolean isRemark() {
|| getTypeAsString().indexOf(Type.ASCMS_REMARK.getName()) >= 0
|| getTypeAsString().indexOf(Type.G1_REMARK.getName()) >= 0
|| getTypeAsString().indexOf(Type.UJL_PAUSE_REMARK.getName()) >= 0
|| getTypeAsString().indexOf(Type.UJL_SHEN_FINAL_MARK.getName()) >= 0;
|| getTypeAsString().indexOf(Type.UJL_SHEN_PAUSE_FINAL_MARK.getName()) >= 0;
}

public boolean hasPause() {
Expand Down Expand Up @@ -683,19 +683,30 @@ public String toString() {
public static final Type UJL_G1_PHASE_COMPACT_HEAP = new Type("Phase 4: Compact heap", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);

// unified jvm logging shenandoah event types
public static final Type UJL_SHEN_INIT_MARK = new Type("Pause Init Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_FINAL_MARK = new Type("Pause Final Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_INIT_UPDATE_REFS = new Type("Pause Init Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_DEGENERATED_GC = new Type("Pause Degenerated GC", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_MARK = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_EVAC = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
// Only "Concurrent cleanup", "Concurrent uncommit", "Pause Degenerated GC", "Pause Full" event types have memory info
public static final Type UJL_SHEN_PAUSE_INIT_MARK = new Type("Pause Init Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_PAUSE_FINAL_MARK = new Type("Pause Final Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_PAUSE_INIT_UPDATE_REFS = new Type("Pause Init Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_PAUSE_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_PAUSE_FINAL_ROOTS = new Type("Pause Final Roots", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_PAUSE_DEGENERATED_GC = new Type("Pause Degenerated GC", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_RESET = new Type("Concurrent reset", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
// FIX ME! looks like the event "Concurrent reset bitmaps" doesn't exist anymore(not in jdk8u332, 11, 17 and 18)
public static final Type UJL_SHEN_CONCURRENT_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_MARKING_ROOTS = new Type("Concurrent marking roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_MARKING = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
// FIX ME! looks like the event "Cancel concurrent mark" doesn't exist anymore(not in jdk8u332, 11, 17 and 18)
public static final Type UJL_SHEN_CONCURRENT_CANCEL_CONC_MARK = new Type("Cancel concurrent mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_RESET = new Type("Concurrent reset", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CONC_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CLEANUP = new Type("Concurrent cleanup", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_THREAD_ROOTS = new Type("Concurrent thread roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_WEAK_REFERENCES = new Type("Concurrent weak references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_WEAK_ROOTS = new Type("Concurrent weak roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CLEANUP = new Type("Concurrent cleanup", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_CLASS_UNLOADING = new Type("Concurrent class unloading", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_STRONG_ROOTS = new Type("Concurrent strong roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_EVACUATION = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_UPDATE_THREAD_ROOTS = new Type("Concurrent update thread roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_CONCURRENT_UNCOMMIT = new Type("Concurrent uncommit", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);

// unified jvm logging ZGC event types
Expand Down
24 changes: 24 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
import static org.hamcrest.Matchers.startsWith;
import static org.junit.Assert.assertThat;

import java.io.ByteArrayInputStream;
import java.io.File;
import java.io.IOException;
import java.io.InputStream;
Expand Down Expand Up @@ -146,6 +147,29 @@ public static GCModel getGCModelFromLogFile(String fileName, FOLDER folderName,
}
}

/**
* Return GCModel from given log string.
*
* @param logString gc log string to be parsed
* @param expectedDataReaderClass expected DataReaderFactory class for the given fileName parameter
* @return GCModel model containing contents of parsed log string
* @throws IOException if resource could not be found
*/
public static GCModel getGCModelFromLogString(String logString, Class expectedDataReaderClass) throws IOException {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);
InputStream in = new ByteArrayInputStream(logString.getBytes());

DataReader reader = new DataReaderFactory().getDataReader(gcResource, in);
assertThat("reader from factory", reader.getClass().getName(), is(expectedDataReaderClass.getName()));

GCModel model = reader.read();
assertThat("number of errors", handler.getCount(), is(0));
return model;
}

/**
* Tests a given <code>event</code> for several of its attribute values.
* @param event event under test
Expand Down
Loading

0 comments on commit 59f7eb9

Please sign in to comment.