diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewCmsSerialOldEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewCmsSerialOldEvent.java index fab8c321..fe01253d 100644 --- 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->2176K(19648K), 0.0184470 secs]6.121: [Tenured: 44849K->25946K(44864K), 0.2586250 secs] 60100K->25946K(64512K), [Perm : 43759K->43759K(262144K)], 0.2773070 secs] [Times: user=0.16 sys=0.01, real=0.28 secs] * * + *

+ * 3) JDK 1.8 + *

+ * + * 
+ * 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]
+ *
+ * * @author Mike Millson * @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/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewConcurrentModeFailurePermDataEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewConcurrentModeFailurePermDataEvent.java index 708124be..6ccdfb1e 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewConcurrentModeFailurePermDataEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewConcurrentModeFailurePermDataEvent.java @@ -73,7 +73,7 @@ *

Example Logging

* *

- * {@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: *

* @@ -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] * * + *

+ * 2) JDK8 with Metaspace: + *

+ * + * 
+ * 1202.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]
+ *  (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]
+ *
+ * + *

+ * Preprocessed: + *

+ * + * 
+ * 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]
+ * 1203.491: [CMS-concurrent-sweep: 1.009/1.060 secs] [Times: user=1.55 sys=0.12, real=1.06 secs]
+ *
+ * * @author Mike Millson * @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 index abe25ac9..5104018f 100644 --- a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/CmsPreprocessAction.java +++ b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/CmsPreprocessAction.java @@ -158,7 +158,7 @@ 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 + "?)[ ]*$"; /** @@ -166,7 +166,7 @@ public class CmsPreprocessAction implements PreprocessAction { */ 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 index ef629fbc..43860cf4 100644 --- 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/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewConcurrentModeFailurePermDataEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewConcurrentModeFailurePermDataEvent.java index a3d9aa3b..0b4c44e4 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewConcurrentModeFailurePermDataEvent.java +++ b/src/test/java/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 index 182fe684..64f01cb3 100644 --- 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. *