Skip to content

Commit e8eeb30

Browse files
chewiebugchewiebug
committed
#198 add support for -XX:+UseShenandoahGC - XX:+PrintGCDetails
1 parent 255da16 commit e8eeb30

File tree

3 files changed

+202
-0
lines changed

3 files changed

+202
-0
lines changed

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

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -114,6 +114,12 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
114114
EXCLUDE_STRINGS.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
115115
EXCLUDE_STRINGS.add("Uncommitted"); // -XX:+UseShenandoahGC
116116
EXCLUDE_STRINGS.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC
117+
EXCLUDE_STRINGS.add("Capacity"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
118+
EXCLUDE_STRINGS.add("Periodic GC triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
119+
EXCLUDE_STRINGS.add("Immediate Garbage"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
120+
EXCLUDE_STRINGS.add("Garbage to be collected"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
121+
EXCLUDE_STRINGS.add("Live"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
122+
EXCLUDE_STRINGS.add("Concurrent marking triggered"); // -XX:+UseShenandoahGC -XX:+PrintGCDetails
117123
}
118124

119125
private static final String EVENT_YG_OCCUPANCY = "YG occupancy";
@@ -201,6 +207,18 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
201207
private static final int PRINT_TENURING_DISTRIBUTION_PATTERN_GROUP_BEFORE = 1;
202208
private static final int PRINT_TENURING_DISTRIBUTION_PATTERN_GROUP_AFTER = 2;
203209

210+
// -XX:+UseShenandoahGC -XX:+PrintGCDetails
211+
// 590327.714: [Pause Final MarkTotal Garbage: 57403M
212+
// Immediate Garbage: 32M, 2 regions (1% of total)
213+
// Garbage to be collected: 5134M (8% of total), 164 regions
214+
// Live objects to be evacuated: 113M
215+
// Live/garbage ratio in collected regions: 2%
216+
// 219G->219G(256G), 5.000 ms]
217+
private static final String SHENANDOAH_DETAILS_FINAL_MARK = "Final MarkTotal";
218+
private static final String SHENANDOAH_DETAILS_FINAL_MARK_SPLIT_START = "Total";
219+
220+
private static final String SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS = "Shenandoah Heap";
221+
204222
// -XX:+PrintReferenceGC
205223
private static final String PRINT_REFERENCE_GC_INDICATOR = "Reference";
206224

@@ -256,6 +274,14 @@ else if (line.indexOf(LOGFILE_ROLLING_BEGIN) > 0 || line.indexOf(LOGFILE_ROLLING
256274
continue;
257275
}
258276

277+
if (line.contains(SHENANDOAH_DETAILS_FINAL_MARK)) {
278+
beginningOfLine.addFirst(line.substring(0, line.indexOf(SHENANDOAH_DETAILS_FINAL_MARK_SPLIT_START)));
279+
continue;
280+
} else if (line.startsWith(SHENANDOAH_INTRODUCTION_TO_GC_STATISTICS)) {
281+
// Assumption: As soon as the shenandoah gc statistics block starts, the vm is shutting down
282+
skipAndLogToEndOfFile(in);
283+
continue;
284+
}
259285
if (line.indexOf(CMS_ABORT_PRECLEAN) >= 0) {
260286
// line contains like " CMS: abort preclean due to time "
261287
// -> remove the text
@@ -429,6 +455,13 @@ else if (beginningOfLine.size() > 0) {
429455
}
430456
}
431457

458+
private void skipAndLogToEndOfFile(LineNumberReader in) throws IOException {
459+
String line;
460+
while ((line = in.readLine()) != null) {
461+
getLogger().info(line);
462+
}
463+
}
464+
432465
private boolean isPrintHeapAtGcStarting(String line) {
433466
return line.startsWith(HEAP) // jdk 6 and before
434467
|| line.indexOf(HEAP_SIZING_BEFORE) >= 0 // jdk 7 and after

‎src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0.java

Lines changed: 71 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -238,4 +238,75 @@ public void shenandoahIgnoredLines() throws Exception {
238238
assertThat("gc count", model.size(), is(0));
239239
assertThat("warnings", handler.getCount(), is(0));
240240
}
241+
242+
@Test
243+
public void shenandoaPauseInitMarkDetails() throws Exception {
244+
TestLogHandler handler = new TestLogHandler();
245+
handler.setLevel(Level.WARNING);
246+
GCResource gcResource = new GcResourceFile("byteArray");
247+
gcResource.getLogger().addHandler(handler);
248+
249+
ByteArrayInputStream in = new ByteArrayInputStream(
250+
("Capacity: 262144M, Peak Occupancy: 222063M, Lowest Free: 40080M, Free Threshold: 7864M\n" +
251+
"Uncommitted 1184M. Heap: 262144M reserved, 223616M committed, 213270M used\n" +
252+
"Periodic GC triggered. Time since last GC: 300004 ms, Guaranteed Interval: 300000 ms\n" +
253+
"347584.988: [Pause Init Mark, 3.942 ms]\n")
254+
.getBytes());
255+
256+
DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
257+
GCModel model = reader.read();
258+
259+
assertThat("gc count", model.size(), is(1));
260+
assertThat("warnings", handler.getCount(), is(0));
261+
262+
AbstractGCEvent<?> initMarkEvent = model.get(0);
263+
assertThat("Pause init mark: duration", initMarkEvent.getPause(), closeTo(0.003942, 0.00001));
264+
}
265+
266+
@Test
267+
public void shenandoahPauseFinalMarkDetails() throws Exception {
268+
TestLogHandler handler = new TestLogHandler();
269+
handler.setLevel(Level.WARNING);
270+
GCResource gcResource = new GcResourceFile("byteArray");
271+
gcResource.getLogger().addHandler(handler);
272+
273+
ByteArrayInputStream in = new ByteArrayInputStream(
274+
("346363.391: [Pause Final MarkTotal Garbage: 54870M" +
275+
"\nImmediate Garbage: 0M, 0 regions (0% of total)" +
276+
"\nGarbage to be collected: 8900M (16% of total), 281 regions" +
277+
"\nLive objects to be evacuated: 85M" +
278+
"\nLive/garbage ratio in collected regions: 0%" +
279+
"\n 216G->216G(256G), 14.095 ms]")
280+
.getBytes());
281+
282+
DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
283+
GCModel model = reader.read();
284+
285+
assertThat("gc count", model.size(), is(1));
286+
assertThat("warnings", handler.getCount(), is(0));
287+
288+
AbstractGCEvent<?> finalMarkEvent = model.get(0);
289+
assertThat("name", finalMarkEvent.getTypeAsString(), equalTo("Pause Final Mark"));
290+
assertThat("duration", finalMarkEvent.getPause(), closeTo(0.014095, 0.000000001));
291+
assertThat("before", finalMarkEvent.getPreUsed(), is(216 * 1024 * 1024));
292+
}
293+
294+
@Test
295+
public void shenandoahDetailsShutdown() throws Exception {
296+
TestLogHandler handler = new TestLogHandler();
297+
handler.setLevel(Level.INFO);
298+
GCResource gcResource = new GcResourceFile("SampleSun1_8_0ShenandoahDetailsShutdown.txt");
299+
gcResource.getLogger().addHandler(handler);
300+
301+
DataReader reader = getDataReader(gcResource);
302+
GCModel model = reader.read();
303+
304+
assertThat("gc count", model.size(), is(0));
305+
assertThat("number of errors",
306+
handler.getLogRecords().stream().filter(logRecord -> !logRecord.getLevel().equals(Level.INFO)).count(),
307+
is(0L));
308+
assertThat("contains GC STATISTICS",
309+
handler.getLogRecords().stream().filter(logRecord -> logRecord.getMessage().startsWith("GC STATISTICS")).count(),
310+
is(1L));
311+
}
241312
}

‎src/test/resources/openjdk/SampleSun1_8_0ShenandoahDetailsShutdown.txt

Lines changed: 98 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,98 @@
1+
Cancelling concurrent GC: Stopping VM
2+
Heap
3+
Shenandoah Heap
4+
268435456K total, 261685248K committed, 226747245K used
5+
8192 x 32768K regions
6+
Status: idle cancelled
7+
Reserved region:
8+
- [0x00007f4ba8000000, 0x00007f8ba8000000)
9+
10+
GC STATISTICS:
11+
"(G)" (gross) pauses include VM time: time to notify and block threads, do the pre-
12+
and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect.
13+
"(N)" (net) pauses are the times spent in the actual GC code.
14+
"a" is average time for each phase, look at levels to see if average makes sense.
15+
"lvls" are quantiles: 0% (minimum), 25%, 50% (median), 75%, 100% (maximum).
16+
17+
Total Pauses (G) = 60.47 s (a = 7786 us) (n = 7766) (lvls, us = 689, 4746, 7109, 9609, 85448)
18+
Total Pauses (N) = 31.31 s (a = 4031 us) (n = 7766) (lvls, us = 158, 2539, 3613, 4922, 81166)
19+
Pause Init Mark (G) = 14.90 s (a = 7662 us) (n = 1945) (lvls, us = 3691, 6641, 7109, 7812, 37445)
20+
Pause Init Mark (N) = 8.29 s (a = 4264 us) (n = 1945) (lvls, us = 2441, 3672, 4043, 4551, 35342)
21+
Accumulate Stats = 0.33 s (a = 172 us) (n = 1945) (lvls, us = 71, 158, 164, 176, 2534)
22+
Make Parsable = 0.10 s (a = 52 us) (n = 1945) (lvls, us = 5, 39, 51, 58, 1048)
23+
Clear Liveness = 1.59 s (a = 818 us) (n = 1945) (lvls, us = 426, 730, 797, 885, 2195)
24+
Scan Roots = 5.82 s (a = 2990 us) (n = 1945) (lvls, us = 1543, 2441, 2754, 3223, 34120)
25+
S: Thread Roots = 0.61 s (a = 314 us) (n = 1945) (lvls, us = 56, 215, 244, 297, 22527)
26+
S: String Table Roots = 1.08 s (a = 554 us) (n = 1945) (lvls, us = 0, 357, 488, 744, 3173)
27+
S: Universe Roots = 0.01 s (a = 5 us) (n = 1945) (lvls, us = 1, 2, 2, 2, 2351)
28+
S: JNI Roots = 0.02 s (a = 11 us) (n = 1945) (lvls, us = 3, 6, 7, 8, 1717)
29+
S: JNI Weak Roots = 0.04 s (a = 22 us) (n = 1945) (lvls, us = 0, 14, 18, 25, 1471)
30+
S: Synchronizer Roots = 0.00 s (a = 2 us) (n = 1945) (lvls, us = 0, 1, 2, 2, 63)
31+
S: Flat Profiler Roots = 0.05 s (a = 24 us) (n = 1945) (lvls, us = 1, 18, 20, 23, 754)
32+
S: Management Roots = 0.01 s (a = 3 us) (n = 1945) (lvls, us = 1, 2, 2, 3, 384)
33+
S: System Dict Roots = 0.20 s (a = 101 us) (n = 1945) (lvls, us = 10, 16, 21, 45, 1488)
34+
S: CLDG Roots = 0.14 s (a = 73 us) (n = 1945) (lvls, us = 30, 54, 60, 68, 7618)
35+
S: JVMTI Roots = 0.00 s (a = 1 us) (n = 1945) (lvls, us = 0, 0, 1, 1, 209)
36+
Resize TLABs = 0.24 s (a = 123 us) (n = 1945) (lvls, us = 9, 107, 113, 125, 858)
37+
Pause Final Mark (G) = 25.04 s (a = 12876 us) (n = 1945) (lvls, us = 6074, 9082, 11719, 15625, 85442)
38+
Pause Final Mark (N) = 15.58 s (a = 8011 us) (n = 1945) (lvls, us = 3906, 5117, 6074, 10938, 81164)
39+
Update Roots = 0.02 s (a = 2195 us) (n = 7) (lvls, us = 1680, 1680, 2109, 2207, 2579)
40+
U: Thread Roots = 0.00 s (a = 303 us) (n = 7) (lvls, us = 240, 240, 289, 318, 367)
41+
U: String Table Roots = 0.00 s (a = 532 us) (n = 7) (lvls, us = 301, 301, 480, 602, 726)
42+
U: Universe Roots = 0.00 s (a = 1 us) (n = 7) (lvls, us = 1, 1, 1, 1, 2)
43+
U: JNI Roots = 0.00 s (a = 6 us) (n = 7) (lvls, us = 4, 4, 5, 6, 9)
44+
U: JNI Weak Roots = 0.00 s (a = 20 us) (n = 7) (lvls, us = 3, 3, 16, 26, 33)
45+
U: Synchronizer Roots = 0.00 s (a = 1 us) (n = 7) (lvls, us = 1, 1, 1, 2, 2)
46+
U: Flat Profiler Roots = 0.00 s (a = 18 us) (n = 7) (lvls, us = 13, 13, 17, 19, 24)
47+
U: Management Roots = 0.00 s (a = 8 us) (n = 7) (lvls, us = 5, 5, 7, 9, 12)
48+
U: System Dict Roots = 0.00 s (a = 30 us) (n = 7) (lvls, us = 8, 8, 27, 33, 48)
49+
U: CLDG Roots = 0.00 s (a = 45 us) (n = 7) (lvls, us = 22, 22, 45, 47, 59)
50+
U: JVMTI Roots = 0.00 s (a = 1 us) (n = 7) (lvls, us = 0, 0, 1, 1, 1)
51+
Finish Queues = 3.49 s (a = 1792 us) (n = 1945) (lvls, us = 1074, 1602, 1758, 1914, 3164)
52+
Weak References = 1.32 s (a = 3398 us) (n = 389) (lvls, us = 885, 2129, 3242, 3926, 74072)
53+
Process = 0.79 s (a = 2033 us) (n = 389) (lvls, us = 25, 953, 1973, 2461, 72472)
54+
Enqueue = 0.52 s (a = 1349 us) (n = 389) (lvls, us = 580, 1074, 1270, 1562, 2544)
55+
System Purge = 2.87 s (a = 7381 us) (n = 389) (lvls, us = 6367, 6992, 7227, 7656, 9396)
56+
Unload Classes = 0.46 s (a = 1173 us) (n = 389) (lvls, us = 832, 982, 1035, 1211, 2371)
57+
Parallel Cleanup = 2.41 s (a = 6193 us) (n = 389) (lvls, us = 5371, 5918, 6113, 6387, 7774)
58+
Code Cache = 0.29 s (a = 758 us) (n = 389) (lvls, us = 396, 729, 754, 783, 1441)
59+
String/Symbol Tables = 0.58 s (a = 1480 us) (n = 389) (lvls, us = 1055, 1270, 1387, 1602, 2794)
60+
Clean Classes = 1.05 s (a = 2709 us) (n = 389) (lvls, us = 1309, 2656, 2695, 2754, 2915)
61+
Synchronization = 0.01 s (a = 16 us) (n = 389) (lvls, us = 0, 8, 12, 18, 386)
62+
CLDG = 0.00 s (a = 6 us) (n = 389) (lvls, us = 3, 4, 5, 5, 277)
63+
Prepare Evacuation = 1.53 s (a = 788 us) (n = 1945) (lvls, us = 607, 707, 752, 811, 1793)
64+
Initial Evacuation = 6.05 s (a = 3113 us) (n = 1945) (lvls, us = 1348, 2246, 2441, 2715, 17740)
65+
E: Thread Roots = 1.38 s (a = 708 us) (n = 1945) (lvls, us = 15, 248, 293, 371, 9000)
66+
E: Code Cache Roots = 1.10 s (a = 567 us) (n = 1945) (lvls, us = 211, 496, 602, 625, 904)
67+
Pause Init Update Refs (G) = 3.45 s (a = 1780 us) (n = 1938) (lvls, us = 686, 1602, 1719, 1895, 4542)
68+
Pause Init Update Refs (N) = 0.78 s (a = 402 us) (n = 1938) (lvls, us = 158, 352, 402, 443, 1097)
69+
Pause Final Update Refs (G) = 17.00 s (a = 8772 us) (n = 1938) (lvls, us = 3145, 6582, 7090, 9590, 48756)
70+
Pause Final Update Refs (N) = 6.62 s (a = 3415 us) (n = 1938) (lvls, us = 2441, 3164, 3340, 3574, 5330)
71+
Update Roots = 4.88 s (a = 2519 us) (n = 1938) (lvls, us = 1680, 2305, 2461, 2637, 4525)
72+
UR: Thread Roots = 0.53 s (a = 276 us) (n = 1938) (lvls, us = 12, 230, 258, 297, 1466)
73+
UR: String Table Roots = 1.27 s (a = 655 us) (n = 1938) (lvls, us = 311, 600, 660, 709, 1327)
74+
UR: Universe Roots = 0.00 s (a = 1 us) (n = 1938) (lvls, us = 1, 1, 1, 1, 10)
75+
UR: JNI Roots = 0.01 s (a = 6 us) (n = 1938) (lvls, us = 3, 4, 5, 6, 53)
76+
UR: JNI Weak Roots = 0.02 s (a = 12 us) (n = 1938) (lvls, us = 5, 8, 9, 13, 134)
77+
UR: Synchronizer Roots = 0.00 s (a = 2 us) (n = 1938) (lvls, us = 0, 1, 2, 2, 10)
78+
UR: Flat Profiler Roots = 0.04 s (a = 20 us) (n = 1938) (lvls, us = 1, 17, 20, 22, 49)
79+
UR: Management Roots = 0.01 s (a = 8 us) (n = 1938) (lvls, us = 1, 5, 6, 8, 90)
80+
UR: System Dict Roots = 0.04 s (a = 18 us) (n = 1938) (lvls, us = 8, 10, 12, 19, 214)
81+
UR: CLDG Roots = 0.09 s (a = 45 us) (n = 1938) (lvls, us = 27, 42, 44, 46, 138)
82+
UR: JVMTI Roots = 0.00 s (a = 1 us) (n = 1938) (lvls, us = 0, 1, 1, 1, 9)
83+
Recycle = 1.59 s (a = 822 us) (n = 1938) (lvls, us = 617, 754, 801, 863, 1455)
84+
Concurrent Marking = 8083.29 s (a = 4155932 us) (n = 1945) (lvls, us = 3183594, 4121094, 4140625, 4179688, 4427827)
85+
Concurrent Precleaning = 0.65 s (a = 1666 us) (n = 389) (lvls, us = 1328, 1504, 1582, 1660, 24655)
86+
Concurrent Evacuation = 27.23 s (a = 14002 us) (n = 1945) (lvls, us = 1914, 8750, 13477, 17383, 173985)
87+
Concurrent Update Refs = 4110.85 s (a = 2121183 us) (n = 1938) (lvls, us = 2050781, 2070312, 2089844, 2128906, 2758746)
88+
Concurrent Reset Bitmaps = 244.91 s (a = 125916 us) (n = 1945) (lvls, us = 1367, 119141, 125000, 130859, 140241)
89+
90+
0 allocation failure and 0 user requested GCs
91+
1945 successful and 0 degenerated concurrent markings
92+
1938 successful and 0 degenerated update references
93+
94+
ALLOCATION TRACING
95+
These are the slow-path allocations, including TLAB/GCLAB refills, and out-of-TLAB allocations.
96+
In-TLAB/GCLAB allocations happen orders of magnitude more frequently, and without delays.
97+
98+
Allocation tracing is disabled, use -XX:+ShenandoahAllocationTrace to enable.

0 commit comments

Comments
 (0)