From ad209998cf63bcda2f6671de5a0d2c56cf283a98 Mon Sep 17 00:00:00 2001 From: Mike Millson Date: Wed, 19 Apr 2017 08:36:59 -0400 Subject: [PATCH] Issue #73. Initial parallelism reporting/analysis. --- .../java/org/eclipselabs/garbagecat/Main.java | 12 +++++ .../eclipselabs/garbagecat/domain/JvmRun.java | 26 ++++++++++ .../garbagecat/domain/ParallelCollection.java | 23 ++++++++ .../garbagecat/domain/TimesData.java | 50 ++++++++++++++++++ .../domain/jdk/ClassHistogramEvent.java | 3 +- .../domain/jdk/CmsInitialMarkEvent.java | 3 +- .../garbagecat/domain/jdk/CmsRemarkEvent.java | 7 +-- .../domain/jdk/CmsSerialOldEvent.java | 5 +- .../garbagecat/domain/jdk/G1CleanupEvent.java | 3 +- .../domain/jdk/G1ConcurrentEvent.java | 3 +- .../garbagecat/domain/jdk/G1FullGCEvent.java | 5 +- .../domain/jdk/G1MixedPauseEvent.java | 41 +++++++++++++-- .../garbagecat/domain/jdk/G1RemarkEvent.java | 3 +- .../domain/jdk/G1YoungInitialMarkEvent.java | 7 +-- .../domain/jdk/G1YoungPauseEvent.java | 50 +++++++++++++++--- .../garbagecat/domain/jdk/ParNewEvent.java | 32 +++++++++++- .../jdk/ParallelOldCompactingEvent.java | 34 ++++++++++-- .../domain/jdk/ParallelScavengeEvent.java | 32 +++++++++++- .../domain/jdk/ParallelSerialOldEvent.java | 3 +- .../garbagecat/domain/jdk/SerialNewEvent.java | 3 +- .../garbagecat/domain/jdk/SerialOldEvent.java | 3 +- .../eclipselabs/garbagecat/hsql/JvmDao.java | 41 +++++++++++++++ ...icationConcurrentTimePreprocessAction.java | 3 +- ...pplicationStoppedTimePreprocessAction.java | 3 +- .../preprocess/jdk/CmsPreprocessAction.java | 22 ++++---- .../preprocess/jdk/G1PreprocessAction.java | 3 +- .../jdk/ParallelPreprocessAction.java | 3 +- .../garbagecat/service/GcManager.java | 22 ++++++++ .../garbagecat/util/jdk/JdkMath.java | 52 +++++++++++++++++++ .../garbagecat/util/jdk/JdkRegEx.java | 9 ---- .../garbagecat/domain/TestJvmRun.java | 2 + .../domain/jdk/TestG1MixedPauseEvent.java | 24 +++++++++ .../domain/jdk/TestG1YoungPauseEvent.java | 27 +++++++++- .../domain/jdk/TestParNewEvent.java | 30 +++++++++++ .../jdk/TestParallelOldCompactingEvent.java | 20 ++++++- .../domain/jdk/TestParallelScavengeEvent.java | 27 ++++++++++ .../jdk/TestG1PreprocessAction.java | 1 + .../garbagecat/util/jdk/TestAnalysis.java | 1 + .../garbagecat/util/jdk/TestJdkMath.java | 41 +++++++++++++++ .../garbagecat/util/jdk/TestJdkRegEx.java | 4 +- 40 files changed, 619 insertions(+), 64 deletions(-) create mode 100644 src/main/java/org/eclipselabs/garbagecat/domain/ParallelCollection.java create mode 100644 src/main/java/org/eclipselabs/garbagecat/domain/TimesData.java diff --git a/src/main/java/org/eclipselabs/garbagecat/Main.java b/src/main/java/org/eclipselabs/garbagecat/Main.java index 07766c38..aaec0a70 100644 --- a/src/main/java/org/eclipselabs/garbagecat/Main.java +++ b/src/main/java/org/eclipselabs/garbagecat/Main.java @@ -393,6 +393,18 @@ public static void createReport(JvmRun jvmRun, String reportFileName) { bufferedWriter.write("========================================" + System.getProperty("line.separator")); + // Parallelism + if (jvmRun.getBadParallelismCount() > 0) { + // Parallelism + bufferedWriter.write("BAD PARALLELISM:" + System.getProperty("line.separator")); + bufferedWriter.write("----------------------------------------" + System.getProperty("line.separator")); + bufferedWriter + .write("# Events: " + jvmRun.getBadParallelismCount() + System.getProperty("line.separator")); + bufferedWriter.write("Worst Event: " + jvmRun.getBaddestParallelismEvent().getLogEntry() + + System.getProperty("line.separator")); + bufferedWriter.write("========================================" + System.getProperty("line.separator")); + } + // Analysis List analysis = jvmRun.getAnalysis(); if (!analysis.isEmpty()) { diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/JvmRun.java b/src/main/java/org/eclipselabs/garbagecat/domain/JvmRun.java index 0fab4fd2..35b6b75d 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/JvmRun.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/JvmRun.java @@ -160,6 +160,16 @@ public class JvmRun { */ private String lastLogLineUnprocessed; + /** + * The ParallelCollection event with the worst "bad" parallelism (0-1). + */ + private LogEvent baddestParallelismEvent; + + /** + * The number of ParallelCollection with "bad" parallelism (0-1). + */ + private long badParallelismCount; + /** * Constructor accepting throughput threshold, JVM services, and JVM environment information. * @@ -369,6 +379,22 @@ public void setLastLogLineUnprocessed(String lastLogLineUnprocessed) { this.lastLogLineUnprocessed = lastLogLineUnprocessed; } + public LogEvent getBaddestParallelismEvent() { + return baddestParallelismEvent; + } + + public void setBaddestParallelismEvent(LogEvent baddestParallelismEvent) { + this.baddestParallelismEvent = baddestParallelismEvent; + } + + public long getBadParallelismCount() { + return badParallelismCount; + } + + public void setBadParallelismCount(long badParallelismCount) { + this.badParallelismCount = badParallelismCount; + } + /** * @return Throughput based only on garbage collection as a percent rounded to the nearest integer. CG throughput is * the percent of time not spent doing GC. 0 means all time was spent doing GC. 100 means no time was spent diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/ParallelCollection.java b/src/main/java/org/eclipselabs/garbagecat/domain/ParallelCollection.java new file mode 100644 index 00000000..8b1b8834 --- /dev/null +++ b/src/main/java/org/eclipselabs/garbagecat/domain/ParallelCollection.java @@ -0,0 +1,23 @@ +/********************************************************************************************************************** + * garbagecat * + * * + * Copyright (c) 2008-2016 Red Hat, Inc. * + * * + * All rights reserved. This program and the accompanying materials are made available under the terms of the Eclipse * + * Public License v1.0 which accompanies this distribution, and is available at * + * http://www.eclipse.org/legal/epl-v10.html. * + * * + * Contributors: * + * Red Hat, Inc. - initial API and implementation * + *********************************************************************************************************************/ +package org.eclipselabs.garbagecat.domain; + +/** + * Multi-threaded collection. + * + * @author Mike Millson + * + */ +public interface ParallelCollection { + +} diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/TimesData.java b/src/main/java/org/eclipselabs/garbagecat/domain/TimesData.java new file mode 100644 index 00000000..d0763452 --- /dev/null +++ b/src/main/java/org/eclipselabs/garbagecat/domain/TimesData.java @@ -0,0 +1,50 @@ +/********************************************************************************************************************** + * garbagecat * + * * + * Copyright (c) 2008-2016 Red Hat, Inc. * + * * + * All rights reserved. This program and the accompanying materials are made available under the terms of the Eclipse * + * Public License v1.0 which accompanies this distribution, and is available at * + * http://www.eclipse.org/legal/epl-v10.html. * + * * + * Contributors: * + * Red Hat, Inc. - initial API and implementation * + *********************************************************************************************************************/ +package org.eclipselabs.garbagecat.domain; + +/** + * Times data block output at the end of some garbage collection logging events. + * + *

Example Logging

+ * + *

+ * [Times: user=0.31 sys=0.00, real=0.04 secs] + *

+ * + * @author Mike Millson + * + */ +public interface TimesData { + + /** + * Regular expression for times data block. + */ + String REGEX = "( \\[Times: user=(\\d{1,4}[\\.\\,]\\d{2}) sys=\\d{1,4}[\\.\\,]\\d{2}, " + + "real=(\\d{1,4}[\\.\\,]\\d{2}) secs\\])"; + + /** + * @return The time of all threads added together in centoseconds. + */ + int getTimeUser(); + + /** + * @return The wall (clock) time in centoseconds. + */ + int getTimeReal(); + + /** + * @return The ratio of user:real time rounded to the nearest whole number. With good parallelism, the user time + * will be (# threads) x (real time). + */ + byte getParallelism(); +} diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ClassHistogramEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ClassHistogramEvent.java index bb787090..f69e6dd7 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ClassHistogramEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ClassHistogramEvent.java @@ -13,6 +13,7 @@ package org.eclipselabs.garbagecat.domain.jdk; import org.eclipselabs.garbagecat.domain.ThrowAwayEvent; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -95,7 +96,7 @@ public class ClassHistogramEvent implements ThrowAwayEvent { /* * Preprocessed block as a single line */ - "^" + REGEX_PREPROCESSED + JdkRegEx.TIMES_BLOCK + "?[ ]*$" }; + "^" + REGEX_PREPROCESSED + TimesData.REGEX + "?[ ]*$" }; /** * The log entry for the event. Can be used for debugging purposes. diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsInitialMarkEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsInitialMarkEvent.java index 30d2bba0..f48a211e 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsInitialMarkEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsInitialMarkEvent.java @@ -16,6 +16,7 @@ import java.util.regex.Pattern; import org.eclipselabs.garbagecat.domain.BlockingEvent; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; @@ -80,7 +81,7 @@ public class CmsInitialMarkEvent extends CmsCollector implements BlockingEvent, private static final String REGEX = "^(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC (\\((" + JdkRegEx.TRIGGER_CMS_INITIAL_MARK + ")\\) )?\\[1 CMS-initial-mark: " + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] " + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + TimesData.REGEX + "?[ ]*$"; private static Pattern pattern = Pattern.compile(CmsInitialMarkEvent.REGEX); /** diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsRemarkEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsRemarkEvent.java index 4a444969..06d464d1 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsRemarkEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsRemarkEvent.java @@ -16,6 +16,7 @@ import java.util.regex.Pattern; import org.eclipselabs.garbagecat.domain.BlockingEvent; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; @@ -169,7 +170,7 @@ public class CmsRemarkEvent extends CmsIncrementalModeCollector implements Block + JdkRegEx.TIMESTAMP + ": \\[weak refs processing, " + JdkRegEx.DURATION + "\\](" + JdkRegEx.DATESTAMP + ": )?(" + JdkRegEx.TIMESTAMP + ": \\[scrub string table, " + JdkRegEx.DURATION + "\\])?[ ]{0,1}\\[1 CMS-remark: " + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] " + JdkRegEx.SIZE - + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; /** * Regular expression for JDK8 logging with {@link org.eclipselabs.garbagecat.domain.jdk.ParNewEvent} from @@ -182,7 +183,7 @@ public class CmsRemarkEvent extends CmsIncrementalModeCollector implements Block + ": \\[ParNew( \\((" + JdkRegEx.TRIGGER_PROMOTION_FAILED + ")\\))?:)? " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\] (" + JdkRegEx.SIZE + "->)?" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)" + JdkRegEx.ICMS_DC_BLOCK + "?, " + JdkRegEx.DURATION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + TimesData.REGEX + "?[ ]*$"; /** * Regular expression for class unloading enabled with -XX:+CMSClassUnloadingEnabled . @@ -199,7 +200,7 @@ public class CmsRemarkEvent extends CmsIncrementalModeCollector implements Block + JdkRegEx.DURATION + "\\])|(\\[scrub symbol table, " + JdkRegEx.DURATION + "\\](" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[scrub string table, " + JdkRegEx.DURATION + "\\]))( )?\\[1 CMS-remark: " + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] " + JdkRegEx.SIZE + "\\(" - + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; /** * Create event from log entry. diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsSerialOldEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsSerialOldEvent.java index 0cc05200..db8213f5 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsSerialOldEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/CmsSerialOldEvent.java @@ -21,6 +21,7 @@ import org.eclipselabs.garbagecat.domain.PermCollection; import org.eclipselabs.garbagecat.domain.PermData; import org.eclipselabs.garbagecat.domain.SerialCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.domain.YoungData; @@ -245,7 +246,7 @@ public class CmsSerialOldEvent extends CmsIncrementalModeCollector implements Bl + JdkRegEx.DURATION + "\\](" + ClassHistogramEvent.REGEX_PREPROCESSED + ")? " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + "\\[(CMS Perm |Metaspace): " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\]" + JdkRegEx.ICMS_DC_BLOCK + "?, " + JdkRegEx.DURATION - + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\]" + TimesData.REGEX + "?[ ]*$"; /** * Regular expression defining the logging beginning with "GC". @@ -261,7 +262,7 @@ public class CmsSerialOldEvent extends CmsIncrementalModeCollector implements Bl + ClassHistogramEvent.REGEX_PREPROCESSED + ")?( " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)(, \\[(CMS Perm |Perm |Metaspace): " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\])?" + JdkRegEx.ICMS_DC_BLOCK + "?, " + JdkRegEx.DURATION + "\\])?" - + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + TimesData.REGEX + "?[ ]*$"; /** * Create event from log entry. diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1CleanupEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1CleanupEvent.java index bb2272b0..a6363858 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1CleanupEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1CleanupEvent.java @@ -17,6 +17,7 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.CombinedData; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -68,7 +69,7 @@ public class G1CleanupEvent extends G1Collector implements BlockingEvent, Combin */ private static final String REGEX = "^(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC cleanup " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION - + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\]" + TimesData.REGEX + "?[ ]*$"; private static final Pattern pattern = Pattern.compile(REGEX); /** diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1ConcurrentEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1ConcurrentEvent.java index 5f01a7e8..f4fb96a7 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1ConcurrentEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1ConcurrentEvent.java @@ -16,6 +16,7 @@ import java.util.regex.Pattern; import org.eclipselabs.garbagecat.domain.LogEvent; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -114,7 +115,7 @@ public class G1ConcurrentEvent extends G1Collector implements LogEvent { + ": )?(: )?\\[GC concurrent-(((root-region-scan|mark|cleanup)-(start|end|abort|reset-for-overflow))" + "|string-deduplication)(\\])?(,)?( " + JdkRegEx.DURATION + ")?(\\])?( " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\))?(, avg " + JdkRegEx.PERCENT + ", " + JdkRegEx.DURATION - + "\\])?" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\])?" + TimesData.REGEX + "?[ ]*$"; private static final Pattern pattern = Pattern.compile(REGEX); diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1FullGCEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1FullGCEvent.java index bfa8a9c8..729e1f15 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1FullGCEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1FullGCEvent.java @@ -21,6 +21,7 @@ import org.eclipselabs.garbagecat.domain.PermCollection; import org.eclipselabs.garbagecat.domain.PermData; import org.eclipselabs.garbagecat.domain.SerialCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.util.jdk.JdkMath; @@ -77,7 +78,7 @@ public class G1FullGCEvent extends G1Collector implements BlockingEvent, YoungCo */ private static final String REGEX = "^" + JdkRegEx.TIMESTAMP + ": \\[Full GC \\((" + JdkRegEx.TRIGGER_SYSTEM_GC + ")\\) " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\), " - + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; /** * Regular expression preprocessed with G1 details. */ @@ -90,7 +91,7 @@ public class G1FullGCEvent extends G1Collector implements BlockingEvent, YoungCo + JdkRegEx.SIZE_G1 + "\\) Survivors: " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + " Heap: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\](, \\[(Perm|Metaspace): " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 - + "\\)\\])?" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\)\\])?" + TimesData.REGEX + "?[ ]*$"; /** * The log entry for the event. Can be used for debugging purposes. diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1MixedPauseEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1MixedPauseEvent.java index c5625956..78410e02 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1MixedPauseEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1MixedPauseEvent.java @@ -17,6 +17,8 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.CombinedData; +import org.eclipselabs.garbagecat.domain.ParallelCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; @@ -71,7 +73,8 @@ * @author James Livingston * */ -public class G1MixedPauseEvent extends G1Collector implements BlockingEvent, CombinedData, TriggerData { +public class G1MixedPauseEvent extends G1Collector + implements BlockingEvent, ParallelCollection, CombinedData, TriggerData, TimesData { /** * Trigger(s) regular expression(s). @@ -83,8 +86,8 @@ public class G1MixedPauseEvent extends G1Collector implements BlockingEvent, Com * Regular expression standard format. */ private static final String REGEX = "^" + JdkRegEx.TIMESTAMP + ": \\[GC pause \\(mixed\\) " + JdkRegEx.SIZE_G1 - + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + + "?[ ]*$"; /** * Regular expression preprocessed. @@ -94,7 +97,7 @@ public class G1MixedPauseEvent extends G1Collector implements BlockingEvent, Com + "\\]\\[Eden: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\) Survivors: " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + " Heap: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 - + "\\)\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\)\\]" + TimesData.REGEX + "?[ ]*$"; /** * The log entry for the event. Can be used for debugging purposes. @@ -131,6 +134,16 @@ public class G1MixedPauseEvent extends G1Collector implements BlockingEvent, Com */ private String trigger; + /** + * The time of all threads added together in centoseconds. + */ + private int timeUser; + + /** + * The wall (clock) time in centoseconds. + */ + private int timeReal; + /** * Create event from log entry. * @@ -150,6 +163,10 @@ public G1MixedPauseEvent(String logEntry) { combinedAvailable = JdkMath.calcKilobytes(Integer.parseInt(matcher.group(8)), matcher.group(10).charAt(0)); duration = JdkMath.convertSecsToMillis(matcher.group(11)).intValue(); + if (matcher.group(14) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(15)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(16)).intValue(); + } } } else if (logEntry.matches(REGEX_PREPROCESSED)) { // preprocessed format @@ -168,6 +185,10 @@ public G1MixedPauseEvent(String logEntry) { combinedEnd = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(44), matcher.group(46).charAt(0)); combinedAvailable = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(47), matcher.group(49).charAt(0)); + if (matcher.group(50) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(51)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(52)).intValue(); + } } } } @@ -220,6 +241,18 @@ public String getTrigger() { return trigger; } + public int getTimeUser() { + return timeUser; + } + + public int getTimeReal() { + return timeReal; + } + + public byte getParallelism() { + return JdkMath.calcParallelism(timeUser, timeReal); + } + /** * Determine if the logLine matches the logging pattern(s) for this event. * diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1RemarkEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1RemarkEvent.java index 5bd5f705..d922d734 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1RemarkEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1RemarkEvent.java @@ -16,6 +16,7 @@ import java.util.regex.Pattern; import org.eclipselabs.garbagecat.domain.BlockingEvent; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -56,7 +57,7 @@ public class G1RemarkEvent extends G1Collector implements BlockingEvent { * Regular expressions defining the logging. */ private static final String REGEX = "^(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC remark, " - + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; private static final Pattern pattern = Pattern.compile(REGEX); diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungInitialMarkEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungInitialMarkEvent.java index a2d2934a..f8273b2d 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungInitialMarkEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungInitialMarkEvent.java @@ -17,6 +17,7 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.CombinedData; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; @@ -71,8 +72,8 @@ public class G1YoungInitialMarkEvent extends G1Collector implements BlockingEven private static final String REGEX = "^(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC pause (\\((" + JdkRegEx.TRIGGER_METADATA_GC_THRESHOLD + "|" + JdkRegEx.TRIGGER_GCLOCKER_INITIATED_GC + "|" + JdkRegEx.TRIGGER_G1_HUMONGOUS_ALLOCATION + ")\\) )?\\(young\\) \\(initial-mark\\) " + JdkRegEx.SIZE_G1 - + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + + "?[ ]*$"; /** * Regular expression preprocessed. @@ -90,7 +91,7 @@ public class G1YoungInitialMarkEvent extends G1Collector implements BlockingEven + JdkRegEx.TRIGGER_TO_SPACE_EXHAUSTED + ")\\))?, " + JdkRegEx.DURATION + "\\](\\[Eden: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\) Survivors: " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + " Heap: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 - + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\]" + JdkRegEx.TIMES_BLOCK + "?)?[ ]*$"; + + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\]" + TimesData.REGEX + "?)?[ ]*$"; /** * The log entry for the event. Can be used for debugging purposes. diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungPauseEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungPauseEvent.java index 6ab871f7..b65abfab 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungPauseEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/G1YoungPauseEvent.java @@ -17,6 +17,8 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.CombinedData; +import org.eclipselabs.garbagecat.domain.ParallelCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.util.jdk.JdkMath; @@ -73,7 +75,7 @@ * */ public class G1YoungPauseEvent extends G1Collector - implements BlockingEvent, YoungCollection, CombinedData, TriggerData { + implements BlockingEvent, YoungCollection, ParallelCollection, CombinedData, TriggerData, TimesData { /** * Regular expression standard format. @@ -82,7 +84,7 @@ public class G1YoungPauseEvent extends G1Collector */ private static final String REGEX = "^" + JdkRegEx.TIMESTAMP + ": \\[GC pause (\\((" + JdkRegEx.TRIGGER_G1_EVACUATION_PAUSE + ")\\) )?\\(young\\) " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 - + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION + "\\]"; + + "\\(" + JdkRegEx.SIZE_G1 + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; /** * Regular expression preprocessed with G1 details. @@ -108,7 +110,7 @@ public class G1YoungPauseEvent extends G1Collector + ")\\))?, " + JdkRegEx.DURATION + "\\]\\[Eden: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\) Survivors: " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + " Heap: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 - + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\]" + TimesData.REGEX + "?[ ]*$"; /** * Regular expression preprocessed, no details. @@ -118,7 +120,7 @@ public class G1YoungPauseEvent extends G1Collector */ private static final String REGEX_PREPROCESSED = "^" + JdkRegEx.TIMESTAMP + ": \\[GC pause \\(young\\), " + JdkRegEx.DURATION + "\\]\\[ " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 - + "\\)\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\)\\]" + TimesData.REGEX + "?[ ]*$"; /** * Regular expression preprocessed with G1 details with no duration. Get duration from times block. @@ -133,7 +135,7 @@ public class G1YoungPauseEvent extends G1Collector + ": \\[GC pause (\\((" + JdkRegEx.TRIGGER_G1_EVACUATION_PAUSE + ")\\) )?\\(young\\)\\[Eden: " + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\) Survivors: " + JdkRegEx.SIZE_G1 + "->" + JdkRegEx.SIZE_G1 + " Heap: " + JdkRegEx.SIZE_G1 + "\\(" - + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\]" + JdkRegEx.TIMES_BLOCK + + JdkRegEx.SIZE_G1 + "\\)->" + JdkRegEx.SIZE_G1 + "\\(" + JdkRegEx.SIZE_G1 + "\\)\\]" + TimesData.REGEX + "[ ]*$"; /** @@ -171,6 +173,16 @@ public class G1YoungPauseEvent extends G1Collector */ private String trigger; + /** + * The time of all threads added together in centoseconds. + */ + private int timeUser; + + /** + * The wall (clock) time in centoseconds. + */ + private int timeReal; + /** * Create event from log entry. * @@ -189,6 +201,10 @@ public G1YoungPauseEvent(String logEntry) { combinedAvailable = JdkMath.calcKilobytes(Integer.parseInt(matcher.group(10)), matcher.group(12).charAt(0)); duration = JdkMath.convertSecsToMillis(matcher.group(13)).intValue(); + if (matcher.group(16) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(17)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(18)).intValue(); + } } } else if (logEntry.matches(REGEX_PREPROCESSED_DETAILS)) { Pattern pattern = Pattern.compile(REGEX_PREPROCESSED_DETAILS); @@ -207,6 +223,10 @@ public G1YoungPauseEvent(String logEntry) { combinedEnd = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(44), matcher.group(46).charAt(0)); combinedAvailable = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(47), matcher.group(49).charAt(0)); + if (matcher.group(50) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(51)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(52)).intValue(); + } } } else if (logEntry.matches(REGEX_PREPROCESSED)) { Pattern pattern = Pattern.compile(REGEX_PREPROCESSED); @@ -218,6 +238,10 @@ public G1YoungPauseEvent(String logEntry) { combinedEnd = JdkMath.calcKilobytes(Integer.parseInt(matcher.group(8)), matcher.group(10).charAt(0)); combinedAvailable = JdkMath.calcKilobytes(Integer.parseInt(matcher.group(11)), matcher.group(13).charAt(0)); + if (matcher.group(14) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(15)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(16)).intValue(); + } } } else if (logEntry.matches(REGEX_PREPROCESSED_NO_DURATION)) { Pattern pattern = Pattern.compile(REGEX_PREPROCESSED_NO_DURATION); @@ -229,11 +253,13 @@ public G1YoungPauseEvent(String logEntry) { trigger = matcher.group(14); } // Get duration from times block - duration = JdkMath.convertSecsToMillis(matcher.group(46)).intValue(); + duration = JdkMath.convertSecsToMillis(matcher.group(47)).intValue(); combined = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(33), matcher.group(35).charAt(0)); combinedEnd = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(39), matcher.group(41).charAt(0)); combinedAvailable = JdkMath.convertSizeG1DetailsToKilobytes(matcher.group(42), matcher.group(44).charAt(0)); + timeUser = JdkMath.convertSecsToCentos(matcher.group(46)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(47)).intValue(); } } } @@ -286,6 +312,18 @@ public String getTrigger() { return trigger; } + public int getTimeUser() { + return timeUser; + } + + public int getTimeReal() { + return timeReal; + } + + public byte getParallelism() { + return JdkMath.calcParallelism(timeUser, timeReal); + } + /** * Determine if the logLine matches the logging pattern(s) for this event. * diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewEvent.java index 928ac545..a2ba0790 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParNewEvent.java @@ -17,6 +17,8 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.OldData; +import org.eclipselabs.garbagecat.domain.ParallelCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.domain.YoungData; @@ -89,7 +91,7 @@ * */ public class ParNewEvent extends CmsIncrementalModeCollector - implements BlockingEvent, YoungCollection, YoungData, OldData, TriggerData { + implements BlockingEvent, YoungCollection, ParallelCollection, YoungData, OldData, TriggerData, TimesData { /** * Trigger(s) regular expression(s). @@ -106,7 +108,7 @@ public class ParNewEvent extends CmsIncrementalModeCollector + ": )?(" + JdkRegEx.TIMESTAMP + ": )?\\[ParNew( \\(" + JdkRegEx.TRIGGER_PROMOTION_FAILED + "\\))?: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)" + JdkRegEx.ICMS_DC_BLOCK + "?, " - + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; private static final Pattern pattern = Pattern.compile(ParNewEvent.REGEX); /** @@ -159,6 +161,16 @@ public class ParNewEvent extends CmsIncrementalModeCollector */ private String trigger; + /** + * The time of all threads added together in centoseconds. + */ + private int timeUser; + + /** + * The wall (clock) time in centoseconds. + */ + private int timeReal; + /** * Create event from log entry. * @@ -186,6 +198,10 @@ public ParNewEvent(String logEntry) { } else { super.setIncrementalMode(false); } + if (matcher.group(61) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(62)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(63)).intValue(); + } } } @@ -249,6 +265,18 @@ public String getTrigger() { return trigger; } + public int getTimeUser() { + return timeUser; + } + + public int getTimeReal() { + return timeReal; + } + + public byte getParallelism() { + return JdkMath.calcParallelism(timeUser, timeReal); + } + /** * Determine if the logLine matches the logging pattern(s) for this event. * diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelOldCompactingEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelOldCompactingEvent.java index 51836dac..da0cb057 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelOldCompactingEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelOldCompactingEvent.java @@ -18,8 +18,10 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.OldCollection; import org.eclipselabs.garbagecat.domain.OldData; +import org.eclipselabs.garbagecat.domain.ParallelCollection; import org.eclipselabs.garbagecat.domain.PermCollection; import org.eclipselabs.garbagecat.domain.PermData; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; @@ -79,8 +81,8 @@ * @author jborelo * */ -public class ParallelOldCompactingEvent extends ParallelCollector - implements BlockingEvent, OldCollection, PermCollection, YoungData, OldData, PermData, TriggerData { +public class ParallelOldCompactingEvent extends ParallelCollector implements BlockingEvent, OldCollection, + PermCollection, ParallelCollection, YoungData, OldData, PermData, TriggerData, TimesData { /** * The log entry for the event. Can be used for debugging purposes. @@ -147,6 +149,16 @@ public class ParallelOldCompactingEvent extends ParallelCollector */ private String trigger; + /** + * The time of all threads added together in centoseconds. + */ + private int timeUser; + + /** + * The wall (clock) time in centoseconds. + */ + private int timeReal; + /** * Trigger(s) regular expression(s). */ @@ -163,7 +175,7 @@ public class ParallelOldCompactingEvent extends ParallelCollector + "\\)\\] \\[ParOldGen: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)(,)? \\[(PSPermGen|Metaspace): " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\], " + JdkRegEx.DURATION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + TimesData.REGEX + "?[ ]*$"; private static Pattern pattern = Pattern.compile(ParallelOldCompactingEvent.REGEX); @@ -190,6 +202,10 @@ public ParallelOldCompactingEvent(String logEntry) { permGenEnd = Integer.parseInt(matcher.group(28)); permGenAllocation = Integer.parseInt(matcher.group(29)); duration = JdkMath.convertSecsToMillis(matcher.group(30)).intValue(); + if (matcher.group(33) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(34)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(35)).intValue(); + } } } @@ -265,6 +281,18 @@ public String getTrigger() { return trigger; } + public int getTimeUser() { + return timeUser; + } + + public int getTimeReal() { + return timeReal; + } + + public byte getParallelism() { + return JdkMath.calcParallelism(timeUser, timeReal); + } + /** * Determine if the logLine matches the logging pattern(s) for this event. * diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelScavengeEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelScavengeEvent.java index e8150565..35d220a1 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelScavengeEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelScavengeEvent.java @@ -17,6 +17,8 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.OldData; +import org.eclipselabs.garbagecat.domain.ParallelCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.domain.YoungData; @@ -73,7 +75,7 @@ * */ public class ParallelScavengeEvent extends ParallelCollector - implements BlockingEvent, YoungCollection, YoungData, OldData, TriggerData { + implements BlockingEvent, YoungCollection, ParallelCollection, YoungData, OldData, TriggerData, TimesData { /** * The log entry for the event. Can be used for debugging purposes. @@ -125,6 +127,16 @@ public class ParallelScavengeEvent extends ParallelCollector */ private String trigger; + /** + * The time of all threads added together in centoseconds. + */ + private int timeUser; + + /** + * The wall (clock) time in centoseconds. + */ + private int timeReal; + /** * Trigger(s) regular expression(s). */ @@ -139,7 +151,7 @@ public class ParallelScavengeEvent extends ParallelCollector private static final String REGEX = "^(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC(--)? (\\(" + TRIGGER + "\\) )?(--)?\\[PSYoungGen: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION - + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\]" + TimesData.REGEX + "?[ ]*$"; private static final Pattern pattern = Pattern.compile(ParallelScavengeEvent.REGEX); @@ -165,6 +177,10 @@ public ParallelScavengeEvent(String logEntry) { int totalAllocation = Integer.parseInt(matcher.group(23)); oldAllocation = totalAllocation - youngAvailable; duration = JdkMath.convertSecsToMillis(matcher.group(24)).intValue(); + if (matcher.group(27) != null) { + timeUser = JdkMath.convertSecsToCentos(matcher.group(28)).intValue(); + timeReal = JdkMath.convertSecsToCentos(matcher.group(29)).intValue(); + } } } @@ -228,6 +244,18 @@ public String getTrigger() { return trigger; } + public int getTimeUser() { + return timeUser; + } + + public int getTimeReal() { + return timeReal; + } + + public byte getParallelism() { + return JdkMath.calcParallelism(timeUser, timeReal); + } + /** * Determine if the logLine matches the logging pattern(s) for this event. * diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelSerialOldEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelSerialOldEvent.java index c3d037f7..200fb723 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelSerialOldEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/ParallelSerialOldEvent.java @@ -21,6 +21,7 @@ import org.eclipselabs.garbagecat.domain.PermCollection; import org.eclipselabs.garbagecat.domain.PermData; import org.eclipselabs.garbagecat.domain.SerialCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.domain.YoungData; @@ -146,7 +147,7 @@ public class ParallelSerialOldEvent extends ParallelCollector implements Blockin + TRIGGER + "\\) )?\\[PSYoungGen: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] \\[PSOldGen: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\) \\[PSPermGen: " + JdkRegEx.SIZE + "->" - + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\], " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\], " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; private static Pattern pattern = Pattern.compile(ParallelSerialOldEvent.REGEX); diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialNewEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialNewEvent.java index 1d16ea50..7184ba3b 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialNewEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialNewEvent.java @@ -18,6 +18,7 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.OldData; import org.eclipselabs.garbagecat.domain.SerialCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.domain.YoungData; import org.eclipselabs.garbagecat.util.jdk.JdkMath; @@ -70,7 +71,7 @@ public class SerialNewEvent extends SerialCollector private static final String REGEX = "^(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[(Full )?GC( )?(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[DefNew: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\] " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE - + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; private static final Pattern pattern = Pattern.compile(SerialNewEvent.REGEX); /** diff --git a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialOldEvent.java b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialOldEvent.java index 91814d9d..8b6db80c 100644 --- a/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialOldEvent.java +++ b/src/main/java/org/eclipselabs/garbagecat/domain/jdk/SerialOldEvent.java @@ -21,6 +21,7 @@ import org.eclipselabs.garbagecat.domain.PermCollection; import org.eclipselabs.garbagecat.domain.PermData; import org.eclipselabs.garbagecat.domain.SerialCollection; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.YoungCollection; import org.eclipselabs.garbagecat.domain.YoungData; @@ -162,7 +163,7 @@ public class SerialOldEvent extends SerialCollector implements BlockingEvent, Yo + 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 + "?[ ]*$"; + + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?[ ]*$"; private static Pattern pattern = Pattern.compile(SerialOldEvent.REGEX); diff --git a/src/main/java/org/eclipselabs/garbagecat/hsql/JvmDao.java b/src/main/java/org/eclipselabs/garbagecat/hsql/JvmDao.java index 05fa1983..284364db 100644 --- a/src/main/java/org/eclipselabs/garbagecat/hsql/JvmDao.java +++ b/src/main/java/org/eclipselabs/garbagecat/hsql/JvmDao.java @@ -23,6 +23,7 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.CombinedData; +import org.eclipselabs.garbagecat.domain.LogEvent; import org.eclipselabs.garbagecat.domain.OldData; import org.eclipselabs.garbagecat.domain.PermData; import org.eclipselabs.garbagecat.domain.YoungData; @@ -142,6 +143,16 @@ public class JvmDao { */ private long swapFree; + /** + * The ParallelCollection event with the worst "bad" parallelism (0-1). + */ + private LogEvent baddestParallelismEvent; + + /** + * The number of ParallelCollection with "bad" parallelism (0-1). + */ + private long badParallelismCount; + public JvmDao() { try { // Load database driver. @@ -337,6 +348,36 @@ public void setSwapFree(long swapFree) { this.swapFree = swapFree; } + /** + * @return The worst "bad" (0-1) parallelism event. + */ + public LogEvent getBaddestParallelismEvent() { + return baddestParallelismEvent; + } + + /** + * @param baddestParallelismEvent + * The ParallelCollection with the worst "bad" (0-1) parallelism. + */ + public void setBaddestParallelismEvent(LogEvent baddestParallelismEvent) { + this.baddestParallelismEvent = baddestParallelismEvent; + } + + /** + * @return The number of "bad" (0-1) parallelism events. + */ + public long getBadParallelismCount() { + return badParallelismCount; + } + + /** + * @param badParallelismCount + * The number of "bad" (0-1) parallelism events. + */ + public void setBadParallelismCount(long badParallelismCount) { + this.badParallelismCount = badParallelismCount; + } + /** * Add blocking events to database. */ diff --git a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationConcurrentTimePreprocessAction.java b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationConcurrentTimePreprocessAction.java index d660131d..2c94aeef 100644 --- a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationConcurrentTimePreprocessAction.java +++ b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationConcurrentTimePreprocessAction.java @@ -15,6 +15,7 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.preprocess.PreprocessAction; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -76,7 +77,7 @@ public class ApplicationConcurrentTimePreprocessAction implements PreprocessActi /** * Regular expressions defining the 2nd logging line. */ - private static final String REGEX_LINE2 = "^(: \\[CMS-concurrent-mark-start\\])?" + JdkRegEx.TIMES_BLOCK + "?[ ]*$"; + private static final String REGEX_LINE2 = "^(: \\[CMS-concurrent-mark-start\\])?" + TimesData.REGEX + "?[ ]*$"; private static final Pattern PATTERN2 = Pattern.compile(REGEX_LINE2); /** diff --git a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationStoppedTimePreprocessAction.java b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationStoppedTimePreprocessAction.java index 27a2b1d3..e0be63fb 100644 --- a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationStoppedTimePreprocessAction.java +++ b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ApplicationStoppedTimePreprocessAction.java @@ -15,6 +15,7 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.preprocess.PreprocessAction; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -77,7 +78,7 @@ public class ApplicationStoppedTimePreprocessAction implements PreprocessAction * Regular expressions defining the 2nd logging line. */ private static final String REGEX_LINE2 = "^(: \\[CMS-concurrent-abortable-preclean: " + JdkRegEx.DURATION_FRACTION - + "\\])?" + JdkRegEx.TIMES_BLOCK + "[ ]*$"; + + "\\])?" + TimesData.REGEX + "[ ]*$"; private static final Pattern PATTERN2 = Pattern.compile(REGEX_LINE2); /** 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 89fd6257..4e15a3da 100644 --- a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/CmsPreprocessAction.java +++ b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/CmsPreprocessAction.java @@ -18,6 +18,7 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.preprocess.PreprocessAction; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -192,7 +193,7 @@ public class CmsPreprocessAction implements PreprocessAction { + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\](" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[CMS)?)(( CMS: abort preclean due to time )?(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(abortable-preclean|mark|sweep|preclean|reset): " + JdkRegEx.DURATION_FRACTION - + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Regular expression for retained beginning PAR_NEW mixed with FLS_STATISTICS. @@ -230,7 +231,7 @@ public class CmsPreprocessAction implements PreprocessAction { + JdkRegEx.TRIGGER_GCLOCKER_INITIATED_GC + ")\\)[ ]{0,1})?(" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[CMS)((" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(mark|abortable-preclean|preclean|sweep): " + JdkRegEx.DURATION_FRACTION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + TimesData.REGEX + "?)[ ]*$"; /** * Regular expression for retained beginning CMS_SERIAL_OLD bailing out collection. @@ -282,7 +283,7 @@ public class CmsPreprocessAction implements PreprocessAction { * 233307.273: [CMS-concurrent-mark: 16.547/16.547 secs] */ private static final String REGEX_RETAIN_MIDDLE_CONCURRENT = "^(" + JdkRegEx.TIMESTAMP - + ": \\[CMS-concurrent-mark: " + JdkRegEx.DURATION_FRACTION + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + ": \\[CMS-concurrent-mark: " + JdkRegEx.DURATION_FRACTION + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Middle line when mixed serial and concurrent logging. @@ -295,7 +296,7 @@ public class CmsPreprocessAction implements PreprocessAction { private static final String REGEX_RETAIN_MIDDLE_SERIAL_CONCURRENT_MIXED = "^((: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\])?" + JdkRegEx.TIMESTAMP + ": \\[CMS)(" + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(abortable-preclean|preclean|mark|sweep): " - + JdkRegEx.DURATION_FRACTION + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + JdkRegEx.DURATION_FRACTION + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Middle line when mixed PAR_NEW and concurrent logging. @@ -312,7 +313,7 @@ public class CmsPreprocessAction implements PreprocessAction { + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\](" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[CMS)?)((" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[CMS-concurrent-(abortable-preclean|preclean|mark): " + JdkRegEx.DURATION_FRACTION + "\\]" - + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + TimesData.REGEX + "?)[ ]*$"; /** * Middle line PAR_NEW with FLS_STATISTICS @@ -376,8 +377,7 @@ public class CmsPreprocessAction implements PreprocessAction { */ private static final String REGEX_RETAIN_MIDDLE_CMS_REMARK = "^((" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC (\\(" + JdkRegEx.TRIGGER_CMS_FINAL_REMARK + "\\))? " + JdkRegEx.SIZE + "->" - + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK - + "?)[ ]*$"; + + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Regular expression for retained end. @@ -416,14 +416,13 @@ public class CmsPreprocessAction implements PreprocessAction { + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\])? (" + JdkRegEx.SIZE + "->)?" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)(, \\[(CMS Perm |Metaspace): " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\])?" + JdkRegEx.ICMS_DC_BLOCK + "?, " + JdkRegEx.DURATION - + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Regular expression for retained duration. This can come in the middle or at the end of a logging event split over * multiple lines. Check the TOKEN to see if in the middle of preprocessing an event that spans multiple lines. */ - private static final String REGEX_RETAIN_DURATION = "(, " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK - + "?)[ ]*"; + private static final String REGEX_RETAIN_DURATION = "(, " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?)[ ]*"; /** * Regular expression for PAR_NEW with extraneous prefix. @@ -432,8 +431,7 @@ public class CmsPreprocessAction implements PreprocessAction { + ": \\[ParNew)((" + JdkRegEx.DATESTAMP + ": )?" + JdkRegEx.TIMESTAMP + ": \\[GC \\(" + JdkRegEx.TRIGGER_ALLOCATION_FAILURE + "\\) " + JdkRegEx.TIMESTAMP + ": \\[ParNew: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\] " + JdkRegEx.SIZE + "->" - + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK - + "?)[ ]*$"; + + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\), " + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Log entry in the entangle log list used to indicate the current high level preprocessor (e.g. CMS, G1). This diff --git a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/G1PreprocessAction.java b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/G1PreprocessAction.java index d7f49367..43420191 100644 --- a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/G1PreprocessAction.java +++ b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/G1PreprocessAction.java @@ -18,6 +18,7 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.preprocess.PreprocessAction; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -440,7 +441,7 @@ public class G1PreprocessAction implements PreprocessAction { * * [Times: user=0.01 sys=0.00, real=0.01 secs] */ - private static final String REGEX_RETAIN_END = "^(" + JdkRegEx.TIMES_BLOCK + ")( )?[ ]*$"; + private static final String REGEX_RETAIN_END = "^(" + TimesData.REGEX + ")( )?[ ]*$"; /** * Regular expressions for lines thrown away. diff --git a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ParallelPreprocessAction.java b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ParallelPreprocessAction.java index ade1cfca..e81b713e 100644 --- a/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ParallelPreprocessAction.java +++ b/src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/ParallelPreprocessAction.java @@ -18,6 +18,7 @@ import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.preprocess.PreprocessAction; import org.eclipselabs.garbagecat.util.jdk.JdkRegEx; import org.eclipselabs.garbagecat.util.jdk.JdkUtil; @@ -113,7 +114,7 @@ public class ParallelPreprocessAction implements PreprocessAction { + "\\(" + JdkRegEx.SIZE + "\\)\\]( \\[PSOldGen: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\])? " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)( \\[PSPermGen: " + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\)\\])?)?, " - + JdkRegEx.DURATION + "\\]" + JdkRegEx.TIMES_BLOCK + "?)[ ]*$"; + + JdkRegEx.DURATION + "\\]" + TimesData.REGEX + "?)[ ]*$"; /** * Log entry in the entangle log list used to indicate the current high level preprocessor (e.g. CMS, G1). This diff --git a/src/main/java/org/eclipselabs/garbagecat/service/GcManager.java b/src/main/java/org/eclipselabs/garbagecat/service/GcManager.java index 411928c5..33258479 100644 --- a/src/main/java/org/eclipselabs/garbagecat/service/GcManager.java +++ b/src/main/java/org/eclipselabs/garbagecat/service/GcManager.java @@ -32,9 +32,11 @@ import org.eclipselabs.garbagecat.domain.BlockingEvent; import org.eclipselabs.garbagecat.domain.JvmRun; import org.eclipselabs.garbagecat.domain.LogEvent; +import org.eclipselabs.garbagecat.domain.ParallelCollection; import org.eclipselabs.garbagecat.domain.SerialCollection; import org.eclipselabs.garbagecat.domain.ThrowAwayEvent; import org.eclipselabs.garbagecat.domain.TimeWarpException; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.TriggerData; import org.eclipselabs.garbagecat.domain.UnknownEvent; import org.eclipselabs.garbagecat.domain.jdk.ApplicationConcurrentTimeEvent; @@ -603,6 +605,24 @@ public void store(File logFile, boolean reorder) { } } + // 16) Bad parallelism (0-1) + if (event instanceof ParallelCollection && event instanceof TimesData) { + if (((TimesData) event).getParallelism() > 0 && ((TimesData) event).getParallelism() <= 1) { + // bad parallelism + jvmDao.setBadParallelismCount(jvmDao.getBadParallelismCount() + 1); + if (jvmDao.getBaddestParallelismEvent() == null) { + jvmDao.setBaddestParallelismEvent(event); + } else { + if (((TimesData) event) + .getParallelism() < ((TimesData) jvmDao.getBaddestParallelismEvent()) + .getParallelism()) { + // Update baddest + jvmDao.setBaddestParallelismEvent(event); + } + } + } + } + priorEvent = (BlockingEvent) event; } else if (event instanceof ApplicationStoppedTimeEvent) { @@ -801,6 +821,8 @@ public JvmRun getJvmRun(Jvm jvm, int throughputThreshold) { jvmRun.setCollectorFamiles(jvmDao.getCollectorFamilies()); jvmRun.setAnalysis(jvmDao.getAnalysis()); jvmRun.setBottlenecks(getBottlenecks(jvm, throughputThreshold)); + jvmRun.setBaddestParallelismEvent(jvmDao.getBaddestParallelismEvent()); + jvmRun.setBadParallelismCount(jvmDao.getBadParallelismCount()); jvmRun.doAnalysis(); return jvmRun; } diff --git a/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkMath.java b/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkMath.java index 792ae8a3..2e8217db 100644 --- a/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkMath.java +++ b/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkMath.java @@ -96,6 +96,22 @@ public static BigDecimal convertMicrosToMillis(long micros) { return duration; } + /** + * Convert seconds to centoseconds. For example: Convert 1.02 to 102. + * + * @param secs + * Seconds as a number with 2 decimal places. + * @return Centoseconds. + */ + public static BigDecimal convertSecsToCentos(String secs) { + // BigDecimal does not accept decimal commas, only decimal periods + BigDecimal duration = new BigDecimal(secs.replace(",", ".")); + duration = duration.movePointRight(2); + // Round down to avoid TimeWarpExceptions when events are spaced close together + duration = duration.setScale(0, RoundingMode.DOWN); + return duration; + } + /** * Add together an array of durations and convert seconds to milliseconds. * @@ -197,4 +213,40 @@ public static int convertSizeG1DetailsToKilobytes(final String size, final char kilobytes = kilobytes.setScale(0, RoundingMode.HALF_EVEN); return kilobytes.intValue(); } + + /** + * Calculate the throughput between two garbage collection (GC) points. Throughput is the percent of time not spent + * doing GC. + * + * @param currentDuration + * Current collection time spent doing GC (milliseconds) beginning at currentTimestamp. + * @param currentTimestamp + * Current collection timestamp (milliseconds after JVM startup). + * @param priorDuration + * Prior collection time spent doing GC (milliseconds) beginning at priorTimestamp. 0 for the first + * collection. + * @param priorTimestamp + * Prior collection timestamp (milliseconds after JVM startup). 0 for the first collection. + * @return Throughput as a percent. 0 means all time was spent doing GC. 100 means no time was spent doing GC. + */ + + /** + * @param timeUser + * The wall (clock) time in centoseconds. + * @param timeReal + * The wall (clock) time in centoseconds. + * @return The ratio of user:real time rounded to the nearest whole number or -1 if real time - 0. + */ + public static byte calcParallelism(final int timeUser, final int timeReal) { + byte calc = -1; + if (timeReal > 0) { + BigDecimal parallelism = new BigDecimal(timeUser); + parallelism = parallelism.divide(new BigDecimal(timeReal), 0, RoundingMode.HALF_EVEN); + calc = parallelism.byteValue(); + if (parallelism.intValue() > 128) { + throw new RuntimeException("Parallelism out of range (0-128): " + parallelism.intValue()); + } + } + return calc; + } } diff --git a/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkRegEx.java b/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkRegEx.java index 1615168c..e3b716eb 100644 --- a/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkRegEx.java +++ b/src/main/java/org/eclipselabs/garbagecat/util/jdk/JdkRegEx.java @@ -113,15 +113,6 @@ public class JdkRegEx { */ public static final String DURATION_FRACTION = "(\\d{1,4}[\\.\\,]\\d{3}\\/\\d{1,4}[\\.\\,]\\d{3}) secs"; - /** - * Times data. I'm not really sure what JVM option(s) cause this to be output, but I see it added to the end of GC - * events. - * - * For example: [Times: user=0.31 sys=0.00, real=0.04 secs] - */ - public static final String TIMES_BLOCK = "( \\[Times: user=\\d{1,4}[\\.\\,]\\d{2} sys=\\d{1,4}[\\.\\,]\\d{2}, " - + "real=(\\d{1,4}[\\.\\,]\\d{2}) secs\\])"; - /** * Data when the CMS collector is run in incremental mode with the -XX:+CMSIncrementalMode JVM option. * In this mode, the CMS collector does not hold the processor(s) for the entire long concurrent phases but diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/TestJvmRun.java b/src/test/java/org/eclipselabs/garbagecat/domain/TestJvmRun.java index 97c90314..9c2d5676 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/TestJvmRun.java +++ b/src/test/java/org/eclipselabs/garbagecat/domain/TestJvmRun.java @@ -469,6 +469,7 @@ public void testApplicationStoppedTimeNoTimestamps() { Assert.assertEquals("JVM run duration not correct.", 31703, jvmRun.getJvmRunDuration()); Assert.assertEquals("GC throughput not correct.", 93, jvmRun.getGcThroughput()); Assert.assertEquals("Stopped time throughput not correct.", 94, jvmRun.getStoppedTimeThroughput()); + Assert.assertEquals("Bad parallelism event count not correct.", 1, jvmRun.getBadParallelismCount()); } /** @@ -534,6 +535,7 @@ public void testStopedTime() { Assert.assertEquals("Stopped time throughput not correct.", 4, jvmRun.getStoppedTimeThroughput()); Assert.assertFalse(Analysis.WARN_GC_STOPPED_RATIO + " analysis incorrectly identified.", jvmRun.getAnalysis().contains(Analysis.WARN_GC_STOPPED_RATIO)); + Assert.assertEquals("Bad parallelism event count not correct.", 12, jvmRun.getBadParallelismCount()); } /** diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1MixedPauseEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1MixedPauseEvent.java index 3f16a5b7..a16b4edf 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1MixedPauseEvent.java +++ b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1MixedPauseEvent.java @@ -61,6 +61,9 @@ public void testLogLineWithTimesData() { Assert.assertEquals("Combined end size not parsed correctly.", 525312, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 741376, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 168, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 22, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 22, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 1, event.getParallelism()); } public void testLogLineSpacesAtEnd() { @@ -91,6 +94,9 @@ public void testLogLinePreprocessedTriggerBeforeG1EvacuationPause() { Assert.assertEquals("Combined available size not parsed correctly.", 30 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 45, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 19, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 5, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testLogLinePreprocessedNoTrigger() { @@ -106,6 +112,9 @@ public void testLogLinePreprocessedNoTrigger() { Assert.assertEquals("Combined available size not parsed correctly.", 26 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 76, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 30, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 8, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testLogLinePreprocessedNoTriggerWholeSizes() { @@ -120,6 +129,9 @@ public void testLogLinePreprocessedNoTriggerWholeSizes() { Assert.assertEquals("Combined end size not parsed correctly.", 435 * 1024, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 12288 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 61, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 43, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 6, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 7, event.getParallelism()); } public void testLogLinePreprocessedWithDatestamp() { @@ -135,6 +147,9 @@ public void testLogLinePreprocessedWithDatestamp() { Assert.assertEquals("Combined available size not parsed correctly.", 26 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 76, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 30, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 8, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testNoTriggerToSpaceExhausted() { @@ -152,6 +167,9 @@ public void testNoTriggerToSpaceExhausted() { Assert.assertEquals("Combined available size not parsed correctly.", 18 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 1502, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 1135, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 150, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 8, event.getParallelism()); } public void testDoubleTriggerToSpaceExhausted() { @@ -169,6 +187,9 @@ public void testDoubleTriggerToSpaceExhausted() { Assert.assertEquals("Combined available size not parsed correctly.", 28 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 8642, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 3439, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 864, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testTriggerGcLockerInitiatedGc() { @@ -185,6 +206,9 @@ public void testTriggerGcLockerInitiatedGc() { Assert.assertEquals("Combined end size not parsed correctly.", 1090048, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 1500 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 21, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 7, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } /** diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1YoungPauseEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1YoungPauseEvent.java index 03e13435..b8c18162 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1YoungPauseEvent.java +++ b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestG1YoungPauseEvent.java @@ -43,7 +43,8 @@ public void testNotInitialMark() { } public void testLogLineKilobytes() { - String logLine = "0.308: [GC pause (young) 8192K->2028K(59M), 0.0078140 secs]"; + String logLine = "0.308: [GC pause (young) 8192K->2028K(59M), 0.0078140 secs] " + + "[Times: user=0.01 sys=0.00, real=0.02 secs]"; Assert.assertTrue("Log line not recognized as " + JdkUtil.LogEventType.G1_YOUNG_PAUSE.toString() + ".", G1YoungPauseEvent.match(logLine)); G1YoungPauseEvent event = new G1YoungPauseEvent(logLine); @@ -52,6 +53,9 @@ public void testLogLineKilobytes() { Assert.assertEquals("Combined end size not parsed correctly.", 2028, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 60416, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 7, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 1, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 0, event.getParallelism()); } public void testLogLinePreprocessedG1Details() { @@ -81,6 +85,9 @@ public void testLogLinePreprocessedG1Sizes() { Assert.assertEquals("Combined end size not parsed correctly.", 2589, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 59 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 2, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 1, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 1, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 1, event.getParallelism()); } public void testLogLinePreprocessedG1DetailsTriggerGcLockerInitiatedGc() { @@ -98,6 +105,9 @@ public void testLogLinePreprocessedG1DetailsTriggerGcLockerInitiatedGc() { Assert.assertEquals("Combined available size not parsed correctly.", 30 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 17, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 1, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 0, event.getParallelism()); } public void testLogLinePreprocessedG1DetailsTriggerAfterYoungToSpaceExhausted() { @@ -115,6 +125,9 @@ public void testLogLinePreprocessedG1DetailsTriggerAfterYoungToSpaceExhausted() Assert.assertEquals("Combined available size not parsed correctly.", 26 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 120, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 41, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 12, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testLogLinePreprocessedNoTrigger() { @@ -132,6 +145,9 @@ public void testLogLinePreprocessedNoTrigger() { Assert.assertEquals("Combined available size not parsed correctly.", 26 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 275, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 109, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 27, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testLogLinePreprocessedNoSizeDetails() { @@ -163,6 +179,9 @@ public void testLogLinePreprocessedDoubleTrigger() { Assert.assertEquals("Combined available size not parsed correctly.", 28 * 1024 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 3171, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 1773, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 318, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 6, event.getParallelism()); } public void testLogLinePreprocessedDatestamp() { @@ -179,6 +198,9 @@ public void testLogLinePreprocessedDatestamp() { Assert.assertEquals("Combined end size not parsed correctly.", 8750, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 1500 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 12, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 3, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testLogLinePreprocessedNoDuration() { @@ -195,5 +217,8 @@ public void testLogLinePreprocessedNoDuration() { Assert.assertEquals("Combined end size not parsed correctly.", 3555635, event.getCombinedOccupancyEnd()); Assert.assertEquals("Combined available size not parsed correctly.", 8192 * 1024, event.getCombinedSpace()); Assert.assertEquals("Duration not parsed correctly.", 110, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 22, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 11, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } } diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewEvent.java index b1aec1de..57db987f 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewEvent.java +++ b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParNewEvent.java @@ -73,6 +73,9 @@ public void testLogLineWithTimesData() { Assert.assertEquals("Old allocation size not parsed correctly.", 8218240, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 46, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 34, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 5, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 7, event.getParallelism()); } public void testLogLineWithIcmsDcData() { @@ -91,6 +94,9 @@ public void testLogLineWithIcmsDcData() { Assert.assertEquals("Old allocation size not parsed correctly.", (1828480 - 59008), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 22, event.getDuration()); Assert.assertTrue("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 5, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testLogLineWhitespaceAtEnd() { @@ -132,6 +138,9 @@ public void testLogLineJdk8WithTrigger() { Assert.assertEquals("Old allocation size not parsed correctly.", (1986432 - 996800), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 19, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 9, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testLogLineJdk8NoSpaceAfterTrigger() { @@ -151,6 +160,9 @@ public void testLogLineJdk8NoSpaceAfterTrigger() { Assert.assertEquals("Old allocation size not parsed correctly.", (494976 - 153600), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 30, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 10, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 3, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testLogLineGcLockerTrigger() { @@ -171,6 +183,9 @@ public void testLogLineGcLockerTrigger() { Assert.assertEquals("Old allocation size not parsed correctly.", (8235008 - 1382400), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 39, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 23, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 4, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 6, event.getParallelism()); } public void testLogLineCmsScavengeBeforeRemark() { @@ -189,6 +204,9 @@ public void testLogLineCmsScavengeBeforeRemark() { Assert.assertEquals("Old allocation size not parsed correctly.", (13172736 - 4128768), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 524, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 92, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 51, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testLogLineSystemGcTrigger() { @@ -207,6 +225,9 @@ public void testLogLineSystemGcTrigger() { Assert.assertEquals("Old allocation size not parsed correctly.", (8277888 - 996800), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 13, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 14, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 2, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 7, event.getParallelism()); } public void testLogLinePromotionFailed() { @@ -225,6 +246,9 @@ public void testLogLinePromotionFailed() { Assert.assertEquals("Old allocation size not parsed correctly.", (13172736 - 4128768), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 519, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 92, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 55, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testLogLineWithDatestamp() { @@ -243,6 +267,9 @@ public void testLogLineWithDatestamp() { Assert.assertEquals("Old allocation size not parsed correctly.", (980352 - 341376), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 3, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 0, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 0, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", -1, event.getParallelism()); } public void testLogLineWithDatestampNoTimestamp() { @@ -269,6 +296,9 @@ public void testLogLineWithDoubleDatestamp() { Assert.assertEquals("Old allocation size not parsed correctly.", (1014528 - 306688), event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 38, event.getDuration()); Assert.assertFalse("Incremental Mode not parsed correctly.", event.isIncrementalMode()); + Assert.assertEquals("User time not parsed correctly.", 11, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 4, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } /** diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelOldCompactingEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelOldCompactingEvent.java index 3b798547..f01e43db 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelOldCompactingEvent.java +++ b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelOldCompactingEvent.java @@ -94,6 +94,9 @@ public void testLogLineJdk8() { Assert.assertEquals("Perm gen end size not parsed correctly.", 19114, event.getPermOccupancyEnd()); Assert.assertEquals("Perm gen allocation size not parsed correctly.", 1067008, event.getPermSpace()); Assert.assertEquals("Duration not parsed correctly.", 35, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 9, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 4, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testLogLineLastDitchCollectionTrigger() { @@ -117,6 +120,9 @@ public void testLogLineLastDitchCollectionTrigger() { Assert.assertEquals("Perm gen end size not parsed correctly.", 4177368, event.getPermOccupancyEnd()); Assert.assertEquals("Perm gen allocation size not parsed correctly.", 4194304, event.getPermSpace()); Assert.assertEquals("Duration not parsed correctly.", 1970, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 441, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 197, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testIsBlocking() { @@ -148,6 +154,9 @@ public void testLogLineErgonomicsTrigger() { Assert.assertEquals("Perm gen end size not parsed correctly.", 135256, event.getPermOccupancyEnd()); Assert.assertEquals("Perm gen allocation size not parsed correctly.", 1177600, event.getPermSpace()); Assert.assertEquals("Duration not parsed correctly.", 3452, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 1158, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 345, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testHeapInspectionInitiatedGcTrigger() { @@ -172,6 +181,9 @@ public void testHeapInspectionInitiatedGcTrigger() { Assert.assertEquals("Metaspace end size not parsed correctly.", 3959881, event.getPermOccupancyEnd()); Assert.assertEquals("Metaspace allocation size not parsed correctly.", 3977216, event.getPermSpace()); Assert.assertEquals("Duration not parsed correctly.", 2430, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 695, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 243, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testAllocationFailureTrigger() { @@ -195,6 +207,9 @@ public void testAllocationFailureTrigger() { Assert.assertEquals("Metaspace end size not parsed correctly.", 170731, event.getPermOccupancyEnd()); Assert.assertEquals("Metaspace allocation size not parsed correctly.", 1220608, event.getPermSpace()); Assert.assertEquals("Duration not parsed correctly.", 3573, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 2624, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 357, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 7, event.getParallelism()); } public void testHeapDumpInitiatedGcTrigger() { @@ -218,5 +233,8 @@ public void testHeapDumpInitiatedGcTrigger() { Assert.assertEquals("Metaspace end size not parsed correctly.", 141753, event.getPermOccupancyEnd()); Assert.assertEquals("Metaspace allocation size not parsed correctly.", 1185792, event.getPermSpace()); Assert.assertEquals("Duration not parsed correctly.", 2372, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 755, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 237, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } -} +} \ No newline at end of file diff --git a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelScavengeEvent.java b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelScavengeEvent.java index ad8b5666..80815b76 100644 --- a/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelScavengeEvent.java +++ b/src/test/java/org/eclipselabs/garbagecat/domain/jdk/TestParallelScavengeEvent.java @@ -84,6 +84,9 @@ public void testSizeWithNineTensPlacesLogLine() { Assert.assertEquals("Old end size not parsed correctly.", 80396669 - 20643840, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 129092672 - 67413056, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 3899, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 6640, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 389, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 17, event.getParallelism()); } public void testJDK8LogLineWithMetatdataGcThreshholdTrigger() { @@ -102,6 +105,9 @@ public void testJDK8LogLineWithMetatdataGcThreshholdTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 17795 - 17779, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 6029312 - 1835008, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 14, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 4, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 1, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 4, event.getParallelism()); } public void testJDK8LogLineWithGcLockerInitiateGcTrigger() { @@ -120,6 +126,9 @@ public void testJDK8LogLineWithGcLockerInitiateGcTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 138909 - 114285, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 4019712 - 1223168, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 71, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 24, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 8, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testJDK8LogLineWithAllocationFailureTrigger() { @@ -138,6 +147,9 @@ public void testJDK8LogLineWithAllocationFailureTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 201204 - 131690, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 4019712 - 1223168, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 65, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 13, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 7, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testLastDitchCollectionTrigger() { @@ -156,6 +168,9 @@ public void testLastDitchCollectionTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 773083 - 0, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 6287872 - 1569280, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 221, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 76, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 22, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testHeapInspectionInitiatedGcTrigger() { @@ -175,6 +190,9 @@ public void testHeapInspectionInitiatedGcTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 2982516 - 47669, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 6233088 - 1514496, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 263, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 86, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 27, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testSystemGcTrigger() { @@ -193,6 +211,9 @@ public void testSystemGcTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 2372732 - 22188, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 6191104 - 1472512, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 166, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 58, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 17, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 3, event.getParallelism()); } public void testHeapDumpInitiatedGcTrigger() { @@ -212,6 +233,9 @@ public void testHeapDumpInitiatedGcTrigger() { Assert.assertEquals("Old end size not parsed correctly.", 918194 - 33192, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 1287680 - 397312, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 24, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 7, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 3, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 2, event.getParallelism()); } public void testDoubleDash() { @@ -231,5 +255,8 @@ public void testDoubleDash() { Assert.assertEquals("Old end size not parsed correctly.", 1275901 - 385537, event.getOldOccupancyEnd()); Assert.assertEquals("Old allocation size not parsed correctly.", 1288192 - 397824, event.getOldSpace()); Assert.assertEquals("Duration not parsed correctly.", 167, event.getDuration()); + Assert.assertEquals("User time not parsed correctly.", 24, event.getTimeUser()); + Assert.assertEquals("Real time not parsed correctly.", 17, event.getTimeReal()); + Assert.assertEquals("Parallelism not calculated correctly.", 1, event.getParallelism()); } } diff --git a/src/test/java/org/eclipselabs/garbagecat/preprocess/jdk/TestG1PreprocessAction.java b/src/test/java/org/eclipselabs/garbagecat/preprocess/jdk/TestG1PreprocessAction.java index 74fc6585..9015ffb2 100644 --- a/src/test/java/org/eclipselabs/garbagecat/preprocess/jdk/TestG1PreprocessAction.java +++ b/src/test/java/org/eclipselabs/garbagecat/preprocess/jdk/TestG1PreprocessAction.java @@ -904,6 +904,7 @@ public void testG1PreprocessActionG1YoungPauseLogging() { Assert.assertEquals("Event type count not correct.", 1, jvmRun.getEventTypes().size()); Assert.assertTrue("Log line not recognized as " + JdkUtil.LogEventType.G1_YOUNG_PAUSE.toString() + ".", jvmRun.getEventTypes().contains(JdkUtil.LogEventType.G1_YOUNG_PAUSE)); + Assert.assertEquals("Bad parallelism event count not correct.", 1, jvmRun.getBadParallelismCount()); } /** diff --git a/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestAnalysis.java b/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestAnalysis.java index bd2d60e0..082cd328 100644 --- a/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestAnalysis.java +++ b/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestAnalysis.java @@ -894,6 +894,7 @@ public void testParallelOldCompactingExplicitGc() { jvmRun.getAnalysis().contains(Analysis.WARN_EXPLICIT_GC_PARALLEL)); Assert.assertFalse(Analysis.ERROR_SERIAL_GC_PARALLEL + " analysis incorrectly identified.", jvmRun.getAnalysis().contains(Analysis.ERROR_SERIAL_GC_PARALLEL)); + Assert.assertEquals("Bad parallelism event count not correct.", 2, jvmRun.getBadParallelismCount()); } public void testThreadStackSizeAnalysis32Bit() { diff --git a/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkMath.java b/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkMath.java index 17ddbeff..55baf39c 100644 --- a/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkMath.java +++ b/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkMath.java @@ -129,4 +129,45 @@ public void testConvertSizeG1DetailsToKilobytesG() { Assert.assertEquals("G1 details not converted to kilobytes.", 104857600, JdkMath.convertSizeG1DetailsToKilobytes(size, units)); } + + public void testCalcParallelism() { + int timeUser = 100; + int timeReal = 10; + Assert.assertEquals("Parallism not calculated correctly.", 10, JdkMath.calcParallelism(timeUser, timeReal)); + } + + public void testCalcParallelismLessRoundedDownToZero() { + int timeUser = 100; + int timeReal = 1000; + Assert.assertEquals("Parallism not calculated correctly.", 0, JdkMath.calcParallelism(timeUser, timeReal)); + } + + public void testCalcParallelismLessRoundedUpToOne() { + int timeUser = 100; + int timeReal = 199; + Assert.assertEquals("Parallism not calculated correctly.", 1, JdkMath.calcParallelism(timeUser, timeReal)); + } + + public void testCalcParallelismOutOfRange() { + int timeUser = 129; + int timeReal = 1; + try { + JdkMath.calcParallelism(timeUser, timeReal); + Assert.fail("Parallelism > 128 should result in RuntimeException."); + } catch (Exception e) { + Assert.assertTrue("Did not fail with 'Parallelism out of range (0-128)'.", e instanceof RuntimeException); + } + } + + public void testCalcParallelismUserZero() { + int timeUser = 0; + int timeReal = 100; + Assert.assertEquals("Parallism not calculated correctly.", 0, JdkMath.calcParallelism(timeUser, timeReal)); + } + + public void testCalcParallelismRealZero() { + int timeUser = 100; + int timeReal = 0; + Assert.assertEquals("Parallism not calculated correctly.", -1, JdkMath.calcParallelism(timeUser, timeReal)); + } } diff --git a/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkRegEx.java b/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkRegEx.java index 958febc4..37104c8a 100644 --- a/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkRegEx.java +++ b/src/test/java/org/eclipselabs/garbagecat/util/jdk/TestJdkRegEx.java @@ -12,6 +12,7 @@ *********************************************************************************************************************/ package org.eclipselabs.garbagecat.util.jdk; +import org.eclipselabs.garbagecat.domain.TimesData; import org.eclipselabs.garbagecat.domain.jdk.ParallelScavengeEvent; import junit.framework.Assert; @@ -176,8 +177,7 @@ public void testDatestampGmtPlus() { public void testTimesBlock4Digits() { String timesBlock = " [Times: user=2889.80 sys=2.42, real=2891.01 secs]"; - Assert.assertTrue("'" + timesBlock + "' " + "is a valid times block.", - timesBlock.matches(JdkRegEx.TIMES_BLOCK)); + Assert.assertTrue("'" + timesBlock + "' " + "is a valid times block.", timesBlock.matches(TimesData.REGEX)); } public void testSizeG1WholeBytes() {