Skip to content

Commit

Permalink
Issue #73. Initial parallelism reporting/analysis.
Browse files Browse the repository at this point in the history
  • Loading branch information
Mike Millson committed Apr 19, 2017
1 parent 70b9539 commit ad20999
Show file tree
Hide file tree
Showing 40 changed files with 619 additions and 64 deletions.
12 changes: 12 additions & 0 deletions src/main/java/org/eclipselabs/garbagecat/Main.java
Original file line number Diff line number Diff line change
Expand Up @@ -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> analysis = jvmRun.getAnalysis();
if (!analysis.isEmpty()) {
Expand Down
26 changes: 26 additions & 0 deletions src/main/java/org/eclipselabs/garbagecat/domain/JvmRun.java
Original file line number Diff line number Diff line change
Expand Up @@ -160,6 +160,16 @@ public class JvmRun {
*/
private String lastLogLineUnprocessed;

/**
* The <code>ParallelCollection</code> event with the worst "bad" parallelism (0-1).
*/
private LogEvent baddestParallelismEvent;

/**
* The number of <code>ParallelCollection</code> with "bad" parallelism (0-1).
*/
private long badParallelismCount;

/**
* Constructor accepting throughput threshold, JVM services, and JVM environment information.
*
Expand Down Expand Up @@ -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
Expand Down
Original file line number Diff line number Diff line change
@@ -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 <a href="mailto:mmillson@redhat.com">Mike Millson</a>
*
*/
public interface ParallelCollection {

}
50 changes: 50 additions & 0 deletions src/main/java/org/eclipselabs/garbagecat/domain/TimesData.java
Original file line number Diff line number Diff line change
@@ -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.
*
* <h3>Example Logging</h3>
*
* <p>
* [Times: user=0.31 sys=0.00, real=0.04 secs]
* </p>
*
* @author <a href="mailto:mmillson@redhat.com">Mike Millson</a>
*
*/
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();
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);

/**
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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
Expand All @@ -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 <code>-XX:+CMSClassUnloadingEnabled</code> .
Expand All @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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".
Expand All @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
/**
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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.
*/
Expand All @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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).
Expand All @@ -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.
Expand All @@ -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.
Expand Down Expand Up @@ -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.
*
Expand All @@ -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
Expand All @@ -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();
}
}
}
}
Expand Down Expand Up @@ -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.
*
Expand Down
Loading

0 comments on commit ad20999

Please sign in to comment.