Skip to content

Commit 0bdc64f

Browse files
chewiebugchewiebug
committed
support combination of -XX:+ScavengeBeforeRemark -XX:+PrintHeapAtGC (fixes #132)
1 parent 72f0c8a commit 0bdc64f

File tree

4 files changed

+149
-33
lines changed

4 files changed

+149
-33
lines changed

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

Lines changed: 32 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -297,28 +297,6 @@ else if (startsWith(line, LOG_INFORMATION_STRINGS, false)) {
297297
continue;
298298
}
299299

300-
if (isCmsScavengeBeforeRemark(line)) {
301-
// This is the case, when option -XX:+CMSScavengeBeforeRemark is used.
302-
// we have two events in the first line -> split it
303-
// if this option is combined with -XX:+PrintTenuringDistribution, the
304-
// first event is also distributed over more than one line
305-
int startOf2ndEvent = line.indexOf("]", line.indexOf(EVENT_YG_OCCUPANCY)) + 1;
306-
beginningOfLine.addFirst(line.substring(0, startOf2ndEvent));
307-
if (!isPrintTenuringDistribution(line)) {
308-
if (line.indexOf(SCAVENGE_BEFORE_REMARK) >= 0) {
309-
// jdk1.5 scavenge before remark: just after another separate event occurs
310-
startOf2ndEvent = line.indexOf(SCAVENGE_BEFORE_REMARK) + SCAVENGE_BEFORE_REMARK.length();
311-
}
312-
model.add(parseLine(line.substring(startOf2ndEvent), parsePosition));
313-
parsePosition.setIndex(0);
314-
}
315-
else {
316-
beginningOfLine.addFirst(line.substring(startOf2ndEvent));
317-
}
318-
319-
lastLineWasScavengeBeforeRemark = true;
320-
continue;
321-
}
322300
int unloadingClassIndex = line.indexOf(UNLOADING_CLASS);
323301
if (unloadingClassIndex > 0) {
324302
beginningOfLine.addFirst(line.substring(0, unloadingClassIndex));
@@ -356,6 +334,18 @@ else if (line.indexOf(ADAPTIVE_PATTERN) >= 0) {
356334
}
357335
continue;
358336
}
337+
else if (line.indexOf(HEAP_SIZING_START) >= 0) {
338+
// if -XX:+ScavengeBeforeRemark and -XX:+PrintHeapAtGC are combined, the following lines are common
339+
// 2015-05-14T18:55:12.588+0200: 1.157: [GC (CMS Final Remark) [YG occupancy: 10451 K (47936 K)]{Heap before GC invocations=22 (full 13):
340+
if (line.contains("]{" + HEAP_SIZING_START)) {
341+
beginningOfLine.add(line.substring(0, line.indexOf("{" + HEAP_SIZING_START)));
342+
lastLineWasScavengeBeforeRemark = true;
343+
}
344+
345+
// the next few lines will be the sizing of the heap
346+
lineNumber = skipLines(in, parsePosition, lineNumber, HEAP_STRINGS);
347+
continue;
348+
}
359349
else if (beginningOfLine.size() > 0) {
360350
// -XX:+CMSScavengeBeforeRemark combined with -XX:+PrintTenuringDistribution
361351
// is the only case where beginningOfLine.size() > 1
@@ -376,9 +366,26 @@ else if (beginningOfLine.size() > 0) {
376366
line = beginningOfLine.removeFirst() + line;
377367
}
378368
}
379-
else if (line.indexOf(HEAP_SIZING_START) >= 0) {
380-
// the next few lines will be the sizing of the heap
381-
lineNumber = skipLines(in, parsePosition, lineNumber, HEAP_STRINGS);
369+
if (isCmsScavengeBeforeRemark(line)) {
370+
// This is the case, when option -XX:+CMSScavengeBeforeRemark is used.
371+
// we have two events in the first line -> split it
372+
// if this option is combined with -XX:+PrintTenuringDistribution, the
373+
// first event is also distributed over more than one line
374+
int startOf2ndEvent = line.indexOf("]", line.indexOf(EVENT_YG_OCCUPANCY)) + 1;
375+
beginningOfLine.addFirst(line.substring(0, startOf2ndEvent));
376+
if (!isPrintTenuringDistribution(line)) {
377+
if (line.indexOf(SCAVENGE_BEFORE_REMARK) >= 0) {
378+
// jdk1.5 scavenge before remark: just after another separate event occurs
379+
startOf2ndEvent = line.indexOf(SCAVENGE_BEFORE_REMARK) + SCAVENGE_BEFORE_REMARK.length();
380+
}
381+
model.add(parseLine(line.substring(startOf2ndEvent), parsePosition));
382+
parsePosition.setIndex(0);
383+
}
384+
else {
385+
beginningOfLine.addFirst(line.substring(startOf2ndEvent));
386+
}
387+
388+
lastLineWasScavengeBeforeRemark = true;
382389
continue;
383390
}
384391

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

Lines changed: 47 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,9 @@
11
package com.tagtraum.perf.gcviewer.imp;
22

3+
import static org.hamcrest.Matchers.closeTo;
4+
import static org.hamcrest.Matchers.is;
35
import static org.junit.Assert.assertEquals;
6+
import static org.junit.Assert.assertThat;
47

58
import java.io.IOException;
69
import java.io.InputStream;
@@ -13,7 +16,7 @@
1316

1417
/**
1518
* Test logs generated specifically by java 1.8.
16-
*
19+
*
1720
* @author <a href="mailto:[email protected]">Joerg Wuethrich</a>
1821
* <p>created on: 25.09.2013</p>
1922
*/
@@ -24,20 +27,56 @@ public class TestDataReaderSun1_8_0 {
2427
private InputStream getInputStream(String fileName) throws IOException {
2528
return UnittestHelper.getResourceAsStream(UnittestHelper.FOLDER_OPENJDK, fileName);
2629
}
27-
30+
2831
@Test
2932
public void parallelPrintHeapAtGC() throws Exception {
3033
TestLogHandler handler = new TestLogHandler();
3134
handler.setLevel(Level.WARNING);
3235
IMP_LOGGER.addHandler(handler);
3336
DATA_READER_FACTORY_LOGGER.addHandler(handler);
34-
35-
final InputStream in = getInputStream("SampleSun1_8_0ParallelPrintHeapAtGC.txt");
36-
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_8);
37+
38+
InputStream in = getInputStream("SampleSun1_8_0ParallelPrintHeapAtGC.txt");
39+
DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_8);
40+
GCModel model = reader.read();
41+
42+
assertThat("gc pause sum", model.getPause().getSum(), closeTo(0.0103603, 0.000000001));
43+
44+
assertThat("number of errors", handler.getCount(), is(0));
45+
}
46+
47+
@Test
48+
public void scavengeBeforeRemarkPrintHeapAtGC_YGOccupancy() throws Exception {
49+
TestLogHandler handler = new TestLogHandler();
50+
handler.setLevel(Level.WARNING);
51+
IMP_LOGGER.addHandler(handler);
52+
DATA_READER_FACTORY_LOGGER.addHandler(handler);
53+
54+
InputStream in = getInputStream("SampleSun1_8_0CMS_ScavengeBeforeRemark_HeapAtGc.txt");
55+
DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_8);
3756
GCModel model = reader.read();
38-
39-
assertEquals("gc pause sum", 0.0103603, model.getPause().getSum(), 0.000000001);
40-
57+
58+
assertThat("gc count", model.size(), is(2));
59+
assertThat("scavenge before remark event", model.get(0).getPause(), closeTo(0.0000778, 0.000000001));
60+
assertThat("remark event", model.get(1).getPause(), closeTo(0.0019970 - 0.0000778, 0.000000001));
61+
62+
assertEquals("number of errors", 0, handler.getCount());
63+
}
64+
65+
@Test
66+
public void scavengeBeforeRemark_HeapAtGC_PrintTenuringDistribution_PrintFLSStats() throws Exception {
67+
TestLogHandler handler = new TestLogHandler();
68+
handler.setLevel(Level.WARNING);
69+
IMP_LOGGER.addHandler(handler);
70+
DATA_READER_FACTORY_LOGGER.addHandler(handler);
71+
72+
InputStream in = getInputStream("SampleSun1_8_0CMS_ScavengeBR_HeapAtGC_TenuringDist_PrintFLS.txt");
73+
DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_8);
74+
GCModel model = reader.read();
75+
76+
assertThat("gc count", model.size(), is(2));
77+
assertThat("scavenge before remark event", model.get(0).getPause(), closeTo(0.1306264, 0.000000001));
78+
assertThat("remark event", model.get(1).getPause(), closeTo(0.1787717 - 0.1306264, 0.000000001));
79+
4180
assertEquals("number of errors", 0, handler.getCount());
4281
}
4382
}

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

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,51 @@
1+
2015-05-13T13:28:51.504-0400: 12.356: [GC [YG occupancy: 830688 K (1310720 K)]{Heap before GC invocations=1 (full 1):
2+
par new generation total 1310720K, used 830688K [0x0000000640000000, 0x00000006a0000000, 0x00000006a0000000)
3+
eden space 1048576K, 76% used [0x0000000640000000, 0x000000067140a1f0, 0x0000000680000000)
4+
from space 262144K, 9% used [0x0000000690000000, 0x000000069172dec0, 0x00000006a0000000)
5+
to space 262144K, 0% used [0x0000000680000000, 0x0000000680000000, 0x0000000690000000)
6+
concurrent mark-sweep generation total 3670016K, used 0K [0x00000006a0000000, 0x0000000780000000, 0x00000007c0000000)
7+
Metaspace used 38929K, capacity 43528K, committed 43796K, reserved 1087488K
8+
class space used 4934K, capacity 6361K, committed 6472K, reserved 1048576K
9+
2015-05-13T13:28:51.504-0400: 12.357: [GC Before GC:
10+
Statistics for BinaryTreeDictionary:
11+
------------------------------------
12+
Total Free Space: 469745664
13+
Max Chunk Size: 469745664
14+
Number of Blocks: 1
15+
Av. Block Size: 469745664
16+
Tree Height: 1
17+
Statistics for IndexedFreeLists:
18+
--------------------------------
19+
Total Free Space: 0
20+
Max Chunk Size: 0
21+
Number of Blocks: 0
22+
free=469745664 frag=0.0000
23+
12.357: [ParNew
24+
Desired survivor size 134217728 bytes, new threshold 1 (max 1)
25+
- age 1: 19742112 bytes, 19742112 total
26+
: 830688K->25255K(1310720K), 0.1302057 secs] 830688K->36167K(4980736K)After GC:
27+
Statistics for BinaryTreeDictionary:
28+
------------------------------------
29+
Total Free Space: 468117326
30+
Max Chunk Size: 468117326
31+
Number of Blocks: 1
32+
Av. Block Size: 468117326
33+
Tree Height: 1
34+
Statistics for IndexedFreeLists:
35+
--------------------------------
36+
Total Free Space: 231659
37+
Max Chunk Size: 254
38+
Number of Blocks: 3415
39+
Av. Block Size: 67
40+
free=468348985 frag=0.0010
41+
, 0.1306264 secs] [Times: user=0.45 sys=0.02, real=0.12 secs]
42+
Heap after GC invocations=2 (full 1):
43+
par new generation total 1310720K, used 25255K [0x0000000640000000, 0x00000006a0000000, 0x00000006a0000000)
44+
eden space 1048576K, 0% used [0x0000000640000000, 0x0000000640000000, 0x0000000680000000)
45+
from space 262144K, 9% used [0x0000000680000000, 0x00000006818a9dd0, 0x0000000690000000)
46+
to space 262144K, 0% used [0x0000000690000000, 0x0000000690000000, 0x00000006a0000000)
47+
concurrent mark-sweep generation total 3670016K, used 10911K [0x00000006a0000000, 0x0000000780000000, 0x00000007c0000000)
48+
Metaspace used 38929K, capacity 43528K, committed 43796K, reserved 1087488K
49+
class space used 4934K, capacity 6361K, committed 6472K, reserved 1048576K
50+
}
51+
12.487: [Rescan (parallel) , 0.0173509 secs]12.505: [weak refs processing, 0.0018299 secs]12.507: [class unloading, 0.0084064 secs]12.515: [scrub symbol table, 0.0160760 secs]12.531: [scrub string table, 0.0013724 secs][1 CMS-remark: 10911K(3670016K)] 36167K(4980736K), 0.1787717 secs] [Times: user=0.58 sys=0.02, real=0.17 secs]

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

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
1+
2015-05-14T18:55:12.588+0200: 1.157: [GC (CMS Final Remark) [YG occupancy: 10451 K (47936 K)]{Heap before GC invocations=22 (full 13):
2+
par new generation total 47936K, used 10451K [0x00000000f6400000, 0x00000000f9800000, 0x00000000f9800000)
3+
eden space 42624K, 12% used [0x00000000f6400000, 0x00000000f690c520, 0x00000000f8da0000)
4+
from space 5312K, 99% used [0x00000000f92d0000, 0x00000000f97f8a50, 0x00000000f9800000)
5+
to space 5312K, 0% used [0x00000000f8da0000, 0x00000000f8da0000, 0x00000000f92d0000)
6+
concurrent mark-sweep generation total 106496K, used 100839K [0x00000000f9800000, 0x0000000100000000, 0x0000000100000000)
7+
Metaspace used 2476K, capacity 4490K, committed 4864K, reserved 1056768K
8+
class space used 271K, capacity 386K, committed 512K, reserved 1048576K
9+
2015-05-14T18:55:12.588+0200: 1.158: [GC (CMS Final Remark) 1.158: [ParNew: 10451K->10451K(47936K), 0.0000303 secs] 111291K->111291K(154432K), 0.0000778 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
10+
Heap after GC invocations=23 (full 13):
11+
par new generation total 47936K, used 10451K [0x00000000f6400000, 0x00000000f9800000, 0x00000000f9800000)
12+
eden space 42624K, 12% used [0x00000000f6400000, 0x00000000f690c520, 0x00000000f8da0000)
13+
from space 5312K, 99% used [0x00000000f92d0000, 0x00000000f97f8a50, 0x00000000f9800000)
14+
to space 5312K, 0% used [0x00000000f8da0000, 0x00000000f8da0000, 0x00000000f92d0000)
15+
concurrent mark-sweep generation total 106496K, used 100839K [0x00000000f9800000, 0x0000000100000000, 0x0000000100000000)
16+
Metaspace used 2476K, capacity 4490K, committed 4864K, reserved 1056768K
17+
class space used 271K, capacity 386K, committed 512K, reserved 1048576K
18+
}
19+
1.158: [Rescan (parallel) , 0.0002732 secs]1.158: [weak refs processing, 0.0000176 secs]1.158: [class unloading, 0.0005055 secs]1.159: [scrub symbol table, 0.0006476 secs]1.159: [scrub string table, 0.0001462 secs][1 CMS-remark: 100839K(106496K)] 111291K(154432K), 0.0019970 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

0 commit comments

Comments
 (0)