Skip to content

Commit d7ec81b

Browse files
chewiebugchewiebug
committed
#200 generalise handling of System.gc() events
1 parent 381e973 commit d7ec81b

File tree

8 files changed

+118
-16
lines changed

8 files changed

+118
-16
lines changed

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@
1313
*/
1414
public class DataReaderTools {
1515

16-
private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?");
16+
private static Pattern parenthesesPattern = Pattern.compile("\\([^)]*(\\))?\\) ?");
1717

1818
private Logger logger;
1919

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

Lines changed: 12 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -248,6 +248,14 @@ public boolean isFull() {
248248
return false;
249249
}
250250

251+
/**
252+
* Returns true, if this event was triggered by a call to "System.gc()"
253+
* @return <code>true</code> if triggered by "System.gc()"
254+
*/
255+
public boolean isSystem() {
256+
return getExtendedType().getName().contains("System");
257+
}
258+
251259
public boolean isInc() {
252260
return getExtendedType().getType() == GCEvent.Type.INC_GC;
253261
}
@@ -494,9 +502,7 @@ public String toString() {
494502
public static final Type SCAVENGE_BEFORE_REMARK = new Type("Scavenge-Before-Remark", Generation.ALL);
495503

496504
public static final Type FULL_GC = new Type("Full GC", Generation.ALL);
497-
public static final Type FULL_GC_SYSTEM = new Type("Full GC (System)", Generation.ALL);
498505
public static final Type GC = new Type("GC", Generation.YOUNG);
499-
public static final Type GC_SYSTEM = new Type("GC (System.gc())", Generation.YOUNG);
500506
public static final Type DEF_NEW = new Type("DefNew", Generation.YOUNG, Concurrency.SERIAL); // single threaded
501507
public static final Type PAR_NEW = new Type("ParNew", Generation.YOUNG); // parallel
502508
public static final Type ASPAR_NEW = new Type("ASParNew", Generation.YOUNG); // parallel (CMS AdaptiveSizePolicy)
@@ -519,11 +525,11 @@ public String toString() {
519525
public static final Type CMS_PERM = new Type("CMS Perm", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY);
520526

521527
// Parnew (promotion failed)
522-
public static final Type PAR_NEW_PROMOTION_FAILED = new Type("ParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
528+
public static final Type PAR_NEW_PROMOTION_FAILED = new Type("ParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
523529

524530
// CMS (concurrent mode failure / interrupted)
525-
public static final Type CMS_CMF = new Type("CMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL);
526-
public static final Type CMS_CMI = new Type("CMS (concurrent mode interrupted)", Generation.TENURED, Concurrency.SERIAL);
531+
public static final Type CMS_CMF = new Type("CMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL);
532+
public static final Type CMS_CMI = new Type("CMS (concurrent mode interrupted)", Generation.TENURED, Concurrency.SERIAL);
527533

528534
// CMS (Concurrent Mark Sweep) Event Types
529535
public static final Type CMS_CONCURRENT_MARK_START = new Type("CMS-concurrent-mark-start", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC);
@@ -544,7 +550,7 @@ public String toString() {
544550
public static final Type ASCMS = new Type("ASCMS", Generation.TENURED);
545551

546552
// Parnew (promotion failed) AdaptiveSizePolicy
547-
public static final Type ASPAR_NEW_PROMOTION_FAILED = new Type("ASParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
553+
public static final Type ASPAR_NEW_PROMOTION_FAILED = new Type("ASParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
548554

549555
// CMS (concurrent mode failure / interrupted) AdaptiveSizePolicy
550556
public static final Type ASCMS_CMF = new Type("ASCMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL);
@@ -564,9 +570,6 @@ public String toString() {
564570
public static final Type ASCMS_INITIAL_MARK = new Type("ASCMS-initial-mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE, CollectionType.CONCURRENCY_HELPER);
565571
public static final Type ASCMS_REMARK = new Type("ASCMS-remark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY, CollectionType.CONCURRENCY_HELPER);
566572

567-
// G1 stop the world types
568-
public static final Type G1_FULL_GC_SYSTEM = new Type("Full GC (System.gc())", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
569-
570573
// only young collection
571574
public static final Type G1_YOUNG = new Type("GC pause (young)", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
572575
public static final Type G1_YOUNG_MARK_STACK_FULL = new Type("GC pause (young)Mark stack is full.", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
@@ -583,7 +586,6 @@ public String toString() {
583586

584587
// TODO: Generation: young and tenured!
585588
public static final Type G1_YOUNG_INITIAL_MARK = new Type("GC pause (young) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
586-
public static final Type G1_YOUNG_INITIAL_MARK_SYSTEM_GC = new Type("GC pause (System.gc()) (young) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
587589
public static final Type G1_YOUNG_INITIAL_MARK_TO_SPACE_OVERFLOW = new Type("GC pause (young) (to-space overflow) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
588590
// The following two Types are basically the same but in a different order. In JDK 6 the order was defined, no longer the case with JDK 7 (see: https://github.com/chewiebug/GCViewer/issues/100)
589591
public static final Type G1_YOUNG_INITIAL_MARK_TO_SPACE_EXHAUSTED = new Type("GC pause (young) (initial-mark) (to-space exhausted)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
@@ -612,7 +614,6 @@ public String toString() {
612614
// unified jvm logging generic event types
613615
public static final Type UJL_PAUSE_YOUNG = new Type("Pause Young", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
614616
public static final Type UJL_PAUSE_FULL = new Type("Pause Full", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
615-
public static final Type UJL_PAUSE_FULL_SYSTEM = new Type("Pause Full (System.gc())", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
616617

617618
// unified jvm logging cms / g1 event types
618619
public static final Type UJL_PAUSE_INITIAL_MARK = new Type("Pause Initial Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE, CollectionType.CONCURRENCY_HELPER);

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

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -127,6 +127,7 @@ public void testCMSFullGcCmsInterrupted() throws Exception {
127127
assertEquals("count", 1, model.getPause().getN());
128128

129129
assertEquals("full gc pause", 0.0089351, model.getFullGCPause().getSum(), 0.00000001);
130+
assertThat("is system gc", model.get(0).isSystem(), is(true));
130131
}
131132

132133
@Test
@@ -493,6 +494,7 @@ public void testAdaptiveSizePolicyFullSystemGc() throws Exception {
493494

494495
assertEquals("GC count", 1, model.size());
495496
assertEquals("Full GC pause", 0.0070749, model.getFullGCPause().getMax(), 0.00000001);
497+
assertThat("is system gc", model.get(0).isSystem(), is(true));
496498
}
497499

498500
@Test

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -91,7 +91,7 @@ public void testG1FullGcSystemGc() throws Exception {
9191

9292
assertEquals("count", 1, model.size());
9393
assertEquals("full gc pause", 0.1604955, model.getFullGCPause().getMax(), 0.000001);
94-
94+
assertThat("is system gc", model.get(0).isSystem(), is(true));
9595
}
9696

9797
@Test

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

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -143,4 +143,35 @@ public void extendedRemark() throws Exception {
143143
assertThat("number of errors", handler.getCount(), is(0));
144144
assertThat("pause duration", model.get(0).getPause(), closeTo(0.1005220, 0.00000001));
145145
}
146+
147+
@Test
148+
public void youngInitialMarkSystemGc() throws Exception {
149+
TestLogHandler handler = new TestLogHandler();
150+
handler.setLevel(Level.WARNING);
151+
GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1SystemGcYoung.txt");
152+
gcResource.getLogger().addHandler(handler);
153+
154+
DataReader reader = getDataReader(gcResource);
155+
GCModel model = reader.read();
156+
157+
assertThat("number of events", model.size(), is(1));
158+
assertThat("number of errors", handler.getCount(), is(0));
159+
assertThat("pause duration", model.get(0).getPause(), closeTo(0.2124664, 0.00000001));
160+
assertThat("is system gc", model.get(0).isSystem(), is(true));
161+
}
162+
163+
@Test
164+
public void youngInitialMarkMetadataThreshold() throws Exception {
165+
TestLogHandler handler = new TestLogHandler();
166+
handler.setLevel(Level.WARNING);
167+
GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1YoungMetadataGcThreshold.txt");
168+
gcResource.getLogger().addHandler(handler);
169+
170+
DataReader reader = getDataReader(gcResource);
171+
GCModel model = reader.read();
172+
173+
assertThat("number of events", model.size(), is(1));
174+
assertThat("number of errors", handler.getCount(), is(0));
175+
assertThat("pause duration", model.get(0).getPause(), closeTo(0.0229931, 0.00000001));
176+
}
146177
}

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

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

33
import static org.hamcrest.Matchers.closeTo;
4+
import static org.hamcrest.Matchers.equalTo;
45
import static org.hamcrest.Matchers.is;
56
import static org.hamcrest.Matchers.startsWith;
67
import static org.junit.Assert.assertThat;
@@ -82,7 +83,8 @@ public void parseDefaultConfiguration() throws Exception {
8283
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
8384

8485
GCEvent event = (GCEvent) model.get(0);
85-
assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString()));
86+
assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())"));
87+
assertThat("is system gc", event.isSystem(), is(true));
8688
assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024));
8789
assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024));
8890
assertThat("total heap size", event.getTotal(), is(128 * 1024));
@@ -129,7 +131,8 @@ public void parseSingleSystemGCEvent() throws Exception {
129131
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
130132

131133
GCEvent event = (GCEvent) model.get(0);
132-
assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString()));
134+
assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())"));
135+
assertThat("is system gc", event.isSystem(), is(true));
133136
assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024));
134137
assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024));
135138
assertThat("total heap size", event.getTotal(), is(128 * 1024));
@@ -146,7 +149,8 @@ public void parseSeveralSystemGCEvents() throws Exception {
146149
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
147150

148151
GCEvent event = (GCEvent) model.get(0);
149-
assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString()));
152+
assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())"));
153+
assertThat("is system gc", event.isSystem(), is(true));
150154
assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024));
151155
assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024));
152156
assertThat("total heap size", event.getTotal(), is(128 * 1024));

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

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,35 @@
1+
2661.447: [GC pause (System.gc()) (young) (initial-mark)
2+
Desired survivor size 826277888 bytes, new threshold 15 (max 15)
3+
- age 1: 3836312 bytes, 3836312 total
4+
- age 2: 56044632 bytes, 59880944 total
5+
- age 3: 27522352 bytes, 87403296 total
6+
- age 4: 18308584 bytes, 105711880 total
7+
- age 5: 14670480 bytes, 120382360 total
8+
- age 6: 10051000 bytes, 130433360 total
9+
, 0.2124664 secs]
10+
[Parallel Time: 150.8 ms, GC Workers: 8]
11+
[GC Worker Start (ms): Min: 2661451.7, Avg: 2661451.9, Max: 2661452.2, Diff: 0.5]
12+
[Ext Root Scanning (ms): Min: 5.8, Avg: 7.8, Max: 9.3, Diff: 3.5, Sum: 62.6]
13+
[Update RS (ms): Min: 15.7, Avg: 16.3, Max: 18.4, Diff: 2.7, Sum: 130.1]
14+
[Processed Buffers: Min: 16, Avg: 31.0, Max: 63, Diff: 47, Sum: 248]
15+
[Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 1.5]
16+
[Code Root Scanning (ms): Min: 0.0, Avg: 1.5, Max: 2.3, Diff: 2.3, Sum: 12.1]
17+
[Object Copy (ms): Min: 120.9, Avg: 123.0, Max: 124.5, Diff: 3.5, Sum: 984.1]
18+
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
19+
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
20+
[GC Worker Other (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 2.0]
21+
[GC Worker Total (ms): Min: 148.8, Avg: 149.1, Max: 149.4, Diff: 0.6, Sum: 1192.5]
22+
[GC Worker End (ms): Min: 2661600.8, Avg: 2661601.0, Max: 2661601.1, Diff: 0.3]
23+
[Code Root Fixup: 0.2 ms]
24+
[Code Root Purge: 0.2 ms]
25+
[Clear CT: 2.6 ms]
26+
[Other: 58.7 ms]
27+
[Choose CSet: 0.0 ms]
28+
[Ref Proc: 50.6 ms]
29+
[Ref Enq: 0.6 ms]
30+
[Redirty Cards: 0.9 ms]
31+
[Humongous Register: 0.1 ms]
32+
[Humongous Reclaim: 0.0 ms]
33+
[Free CSet: 2.3 ms]
34+
[Eden: 8944.0M(12.1G)->0.0B(12.1G) Survivors: 144.0M->376.0M Heap: 22.7G(30.0G)->14.2G(30.0G)]
35+
[Times: user=1.13 sys=0.10, real=0.21 secs]

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

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,29 @@
1+
58.352: [GC pause (Metadata GC Threshold) (young) (initial-mark)
2+
Desired survivor size 50331648 bytes, new threshold 15 (max 15)
3+
, 0.0229931 secs]
4+
[Parallel Time: 17.8 ms, GC Workers: 8]
5+
[GC Worker Start (ms): Min: 58352.7, Avg: 58353.6, Max: 58354.1, Diff: 1.4]
6+
[Ext Root Scanning (ms): Min: 5.2, Avg: 6.2, Max: 7.2, Diff: 2.0, Sum: 49.2]
7+
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
8+
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
9+
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
10+
[Code Root Scanning (ms): Min: 0.0, Avg: 4.6, Max: 10.3, Diff: 10.3, Sum: 36.9]
11+
[Object Copy (ms): Min: 0.0, Avg: 5.2, Max: 9.4, Diff: 9.4, Sum: 41.5]
12+
[Termination (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 6.3]
13+
[Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
14+
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
15+
[GC Worker Total (ms): Min: 16.2, Avg: 16.7, Max: 17.7, Diff: 1.5, Sum: 134.0]
16+
[GC Worker End (ms): Min: 58370.3, Avg: 58370.3, Max: 58370.3, Diff: 0.0]
17+
[Code Root Fixup: 0.0 ms]
18+
[Code Root Purge: 0.0 ms]
19+
[Clear CT: 0.7 ms]
20+
[Other: 4.4 ms]
21+
[Choose CSet: 0.0 ms]
22+
[Ref Proc: 3.3 ms]
23+
[Ref Enq: 0.1 ms]
24+
[Redirty Cards: 0.6 ms]
25+
[Humongous Register: 0.0 ms]
26+
[Humongous Reclaim: 0.0 ms]
27+
[Free CSet: 0.1 ms]
28+
[Eden: 264.0M(768.0M)->0.0B(752.0M) Survivors: 0.0B->16.0M Heap: 264.0M(8192.0M)->13.6M(8192.0M)]
29+
[Times: user=0.10 sys=0.00, real=0.03 secs]

0 commit comments

Comments
 (0)