Skip to content

Commit e5c31e1

Browse files
author
cuiweilong
committed
fix failed parsing for ShenandoahGC
1 parent fb3b88e commit e5c31e1

File tree

10 files changed

+1481
-388
lines changed

10 files changed

+1481
-388
lines changed

‎src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java‎

Lines changed: 33 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -118,6 +118,7 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
118118
EXCLUDE_STRINGS_LINE_START.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
119119
EXCLUDE_STRINGS_LINE_START.add("Uncommitted"); // -XX:+UseShenandoahGC
120120
EXCLUDE_STRINGS_LINE_START.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC
121+
EXCLUDE_STRINGS_LINE_START.add("Cancelling GC"); // -XX:+UseShenandoahGC
121122
EXCLUDE_STRINGS_LINE_START.add("Capacity"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
122123
EXCLUDE_STRINGS_LINE_START.add("Periodic GC triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
123124
EXCLUDE_STRINGS_LINE_START.add("Immediate Garbage"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
@@ -126,7 +127,6 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
126127
EXCLUDE_STRINGS_LINE_START.add("Concurrent marking triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
127128
EXCLUDE_STRINGS_LINE_START.add("Adjusting free threshold"); // -XX:+UseShenandoahGC
128129
EXCLUDE_STRINGS_LINE_START.add("Predicted cset threshold"); // -XX:+UseShenandoahGC
129-
EXCLUDE_STRINGS_LINE_START.add("Trigger"); // -XX:+UseShenandoahGC
130130
EXCLUDE_STRINGS_LINE_START.add("Free"); // -XX:+UseShenandoahGC
131131
EXCLUDE_STRINGS_LINE_START.add("Evacuation Reserve"); // -XX:+UseShenandoahGC
132132
EXCLUDE_STRINGS_LINE_START.add("Pacer for "); // -XX:+UseShenandoahGC
@@ -135,6 +135,9 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
135135
EXCLUDE_STRINGS_LINE_START.add(" Adaptive CSet Selection"); // -XX:+UseShenandoahGC
136136
EXCLUDE_STRINGS_LINE_START.add(" Collectable Garbage"); // -XX:+UseShenandoahGC
137137
EXCLUDE_STRINGS_LINE_START.add(" Immediate Garbage"); // -XX:+UseShenandoahGC
138+
EXCLUDE_STRINGS_LINE_START.add(" Good progress for"); // -XX:+UseShenandoahGC
139+
EXCLUDE_STRINGS_LINE_START.add(" Failed to"); // -XX:+UseShenandoahGC
140+
EXCLUDE_STRINGS_LINE_START.add(" Cancelling GC"); // -XX:+UseShenandoahGC
138141

139142
EXCLUDE_STRINGS_LINE_CONTAIN.add(LOGFILE_ROLLING_BEGIN);
140143
EXCLUDE_STRINGS_LINE_CONTAIN.add(LOGFILE_ROLLING_END);
@@ -155,6 +158,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
155158
LOG_INFORMATION_STRINGS.add("Reference processing"); // -XX:+UseShenandoahGC
156159
LOG_INFORMATION_STRINGS.add("Heuristics ergonomically sets"); // -XX:+UseShenandoahGC
157160
LOG_INFORMATION_STRINGS.add("Initialize Shenandoah heap"); // -XX:+UseShenandoahGC
161+
LOG_INFORMATION_STRINGS.add("Shenandoah GC mode"); // -XX:+UseShenandoahGC
162+
LOG_INFORMATION_STRINGS.add("Soft Max Heap Size"); // -XX:+UseShenandoahGC
158163
}
159164

160165
private static final String EVENT_YG_OCCUPANCY = "YG occupancy";
@@ -253,6 +258,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
253258
private static final String SHENANDOAH_DETAILS_FINAL_MARK_SPLIT_START = "Total";
254259

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

257264
// -XX:+PrintReferenceGC
258265
private static final String PRINT_REFERENCE_GC_INDICATOR = "Reference";
@@ -266,7 +273,6 @@ public DataReaderSun1_6_0(GCResource gcResource, InputStream in, GcLogType gcLog
266273

267274
public GCModel read() throws IOException {
268275
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...");
269-
270276
try (LineNumberReader in = this.in) {
271277
GCModel model = new GCModel();
272278
model.setFormat(GCModel.Format.SUN_X_LOG_GC);
@@ -309,9 +315,17 @@ else if (startsWith(line, LOG_INFORMATION_STRINGS, false)) {
309315
continue;
310316
} else if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) {
311317
// Assumption: As soon as the shenandoah gc statistics block starts, the vm is shutting down
312-
skipAndLogToEndOfFile(in);
318+
skipAndLogToEndOfFile(in, line);
319+
continue;
320+
} else if (line.startsWith(SHENANDOAH_GC_CYCLE_START)) {
321+
// skip the start string of the first gc cycle
322+
continue;
323+
} else if (line.startsWith(SHENANDOAH_GC_CYCLE_DETAILS_START)) {
324+
// ignore details of each gc cycle
325+
skipGcCycleDetails(in);
313326
continue;
314327
}
328+
315329
if (line.indexOf(CMS_ABORT_PRECLEAN) >= 0) {
316330
// line contains like " CMS: abort preclean due to time "
317331
// -> remove the text
@@ -485,13 +499,27 @@ else if (beginningOfLine.size() > 0) {
485499
}
486500
}
487501

488-
private void skipAndLogToEndOfFile(LineNumberReader in) throws IOException {
489-
String line;
502+
private void skipAndLogToEndOfFile(LineNumberReader in, String line) throws IOException {
503+
getLogger().info(line);
490504
while ((line = in.readLine()) != null) {
491505
getLogger().info(line);
492506
}
493507
}
494508

509+
private void skipGcCycleDetails(LineNumberReader in) throws IOException {
510+
String line;
511+
while ((line = in.readLine()) != null) {
512+
// parse the events for the next GC cycle
513+
if (line.startsWith(SHENANDOAH_GC_CYCLE_START)) {
514+
break;
515+
}
516+
// the vm is shutting down
517+
if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) {
518+
skipAndLogToEndOfFile(in, line);
519+
}
520+
}
521+
}
522+
495523
private boolean isPrintHeapAtGcStarting(String line) {
496524
return line.startsWith(HEAP) // jdk 6 and before
497525
|| line.indexOf(HEAP_SIZING_BEFORE) >= 0 // jdk 7 and after

‎src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java‎

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -197,7 +197,9 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
197197
"Heap region size", // jdk 11
198198
"Heap Region Size", // jdk 17
199199
"Consider",
200-
"Heuristics ergonomically sets");
200+
"Heuristics ergonomically sets",
201+
"Soft Max Heap Size" // ShenandoahGC
202+
);
201203

202204
protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
203205
super(gcResource, in);
@@ -320,12 +322,16 @@ private AbstractGCEvent<?> handleTagGcMetaspaceTail(ParseContext context, Abstra
320322
// [1.182s][info][gc,metaspace] GC(0) Metaspace: 11M used, 12M committed, 1088M reserved
321323
// G1:
322324
// [5.537s][info][gc,metaspace] GC(0) Metaspace: 118K(320K)->118K(320K) NonClass: 113K(192K)->113K(192K) Class: 4K(128K)->4K(128K)
323-
324325
if (returnEvent.getExtendedType().getType().equals(Type.METASPACE) && tail != null) {
325326
if (tail.contains("used,") && tail.contains("committed,")) {
326327
return null;
327328
}
328329
}
330+
// the event "Metaspace" in gc tag "[gc,metaspace]" for Shenandoah don't have GC number; ignore it
331+
// [5.063s][info][gc,metaspace] Metaspace: 13104K(13376K)->13192K(13440K) NonClass: 11345K(11456K)->11431K(11520K) Class: 1758K(1920K)->1761K(1920K)
332+
if (returnEvent.getNumber() < 0) {
333+
return null;
334+
}
329335

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

667673
}
668674

669-
}
675+
}

‎src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java‎

Lines changed: 24 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -318,7 +318,7 @@ public boolean isRemark() {
318318
|| getTypeAsString().indexOf(Type.ASCMS_REMARK.getName()) >= 0
319319
|| getTypeAsString().indexOf(Type.G1_REMARK.getName()) >= 0
320320
|| getTypeAsString().indexOf(Type.UJL_PAUSE_REMARK.getName()) >= 0
321-
|| getTypeAsString().indexOf(Type.UJL_SHEN_FINAL_MARK.getName()) >= 0;
321+
|| getTypeAsString().indexOf(Type.UJL_SHEN_PAUSE_FINAL_MARK.getName()) >= 0;
322322
}
323323

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

685685
// unified jvm logging shenandoah event types
686-
public static final Type UJL_SHEN_INIT_MARK = new Type("Pause Init Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
687-
public static final Type UJL_SHEN_FINAL_MARK = new Type("Pause Final Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
688-
public static final Type UJL_SHEN_INIT_UPDATE_REFS = new Type("Pause Init Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
689-
public static final Type UJL_SHEN_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
690-
public static final Type UJL_SHEN_DEGENERATED_GC = new Type("Pause Degenerated GC", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
691-
public static final Type UJL_SHEN_CONCURRENT_CONC_MARK = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
692-
public static final Type UJL_SHEN_CONCURRENT_CONC_EVAC = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
686+
// Only "Concurrent cleanup", "Concurrent uncommit", "Pause Degenerated GC", "Pause Full" event types have memory info
687+
public static final Type UJL_SHEN_PAUSE_INIT_MARK = new Type("Pause Init Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
688+
public static final Type UJL_SHEN_PAUSE_FINAL_MARK = new Type("Pause Final Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
689+
public static final Type UJL_SHEN_PAUSE_INIT_UPDATE_REFS = new Type("Pause Init Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
690+
public static final Type UJL_SHEN_PAUSE_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
691+
public static final Type UJL_SHEN_PAUSE_FINAL_ROOTS = new Type("Pause Final Roots", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
692+
public static final Type UJL_SHEN_PAUSE_DEGENERATED_GC = new Type("Pause Degenerated GC", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
693+
public static final Type UJL_SHEN_CONCURRENT_RESET = new Type("Concurrent reset", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
694+
// FIX ME! looks like the event "Concurrent reset bitmaps" doesn't exist anymore(not in jdk8u332, 11, 17 and 18)
695+
public static final Type UJL_SHEN_CONCURRENT_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
696+
public static final Type UJL_SHEN_CONCURRENT_MARKING_ROOTS = new Type("Concurrent marking roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
697+
public static final Type UJL_SHEN_CONCURRENT_MARKING = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
698+
// FIX ME! looks like the event "Cancel concurrent mark" doesn't exist anymore(not in jdk8u332, 11, 17 and 18)
693699
public static final Type UJL_SHEN_CONCURRENT_CANCEL_CONC_MARK = new Type("Cancel concurrent mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
694-
public static final Type UJL_SHEN_CONCURRENT_RESET = new Type("Concurrent reset", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
695-
public static final Type UJL_SHEN_CONCURRENT_CONC_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
696-
public static final Type UJL_SHEN_CONCURRENT_CONC_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
697-
public static final Type UJL_SHEN_CONCURRENT_CLEANUP = new Type("Concurrent cleanup", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
698-
public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
700+
public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
701+
public static final Type UJL_SHEN_CONCURRENT_THREAD_ROOTS = new Type("Concurrent thread roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
702+
public static final Type UJL_SHEN_CONCURRENT_WEAK_REFERENCES = new Type("Concurrent weak references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
703+
public static final Type UJL_SHEN_CONCURRENT_WEAK_ROOTS = new Type("Concurrent weak roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
704+
public static final Type UJL_SHEN_CONCURRENT_CLEANUP = new Type("Concurrent cleanup", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
705+
public static final Type UJL_SHEN_CONCURRENT_CLASS_UNLOADING = new Type("Concurrent class unloading", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
706+
public static final Type UJL_SHEN_CONCURRENT_STRONG_ROOTS = new Type("Concurrent strong roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
707+
public static final Type UJL_SHEN_CONCURRENT_EVACUATION = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
708+
public static final Type UJL_SHEN_CONCURRENT_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
709+
public static final Type UJL_SHEN_CONCURRENT_UPDATE_THREAD_ROOTS = new Type("Concurrent update thread roots", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
699710
public static final Type UJL_SHEN_CONCURRENT_UNCOMMIT = new Type("Concurrent uncommit", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
700711

701712
// unified jvm logging ZGC event types

‎src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java‎

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
import static org.hamcrest.Matchers.startsWith;
66
import static org.junit.Assert.assertThat;
77

8+
import java.io.ByteArrayInputStream;
89
import java.io.File;
910
import java.io.IOException;
1011
import java.io.InputStream;
@@ -146,6 +147,29 @@ public static GCModel getGCModelFromLogFile(String fileName, FOLDER folderName,
146147
}
147148
}
148149

150+
/**
151+
* Return GCModel from given log string.
152+
*
153+
* @param logString gc log string to be parsed
154+
* @param expectedDataReaderClass expected DataReaderFactory class for the given fileName parameter
155+
* @return GCModel model containing contents of parsed log string
156+
* @throws IOException if resource could not be found
157+
*/
158+
public static GCModel getGCModelFromLogString(String logString, Class expectedDataReaderClass) throws IOException {
159+
TestLogHandler handler = new TestLogHandler();
160+
handler.setLevel(Level.WARNING);
161+
GCResource gcResource = new GcResourceFile("byteArray");
162+
gcResource.getLogger().addHandler(handler);
163+
InputStream in = new ByteArrayInputStream(logString.getBytes());
164+
165+
DataReader reader = new DataReaderFactory().getDataReader(gcResource, in);
166+
assertThat("reader from factory", reader.getClass().getName(), is(expectedDataReaderClass.getName()));
167+
168+
GCModel model = reader.read();
169+
assertThat("number of errors", handler.getCount(), is(0));
170+
return model;
171+
}
172+
149173
/**
150174
* Tests a given <code>event</code> for several of its attribute values.
151175
* @param event event under test

0 commit comments

Comments
 (0)