Additional CMS preprocessing and logging patterns for concurrent mode

failures.
mgm3746 · Oct 1, 2016 · 0fbdf4c · 0fbdf4c
1 parent 8d501e0
commit 0fbdf4c
Show file tree

Hide file tree

Showing 6 changed files with 139 additions and 22 deletions.
diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewCmsSerialOldEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewCmsSerialOldEvent.java
@@ -20,6 +20,7 @@
 import org.eclipselabs.garbagecat.domain.OldData;
 import org.eclipselabs.garbagecat.domain.PermCollection;
 import org.eclipselabs.garbagecat.domain.PermData;
+import org.eclipselabs.garbagecat.domain.TriggerData;
 import org.eclipselabs.garbagecat.domain.YoungData;
 import org.eclipselabs.garbagecat.util.jdk.JdkMath;
 import org.eclipselabs.garbagecat.util.jdk.JdkRegEx;
@@ -54,22 +55,37 @@
  * 6.102: [GC6.102: [ParNew: 19648K-&gt;2176K(19648K), 0.0184470 secs]6.121: [Tenured: 44849K-&gt;25946K(44864K), 0.2586250 secs] 60100K-&gt;25946K(64512K), [Perm : 43759K-&gt;43759K(262144K)], 0.2773070 secs] [Times: user=0.16 sys=0.01, real=0.28 secs]
  * </pre>
  * 
+ * <p>
+ * 3) JDK 1.8
+ * </p>
+ * 
+ * <pre>
+ * 1817.644: [GC (Allocation Failure) 1817.646: [ParNew: 1382383K-&gt;1382383K(1382400K), 0.0000530 secs]1817.646: [CMS: 2658303K-&gt;2658303K(2658304K), 8.7951430 secs] 4040686K-&gt;2873414K(4040704K), [Metaspace: 72200K-&gt;72200K(1118208K)], 8.7986750 secs] [Times: user=8.79 sys=0.01, real=8.80 secs]
+ * </pre>
+ * 
  * @author <a href="mailto:mmillson@redhat.com">Mike Millson</a>
  * @author jborelo
  * 
  */
-public class ParNewCmsSerialOldEvent
-        implements BlockingEvent, OldCollection, YoungData, OldData, CmsCollection, PermCollection, PermData {
+public class ParNewCmsSerialOldEvent implements BlockingEvent, OldCollection, YoungData, OldData, CmsCollection,
+        PermCollection, PermData, TriggerData {
+
+    /**
+     * The trigger for the GC event.
+     */
+    private String trigger;
 
     /**
      * Regular expressions defining the logging.
      */
-    private static final String REGEX = "^" + JdkRegEx.TIMESTAMP + ": \\[GC( )?" + JdkRegEx.TIMESTAMP + ": \\[ParNew: "
-            + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]"
-            + JdkRegEx.TIMESTAMP + ": \\[Tenured: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE
-            + "\\), " + JdkRegEx.DURATION + "\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE
-            + "\\)(, \\[Perm : " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\])?, "
-            + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$";
+    private static final String REGEX = "^" + JdkRegEx.TIMESTAMP + ": \\[GC( )?(\\(("
+            + JdkRegEx.TRIGGER_ALLOCATION_FAILURE + ")\\) )?" + JdkRegEx.TIMESTAMP + ": \\[ParNew: " + JdkRegEx.SIZE
+            + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMESTAMP
+            + ": \\[(Tenured|CMS): " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), "
+            + JdkRegEx.DURATION + "\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE
+            + "\\)(, \\[(Perm |Metaspace): " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE
+            + "\\)\\])?, " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$";
+
     private static Pattern pattern = Pattern.compile(ParNewCmsSerialOldEvent.REGEX);
 
     /**
@@ -143,22 +159,25 @@ public ParNewCmsSerialOldEvent(String logEntry) {
         Matcher matcher = pattern.matcher(logEntry);
         if (matcher.find()) {
             timestamp = JdkMath.convertSecsToMillis(matcher.group(1)).longValue();
-            young = Integer.parseInt(matcher.group(4));
-            old = Integer.parseInt(matcher.group(9));
-            oldEnd = Integer.parseInt(matcher.group(10));
-            oldAllocation = Integer.parseInt(matcher.group(11));
+            if (matcher.group(3) != null) {
+                trigger = matcher.group(4);
+            }
+            young = Integer.parseInt(matcher.group(6));
+            old = Integer.parseInt(matcher.group(12));
+            oldEnd = Integer.parseInt(matcher.group(13));
+            oldAllocation = Integer.parseInt(matcher.group(14));
             // Compute young end and young allocation after full GC
-            int totalEnd = Integer.parseInt(matcher.group(14));
+            int totalEnd = Integer.parseInt(matcher.group(17));
             youngEnd = totalEnd - oldEnd;
-            int totalAllocation = Integer.parseInt(matcher.group(15));
+            int totalAllocation = Integer.parseInt(matcher.group(18));
             youngAvailable = totalAllocation - oldAllocation;
-            if (matcher.group(16) != null) {
-                permGen = Integer.parseInt(matcher.group(17));
-                permGenEnd = Integer.parseInt(matcher.group(18));
-                permGenAllocation = Integer.parseInt(matcher.group(19));
+            if (matcher.group(19) != null) {
+                permGen = Integer.parseInt(matcher.group(21));
+                permGenEnd = Integer.parseInt(matcher.group(22));
+                permGenAllocation = Integer.parseInt(matcher.group(23));
 
             }
-            duration = JdkMath.convertSecsToMillis(matcher.group(20)).intValue();
+            duration = JdkMath.convertSecsToMillis(matcher.group(24)).intValue();
         }
     }
 
@@ -230,6 +249,10 @@ public String getName() {
         return JdkUtil.LogEventType.PAR_NEW_CMS_SERIAL_OLD.toString();
     }
 
+    public String getTrigger() {
+        return trigger;
+    }
+
     /**
      * Determine if the logLine matches the logging pattern(s) for this event.
      * 

diff --git a/.../java/org/eclipselabs/garbagecat/domain/jdk/ParNewConcurrentModeFailurePermDataEvent.java b/.../java/org/eclipselabs/garbagecat/domain/jdk/ParNewConcurrentModeFailurePermDataEvent.java
@@ -73,7 +73,7 @@
  * <h3>Example Logging</h3>
  * 
  * <p>
- * {@link org.eclipselabs.garbagecat.domain.jdk.ParNewConcurrentModeFailurePermDataEvent} combined with
+ * 1) {@link org.eclipselabs.garbagecat.domain.jdk.ParNewConcurrentModeFailurePermDataEvent} combined with
  * {@link org.eclipselabs.garbagecat.domain.jdk.CmsConcurrentEvent} across 2 lines:
  * </p>
  * 
@@ -91,6 +91,24 @@
  * 3081.621: [CMS-concurrent-mark: 11.907/12.958 secs] [Times: user=45.31 sys=3.93, real=12.96 secs]
  * </pre>
  * 
+ * <p>
+ * 2) JDK8 with Metaspace:
+ * </p>
+ * 
+ * <pre>
+ * 1202.526: [GC (Allocation Failure) 1202.528: [ParNew: 1355422K-&gt;1355422K(1382400K), 0.0000500 secs]1202.528: [CMS1203.491: [CMS-concurrent-sweep: 1.009/1.060 secs] [Times: user=1.55 sys=0.12, real=1.06 secs]
+ *  (concurrent mode failure): 2656311K-&gt;2658289K(2658304K), 9.3575580 secs] 4011734K-&gt;2725109K(4040704K), [Metaspace: 72111K-&gt;72111K(1118208K)], 9.3610080 secs] [Times: user=9.35 sys=0.01, real=9.36 secs]
+ * </pre>
+ * 
+ * <p>
+ * Preprocessed:
+ * </p>
+ * 
+ * <pre>
+ * 1202.526: [GC (Allocation Failure) 1202.528: [ParNew: 1355422K-&gt;1355422K(1382400K), 0.0000500 secs]1202.528: [CMS (concurrent mode failure): 2656311K-&gt;2658289K(2658304K), 9.3575580 secs] 4011734K-&gt;2725109K(4040704K), [Metaspace: 72111K-&gt;72111K(1118208K)], 9.3610080 secs] [Times: user=9.35 sys=0.01, real=9.36 secs]
+ * 1203.491: [CMS-concurrent-sweep: 1.009/1.060 secs] [Times: user=1.55 sys=0.12, real=1.06 secs]
+ * </pre>
+ * 
  * @author <a href="mailto:mmillson@redhat.com">Mike Millson</a>
  * @author jborelo
  */

diff --git a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/CmsPreprocessAction.java b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/CmsPreprocessAction.java
@@ -158,15 +158,15 @@ public class CmsPreprocessAction implements PreprocessAction {
             + JdkRegEx.TRIGGER_ALLOCATION_FAILURE + "\\))?( )?" + JdkRegEx.TIMESTAMP + ": \\[ParNew( \\("
             + JdkRegEx.TRIGGER_PROMOTION_FAILED + "\\))?(: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\("
             + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMESTAMP + ": \\[CMS)?)("
-            + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(abortable-preclean|mark): " + JdkRegEx.DURATION_FRACTION
+            + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(abortable-preclean|mark|sweep): " + JdkRegEx.DURATION_FRACTION
             + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$";
 
     /**
      * Regular expression for retained beginning CMS_SERIAL_OLD mixed with CMS_CONCURRENT collection.
      */
     private static final String REGEX_RETAIN_BEGINNING_SERIAL_CONCURRENT = "^(" + JdkRegEx.TIMESTAMP
             + ": \\[Full GC( )?(\\(" + JdkRegEx.TRIGGER_ALLOCATION_FAILURE + "\\) )?" + JdkRegEx.TIMESTAMP
-            + ": \\[CMS)(" + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(mark|abortable-preclean): "
+            + ": \\[CMS)(" + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(mark|abortable-preclean|preclean|sweep): "
             + JdkRegEx.DURATION_FRACTION + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$";
 
     /**

diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewCmsSerialOldEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewCmsSerialOldEvent.java
@@ -84,4 +84,25 @@ public void testLogLineWithPermData() {
         Assert.assertEquals("Perm gen allocation size not parsed correctly.", 262144, event.getPermSpace());
         Assert.assertEquals("Duration not parsed correctly.", 277, event.getDuration());
     }
+
+    public void testLogLineJdk8() {
+        String logLine = "1817.644: [GC (Allocation Failure) 1817.646: [ParNew: 1382383K->1382383K(1382400K), "
+                + "0.0000530 secs]1817.646: [CMS: 2658303K->2658303K(2658304K), 8.7951430 secs] "
+                + "4040686K->2873414K(4040704K), [Metaspace: 72200K->72200K(1118208K)], 8.7986750 secs] "
+                + "[Times: user=8.79 sys=0.01, real=8.80 secs]";
+        Assert.assertTrue("Log line not recognized as " + JdkUtil.LogEventType.PAR_NEW_CMS_SERIAL_OLD.toString() + ".",
+                ParNewCmsSerialOldEvent.match(logLine));
+        ParNewCmsSerialOldEvent event = new ParNewCmsSerialOldEvent(logLine);
+        Assert.assertEquals("Time stamp not parsed correctly.", 1817644, event.getTimestamp());
+        Assert.assertEquals("Young begin size not parsed correctly.", 1382383, event.getYoungOccupancyInit());
+        Assert.assertEquals("Young end size not parsed correctly.", 2873414 - 2658303, event.getYoungOccupancyEnd());
+        Assert.assertEquals("Young available size not parsed correctly.", 4040704 - 2658304, event.getYoungSpace());
+        Assert.assertEquals("Old begin size not parsed correctly.", 2658303, event.getOldOccupancyInit());
+        Assert.assertEquals("Old end size not parsed correctly.", 2658303, event.getOldOccupancyEnd());
+        Assert.assertEquals("Old allocation size not parsed correctly.", 2658304, event.getOldSpace());
+        Assert.assertEquals("Perm gen begin size not parsed correctly.", 72200, event.getPermOccupancyInit());
+        Assert.assertEquals("Perm gen end size not parsed correctly.", 72200, event.getPermOccupancyEnd());
+        Assert.assertEquals("Perm gen allocation size not parsed correctly.", 1118208, event.getPermSpace());
+        Assert.assertEquals("Duration not parsed correctly.", 8798, event.getDuration());
+    }
 }
diff --git a/...a/org/eclipselabs/garbagecat/domain/jdk/TestParNewConcurrentModeFailurePermDataEvent.java b/...a/org/eclipselabs/garbagecat/domain/jdk/TestParNewConcurrentModeFailurePermDataEvent.java
@@ -71,6 +71,30 @@ public void testLogLineMetaspaceIcrementalMode() {
         Assert.assertEquals("Duration not parsed correctly.", 12348, event.getDuration());
     }
 
+    public void testLogLineConcurrentSweep() {
+        String logLine = "1202.526: [GC (Allocation Failure) 1202.528: [ParNew: 1355422K->1355422K(1382400K), "
+                + "0.0000500 secs]1202.528: [CMS (concurrent mode failure): 2656311K->2658289K(2658304K), "
+                + "9.3575580 secs] 4011734K->2725109K(4040704K), [Metaspace: 72111K->72111K(1118208K)], "
+                + "9.3610080 secs] [Times: user=9.35 sys=0.01, real=9.36 secs]";
+        Assert.assertTrue(
+                "Log line not recognized as "
+                        + JdkUtil.LogEventType.PAR_NEW_CONCURRENT_MODE_FAILURE_PERM_DATA.toString() + ".",
+                ParNewConcurrentModeFailurePermDataEvent.match(logLine));
+        ParNewConcurrentModeFailurePermDataEvent event = new ParNewConcurrentModeFailurePermDataEvent(logLine);
+        Assert.assertEquals("Time stamp not parsed correctly.", 1202526, event.getTimestamp());
+        Assert.assertEquals("Young begin size not parsed correctly.", (4011734 - 2656311),
+                event.getYoungOccupancyInit());
+        Assert.assertEquals("Young end size not parsed correctly.", (2725109 - 2658289), event.getYoungOccupancyEnd());
+        Assert.assertEquals("Young available size not parsed correctly.", (4040704 - 2658304), event.getYoungSpace());
+        Assert.assertEquals("Old begin size not parsed correctly.", 2656311, event.getOldOccupancyInit());
+        Assert.assertEquals("Old end size not parsed correctly.", 2658289, event.getOldOccupancyEnd());
+        Assert.assertEquals("Old allocation size not parsed correctly.", 2658304, event.getOldSpace());
+        Assert.assertEquals("Metaspace begin size not parsed correctly.", 72111, event.getPermOccupancyInit());
+        Assert.assertEquals("Metaspace end size not parsed correctly.", 72111, event.getPermOccupancyEnd());
+        Assert.assertEquals("Metaspace allocation size not parsed correctly.", 1118208, event.getPermSpace());
+        Assert.assertEquals("Duration not parsed correctly.", 9361, event.getDuration());
+    }
+
     public void testLogLineWhitespaceAtEnd() {
         String logLine = "3070.289: [GC 3070.289: [ParNew: 207744K->207744K(242304K), 0.0000682 secs]3070.289: "
                 + "[CMS (concurrent mode failure): 6010121K->6014591K(6014592K), 79.0505229 secs] "

diff --git a/src/test/java/org/eclipselabs/garbagecat/preprocess/jdk/TestCmsPreprocessAction.java b/src/test/java/org/eclipselabs/garbagecat/preprocess/jdk/TestCmsPreprocessAction.java
@@ -209,6 +209,37 @@ public void testLogLineMiddle() {
                 CmsPreprocessAction.match(logLine, null, null));
     }
 
+    public void testLogLineParNewConcurrentModeFailurePermDataMixedConcurrentSweep() {
+        String logLine = "11202.526: [GC (Allocation Failure) 1202.528: [ParNew: 1355422K->1355422K(1382400K), "
+                + "0.0000500 secs]1202.528: [CMS1203.491: [CMS-concurrent-sweep: 1.009/1.060 secs] "
+                + "[Times: user=1.55 sys=0.12, real=1.06 secs]";
+        String nextLogLine = " (concurrent mode failure): 2656311K->2658289K(2658304K), 9.3575580 secs] "
+                + "4011734K->2725109K(4040704K), [Metaspace: 72111K->72111K(1118208K)], 9.3610080 secs] "
+                + "[Times: user=9.35 sys=0.01, real=9.36 secs]";
+        Assert.assertTrue("Log line not recognized as " + JdkUtil.PreprocessActionType.CMS.toString() + ".",
+                CmsPreprocessAction.match(logLine, null, nextLogLine));
+    }
+
+    public void testLogLineCmsSerialOldWithConcurrentModeFailureMixedConcurrentPreclean() {
+        String logLine = "1278.200: [Full GC (Allocation Failure) 1278.202: [CMS1280.173: "
+                + "[CMS-concurrent-preclean: 2.819/2.865 secs] [Times: user=6.97 sys=0.41, real=2.87 secs]";
+        String nextLogLine = " (concurrent mode failure): 2658303K->2658303K(2658304K), 9.1546180 secs] "
+                + "4040703K->2750110K(4040704K), [Metaspace: 72113K->72113K(1118208K)], 9.1581450 secs] "
+                + "[Times: user=9.15 sys=0.00, real=9.16 secs]";
+        Assert.assertTrue("Log line not recognized as " + JdkUtil.PreprocessActionType.CMS.toString() + ".",
+                CmsPreprocessAction.match(logLine, null, nextLogLine));
+    }
+
+    public void testLogLineCmsSerialOldWithConcurrentModeFailureMixedConcurrentSweep() {
+        String logLine = "2440.336: [Full GC (Allocation Failure) 2440.338: [CMS"
+                + "2440.542: [CMS-concurrent-sweep: 1.137/1.183 secs] [Times: user=5.33 sys=0.51, real=1.18 secs]";
+        String nextLogLine = " (concurrent mode failure): 2658304K->2658303K(2658304K), 9.4908960 secs] "
+                + "4040703K->2996946K(4040704K), [Metaspace: 72191K->72191K(1118208K)], 9.4942330 secs] "
+                + "[Times: user=9.49 sys=0.00, real=9.49 secs]";
+        Assert.assertTrue("Log line not recognized as " + JdkUtil.PreprocessActionType.CMS.toString() + ".",
+                CmsPreprocessAction.match(logLine, null, nextLogLine));
+    }
+
     /**
      * Test PAR_NEW mixed with CMS_CONCURRENT over 2 lines.
      *