#200 generalise handling of System.gc() events

chewiebug · Aug 1, 2018 · d7ec81b · d7ec81b
1 parent 381e973
commit d7ec81b
Show file tree

Hide file tree

Showing 8 changed files with 118 additions and 16 deletions.
diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java
@@ -13,7 +13,7 @@
  */
 public class DataReaderTools {
 
-    private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?");
+    private static Pattern parenthesesPattern = Pattern.compile("\\([^)]*(\\))?\\) ?");
 
     private Logger logger;
 

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
@@ -248,6 +248,14 @@ public boolean isFull() {
         return false;
     }
 
+    /**
+     * Returns true, if this event was triggered by a call to "System.gc()"
+     * @return <code>true</code> if triggered by "System.gc()"
+     */
+    public boolean isSystem() {
+        return getExtendedType().getName().contains("System");
+    }
+
     public boolean isInc() {
         return getExtendedType().getType() == GCEvent.Type.INC_GC;
     }
@@ -494,9 +502,7 @@ public String toString() {
         public static final Type SCAVENGE_BEFORE_REMARK = new Type("Scavenge-Before-Remark", Generation.ALL);
 
         public static final Type FULL_GC = new Type("Full GC", Generation.ALL);
-        public static final Type FULL_GC_SYSTEM = new Type("Full GC (System)", Generation.ALL);
         public static final Type GC = new Type("GC", Generation.YOUNG);
-        public static final Type GC_SYSTEM = new Type("GC (System.gc())", Generation.YOUNG);
         public static final Type DEF_NEW = new Type("DefNew", Generation.YOUNG, Concurrency.SERIAL); // single threaded
         public static final Type PAR_NEW = new Type("ParNew", Generation.YOUNG); // parallel
         public static final Type ASPAR_NEW = new Type("ASParNew", Generation.YOUNG); // parallel (CMS AdaptiveSizePolicy)
@@ -519,11 +525,11 @@ public String toString() {
         public static final Type CMS_PERM = new Type("CMS Perm", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY);
 
         // Parnew (promotion failed)
-        public static final Type PAR_NEW_PROMOTION_FAILED = new Type("ParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
+         public static final Type PAR_NEW_PROMOTION_FAILED = new Type("ParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
 
         // CMS (concurrent mode failure / interrupted)
-        public static final Type CMS_CMF = new Type("CMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL);
-        public static final Type CMS_CMI = new Type("CMS (concurrent mode interrupted)", Generation.TENURED, Concurrency.SERIAL);
+         public static final Type CMS_CMF = new Type("CMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL);
+         public static final Type CMS_CMI = new Type("CMS (concurrent mode interrupted)", Generation.TENURED, Concurrency.SERIAL);
 
         // CMS (Concurrent Mark Sweep) Event Types
         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() {
         public static final Type ASCMS = new Type("ASCMS", Generation.TENURED);
 
         // Parnew (promotion failed) AdaptiveSizePolicy
-        public static final Type ASPAR_NEW_PROMOTION_FAILED = new Type("ASParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
+         public static final Type ASPAR_NEW_PROMOTION_FAILED = new Type("ASParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL);
 
         // CMS (concurrent mode failure / interrupted) AdaptiveSizePolicy
         public static final Type ASCMS_CMF = new Type("ASCMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL);
@@ -564,9 +570,6 @@ public String toString() {
         public static final Type ASCMS_INITIAL_MARK = new Type("ASCMS-initial-mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE, CollectionType.CONCURRENCY_HELPER);
         public static final Type ASCMS_REMARK = new Type("ASCMS-remark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY, CollectionType.CONCURRENCY_HELPER);
 
-        // G1 stop the world types
-        public static final Type G1_FULL_GC_SYSTEM = new Type("Full GC (System.gc())", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
-
         // only young collection
         public static final Type G1_YOUNG = new Type("GC pause (young)", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
         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() {
 
         // TODO: Generation: young and tenured!
         public static final Type G1_YOUNG_INITIAL_MARK = new Type("GC pause (young) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
-        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);
         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);
         // 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)
         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() {
         // unified jvm logging generic event types
         public static final Type UJL_PAUSE_YOUNG = new Type("Pause Young", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
         public static final Type UJL_PAUSE_FULL = new Type("Pause Full", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
-        public static final Type UJL_PAUSE_FULL_SYSTEM = new Type("Pause Full (System.gc())", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
 
         // unified jvm logging cms / g1 event types
         public static final Type UJL_PAUSE_INITIAL_MARK = new Type("Pause Initial Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE, CollectionType.CONCURRENCY_HELPER);

diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0.java
@@ -127,6 +127,7 @@ public void testCMSFullGcCmsInterrupted() throws Exception {
 		assertEquals("count", 1, model.getPause().getN());
 
 		assertEquals("full gc pause", 0.0089351, model.getFullGCPause().getSum(), 0.00000001);
+		assertThat("is system gc", model.get(0).isSystem(), is(true));
 	}
 
     @Test
@@ -493,6 +494,7 @@ public void testAdaptiveSizePolicyFullSystemGc() throws Exception {
 
         assertEquals("GC count", 1, model.size());
         assertEquals("Full GC pause", 0.0070749, model.getFullGCPause().getMax(), 0.00000001);
+        assertThat("is system gc", model.get(0).isSystem(), is(true));
     }
 
     @Test

diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0G1.java
@@ -91,7 +91,7 @@ public void testG1FullGcSystemGc() throws Exception {
 
 		assertEquals("count", 1, model.size());
 		assertEquals("full gc pause", 0.1604955, model.getFullGCPause().getMax(), 0.000001);
-
+        assertThat("is system gc", model.get(0).isSystem(), is(true));
     }
 
     @Test

diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java
@@ -143,4 +143,35 @@ public void extendedRemark() throws Exception {
         assertThat("number of errors", handler.getCount(), is(0));
         assertThat("pause duration", model.get(0).getPause(), closeTo(0.1005220, 0.00000001));
     }
+
+    @Test
+    public void youngInitialMarkSystemGc() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1SystemGcYoung.txt");
+        gcResource.getLogger().addHandler(handler);
+
+        DataReader reader = getDataReader(gcResource);
+        GCModel model = reader.read();
+
+        assertThat("number of events", model.size(), is(1));
+        assertThat("number of errors", handler.getCount(), is(0));
+        assertThat("pause duration", model.get(0).getPause(), closeTo(0.2124664, 0.00000001));
+        assertThat("is system gc", model.get(0).isSystem(), is(true));
+    }
+
+    @Test
+    public void youngInitialMarkMetadataThreshold() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1YoungMetadataGcThreshold.txt");
+        gcResource.getLogger().addHandler(handler);
+
+        DataReader reader = getDataReader(gcResource);
+        GCModel model = reader.read();
+
+        assertThat("number of events", model.size(), is(1));
+        assertThat("number of errors", handler.getCount(), is(0));
+        assertThat("pause duration", model.get(0).getPause(), closeTo(0.0229931, 0.00000001));
+    }
 }
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java
@@ -1,6 +1,7 @@
 package com.tagtraum.perf.gcviewer.imp;
 
 import static org.hamcrest.Matchers.closeTo;
+import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.is;
 import static org.hamcrest.Matchers.startsWith;
 import static org.junit.Assert.assertThat;
@@ -82,7 +83,8 @@ public void parseDefaultConfiguration() throws Exception {
         assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
 
         GCEvent event = (GCEvent) model.get(0);
-        assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString()));
+        assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())"));
+        assertThat("is system gc", event.isSystem(), is(true));
         assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024));
         assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024));
         assertThat("total heap size", event.getTotal(), is(128 * 1024));
@@ -129,7 +131,8 @@ public void parseSingleSystemGCEvent() throws Exception {
         assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
 
         GCEvent event = (GCEvent) model.get(0);
-        assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString()));
+        assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())"));
+        assertThat("is system gc", event.isSystem(), is(true));
         assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024));
         assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024));
         assertThat("total heap size", event.getTotal(), is(128 * 1024));
@@ -146,7 +149,8 @@ public void parseSeveralSystemGCEvents() throws Exception {
         assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
 
         GCEvent event = (GCEvent) model.get(0);
-        assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString()));
+        assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())"));
+        assertThat("is system gc", event.isSystem(), is(true));
         assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024));
         assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024));
         assertThat("total heap size", event.getTotal(), is(128 * 1024));

diff --git a/src/test/resources/openjdk/SampleSun1_8_0G1SystemGcYoung.txt b/src/test/resources/openjdk/SampleSun1_8_0G1SystemGcYoung.txt
@@ -0,0 +1,35 @@
+2661.447: [GC pause (System.gc()) (young) (initial-mark)
+Desired survivor size 826277888 bytes, new threshold 15 (max 15)
+- age   1:    3836312 bytes,    3836312 total
+- age   2:   56044632 bytes,   59880944 total
+- age   3:   27522352 bytes,   87403296 total
+- age   4:   18308584 bytes,  105711880 total
+- age   5:   14670480 bytes,  120382360 total
+- age   6:   10051000 bytes,  130433360 total
+, 0.2124664 secs]
+   [Parallel Time: 150.8 ms, GC Workers: 8]
+      [GC Worker Start (ms): Min: 2661451.7, Avg: 2661451.9, Max: 2661452.2, Diff: 0.5]
+      [Ext Root Scanning (ms): Min: 5.8, Avg: 7.8, Max: 9.3, Diff: 3.5, Sum: 62.6]
+      [Update RS (ms): Min: 15.7, Avg: 16.3, Max: 18.4, Diff: 2.7, Sum: 130.1]
+         [Processed Buffers: Min: 16, Avg: 31.0, Max: 63, Diff: 47, Sum: 248]
+      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 1.5]
+      [Code Root Scanning (ms): Min: 0.0, Avg: 1.5, Max: 2.3, Diff: 2.3, Sum: 12.1]
+      [Object Copy (ms): Min: 120.9, Avg: 123.0, Max: 124.5, Diff: 3.5, Sum: 984.1]
+      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
+         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
+      [GC Worker Other (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 2.0]
+      [GC Worker Total (ms): Min: 148.8, Avg: 149.1, Max: 149.4, Diff: 0.6, Sum: 1192.5]
+      [GC Worker End (ms): Min: 2661600.8, Avg: 2661601.0, Max: 2661601.1, Diff: 0.3]
+   [Code Root Fixup: 0.2 ms]
+   [Code Root Purge: 0.2 ms]
+   [Clear CT: 2.6 ms]
+   [Other: 58.7 ms]
+      [Choose CSet: 0.0 ms]
+      [Ref Proc: 50.6 ms]
+      [Ref Enq: 0.6 ms]
+      [Redirty Cards: 0.9 ms]
+      [Humongous Register: 0.1 ms]
+      [Humongous Reclaim: 0.0 ms]
+      [Free CSet: 2.3 ms]
+   [Eden: 8944.0M(12.1G)->0.0B(12.1G) Survivors: 144.0M->376.0M Heap: 22.7G(30.0G)->14.2G(30.0G)]
+ [Times: user=1.13 sys=0.10, real=0.21 secs]
diff --git a/src/test/resources/openjdk/SampleSun1_8_0G1YoungMetadataGcThreshold.txt b/src/test/resources/openjdk/SampleSun1_8_0G1YoungMetadataGcThreshold.txt
@@ -0,0 +1,29 @@
+58.352: [GC pause (Metadata GC Threshold) (young) (initial-mark)
+Desired survivor size 50331648 bytes, new threshold 15 (max 15)
+, 0.0229931 secs]
+   [Parallel Time: 17.8 ms, GC Workers: 8]
+      [GC Worker Start (ms): Min: 58352.7, Avg: 58353.6, Max: 58354.1, Diff: 1.4]
+      [Ext Root Scanning (ms): Min: 5.2, Avg: 6.2, Max: 7.2, Diff: 2.0, Sum: 49.2]
+      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
+         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
+      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
+      [Code Root Scanning (ms): Min: 0.0, Avg: 4.6, Max: 10.3, Diff: 10.3, Sum: 36.9]
+      [Object Copy (ms): Min: 0.0, Avg: 5.2, Max: 9.4, Diff: 9.4, Sum: 41.5]
+      [Termination (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 6.3]
+         [Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
+      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
+      [GC Worker Total (ms): Min: 16.2, Avg: 16.7, Max: 17.7, Diff: 1.5, Sum: 134.0]
+      [GC Worker End (ms): Min: 58370.3, Avg: 58370.3, Max: 58370.3, Diff: 0.0]
+   [Code Root Fixup: 0.0 ms]
+   [Code Root Purge: 0.0 ms]
+   [Clear CT: 0.7 ms]
+   [Other: 4.4 ms]
+      [Choose CSet: 0.0 ms]
+      [Ref Proc: 3.3 ms]
+      [Ref Enq: 0.1 ms]
+      [Redirty Cards: 0.6 ms]
+      [Humongous Register: 0.0 ms]
+      [Humongous Reclaim: 0.0 ms]
+      [Free CSet: 0.1 ms]
+   [Eden: 264.0M(768.0M)->0.0B(752.0M) Survivors: 0.0B->16.0M Heap: 264.0M(8192.0M)->13.6M(8192.0M)]
+ [Times: user=0.10 sys=0.00, real=0.03 secs]
-Original file line number
+Diff line change
@@ Expand Up / @@ -91,7 +91,7 @@ public void testG1FullGcSystemGc() throws Exception { @@
     		assertEquals("count", 1, model.size());
     		assertEquals("full gc pause", 0.1604955, model.getFullGCPause().getMax(), 0.000001);
+            assertThat("is system gc", model.get(0).isSystem(), is(true));
         }
         @Test
@@ Expand Down @@