Skip to content

Commit

Permalink
Add ExitOnOutOfMemoryError analysis.
Browse files Browse the repository at this point in the history
  • Loading branch information
@mgm3746
mgm3746 committed Jul 11, 2024
1 parent 576e57e commit 24b6114
Show file tree
Hide file tree
Showing 13 changed files with 211 additions and 56 deletions.
23 changes: 23 additions & 0 deletions src/main/java/org/eclipselabs/garbagecat/domain/JvmRun.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
import static org.eclipselabs.garbagecat.util.jdk.Analysis.ERROR_EXPLICIT_GC_SERIAL_CMS;
import static org.eclipselabs.garbagecat.util.jdk.Analysis.ERROR_EXPLICIT_GC_SERIAL_G1;
import static org.eclipselabs.garbagecat.util.jdk.Analysis.ERROR_G1_HUMONGOUS_JDK_OLD;
import static org.eclipselabs.garbagecat.util.jdk.Analysis.ERROR_OOME_EXIT;
import static org.eclipselabs.garbagecat.util.jdk.Analysis.ERROR_PHYSICAL_MEMORY;
import static org.eclipselabs.garbagecat.util.jdk.Analysis.ERROR_UNIDENTIFIED_LOG_LINES_PREPARSE;
import static org.eclipselabs.garbagecat.util.jdk.Analysis.INFO_FIRST_TIMESTAMP_THRESHOLD_EXCEEDED;
Expand Down Expand Up @@ -59,16 +60,20 @@
import org.eclipselabs.garbagecat.domain.jdk.unified.SafepointEventSummary;
import org.eclipselabs.garbagecat.domain.jdk.unified.UnifiedSafepointEvent;
import org.eclipselabs.garbagecat.preprocess.PreprocessAction.PreprocessEvent;
import org.eclipselabs.garbagecat.preprocess.jdk.unified.UnifiedPreprocessAction;
import org.eclipselabs.garbagecat.util.Constants;
import org.eclipselabs.garbagecat.util.GcUtil;
import org.eclipselabs.garbagecat.util.Memory;
import org.eclipselabs.garbagecat.util.jdk.Analysis;
import org.eclipselabs.garbagecat.util.jdk.GcTrigger;
import org.eclipselabs.garbagecat.util.jdk.JdkMath;
import org.eclipselabs.garbagecat.util.jdk.JdkRegEx;
import org.eclipselabs.garbagecat.util.jdk.JdkUtil;
import org.eclipselabs.garbagecat.util.jdk.JdkUtil.LogEventType;
import org.eclipselabs.garbagecat.util.jdk.unified.UnifiedRegEx;
import org.eclipselabs.garbagecat.util.jdk.unified.UnifiedSafepoint;
import org.eclipselabs.garbagecat.util.jdk.unified.UnifiedUtil;
import org.eclipselabs.garbagecat.util.jdk.unified.UnifiedSafepoint.Trigger;
import org.github.joa.JvmOptions;
import org.github.joa.domain.GarbageCollector;
import org.github.joa.domain.JvmContext;
Expand Down Expand Up @@ -405,6 +410,24 @@ public void doAnalysis() {
if (jvmOptions != null) {
jvmOptions.doAnalysis();
}

// Check for OOME with -XX:+ExitOnOutOfMemoryError
if (!getUnidentifiedLogLines().isEmpty()) {
String lastUnidentifiedLogLine = getUnidentifiedLogLines().get(getUnidentifiedLogLines().size() - 1);
Matcher matcher = UnifiedPreprocessAction.REGEX_RETAIN_BEGINNING_SAFEPOINT_PATTERN
.matcher(lastUnidentifiedLogLine);
if (matcher.find()) {
Trigger trigger = UnifiedSafepoint.getTrigger(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 2));
if (trigger == Trigger.REPORT_JAVA_OUT_OF_MEMORY) {
analysis.add(0, ERROR_OOME_EXIT);
getUnidentifiedLogLines().remove(getUnidentifiedLogLines().size() - 1);
if (getUnidentifiedLogLines().isEmpty()) {
getEventTypes().remove(JdkUtil.LogEventType.UNKNOWN);
}
}
}
}

// Unidentified logging lines
if (!getUnidentifiedLogLines().isEmpty()) {
if (!preprocessed) {
Expand Down
72 changes: 45 additions & 27 deletions ...n/java/org/eclipselabs/garbagecat/domain/jdk/unified/UnifiedG1YoungPrepareMixedEvent.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,7 @@
import org.eclipselabs.garbagecat.domain.jdk.G1Collector;
import org.eclipselabs.garbagecat.domain.jdk.G1ExtRootScanningData;
import org.eclipselabs.garbagecat.preprocess.jdk.unified.UnifiedPreprocessAction;
import org.eclipselabs.garbagecat.util.Constants;
import org.eclipselabs.garbagecat.util.Memory;
import org.eclipselabs.garbagecat.util.jdk.GcTrigger;
import org.eclipselabs.garbagecat.util.jdk.JdkMath;
Expand Down Expand Up @@ -65,6 +66,14 @@
* [16.627s][info][gc,start ] GC(1354) Pause Young (Prepare Mixed) (G1 Evacuation Pause) Other: 0.1ms Humongous regions: 0->0 Metaspace: 3801K->3801K(1056768K) 24M->13M(31M) 0.361ms User=0.00s Sys=0.00s Real=0.00s
* </pre>
*
* <p>
* 3) Preprocessed with "To-space" exhausted.
* </p>
*
* <pre>
* [14.232s][info][gc,start] GC(17368) Pause Young (Prepare Mixed) (G1 Humongous Allocation) To-space exhausted Other: 1.3ms Humongous regions: 312-&gt;70 Metaspace: 401628K-&gt;401628K(1421312K) 11481M-&gt;8717M(12000M) 1125.930ms User=6.31s Sys=0.13s Real=1.13s
* </pre>
*
* @author <a href="mailto:mmillson@redhat.com">Mike Millson</a>
*
*/
Expand All @@ -83,10 +92,10 @@ public class UnifiedG1YoungPrepareMixedEvent extends G1Collector
* Regular expression defining logging.
*/
private static final String _REGEX = "^" + UnifiedRegEx.DECORATOR + " Pause Young \\(Prepare Mixed\\) \\("
+ __TRIGGER + "\\) " + UnifiedPreprocessAction.REGEX_G1_EXT_ROOT_SCANNING + "?(" + OtherTime.REGEX
+ " )?(Humongous regions: \\d{1,}->\\d{1,} )?(Metaspace: " + JdkRegEx.SIZE + "(\\(" + JdkRegEx.SIZE
+ "\\))?->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\) )?" + JdkRegEx.SIZE + "->" + JdkRegEx.SIZE
+ "\\(" + JdkRegEx.SIZE + "\\) " + JdkRegEx.DURATION_MS + TimesData.REGEX_JDK9 + "?[ ]*$";
+ __TRIGGER + "\\) " + UnifiedPreprocessAction.REGEX_G1_EXT_ROOT_SCANNING + "?(To\\-space exhausted )?("
+ OtherTime.REGEX + " )?(Humongous regions: \\d{1,}->\\d{1,} )?(Metaspace: " + JdkRegEx.SIZE + "(\\("
+ JdkRegEx.SIZE + "\\))?->" + JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\) )?" + JdkRegEx.SIZE + "->"
+ JdkRegEx.SIZE + "\\(" + JdkRegEx.SIZE + "\\) " + JdkRegEx.DURATION_MS + TimesData.REGEX_JDK9 + "?[ ]*$";

private static final Pattern PATTERN = Pattern.compile(_REGEX);

Expand Down Expand Up @@ -130,6 +139,7 @@ public static final boolean match(String logLine) {
* Combined young + old generation allocation.
*/
private Memory combinedSpace;

/**
* The elapsed clock time for the GC event in microseconds (rounded).
*/
Expand All @@ -146,7 +156,6 @@ public static final boolean match(String logLine) {
* Time spent outside of garbage collection in microseconds (rounded).
*/
private long otherTime;

/**
* The wall (clock) time in centiseconds.
*/
Expand Down Expand Up @@ -182,43 +191,43 @@ public UnifiedG1YoungPrepareMixedEvent(String logEntry) {
this.logEntry = logEntry;
Matcher matcher = PATTERN.matcher(logEntry);
if (matcher.find()) {
eventTime = JdkMath.convertMillisToMicros(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 30)).intValue();
eventTime = JdkMath.convertMillisToMicros(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 31)).intValue();
long time = UnifiedUtil.calculateTime(matcher);
if (!isEndstamp()) {
timestamp = time;
} else {
timestamp = time - JdkMath.convertMicrosToMillis(eventTime).longValue();
}
trigger = GcTrigger.getTrigger(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 1));
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 4) != null) {
extRootScanningTime = JdkMath.convertMillisToMicros(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 5))
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 2) != null) {
extRootScanningTime = JdkMath.convertMillisToMicros(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 3))
.intValue();
} else {
extRootScanningTime = G1ExtRootScanningData.NO_DATA;
}
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 5) != null) {
otherTime = JdkMath.convertMillisToMicros(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 5)).intValue();
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 6) != null) {
otherTime = JdkMath.convertMillisToMicros(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 6)).intValue();
} else {
otherTime = OtherTime.NO_DATA;
}
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 7) != null) {
classOccupancyInit = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 8),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 10).charAt(0)).convertTo(KILOBYTES);
classOccupancyEnd = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 15),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 17).charAt(0)).convertTo(KILOBYTES);
classSpace = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 18),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 20).charAt(0)).convertTo(KILOBYTES);
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 8) != null) {
classOccupancyInit = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 9),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 11).charAt(0)).convertTo(KILOBYTES);
classOccupancyEnd = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 16),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 18).charAt(0)).convertTo(KILOBYTES);
classSpace = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 19),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 21).charAt(0)).convertTo(KILOBYTES);
}
combinedOccupancyInit = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 21),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 23).charAt(0)).convertTo(KILOBYTES);
combinedOccupancyEnd = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 24),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 26).charAt(0)).convertTo(KILOBYTES);
combinedSpace = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 27),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 29).charAt(0)).convertTo(KILOBYTES);
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 31) != null) {
timeUser = JdkMath.convertSecsToCentis(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 32)).intValue();
timeSys = JdkMath.convertSecsToCentis(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 33)).intValue();
timeReal = JdkMath.convertSecsToCentis(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 34)).intValue();
combinedOccupancyInit = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 22),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 24).charAt(0)).convertTo(KILOBYTES);
combinedOccupancyEnd = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 25),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 27).charAt(0)).convertTo(KILOBYTES);
combinedSpace = memory(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 28),
matcher.group(UnifiedRegEx.DECORATOR_SIZE + 30).charAt(0)).convertTo(KILOBYTES);
if (matcher.group(UnifiedRegEx.DECORATOR_SIZE + 32) != null) {
timeUser = JdkMath.convertSecsToCentis(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 33)).intValue();
timeSys = JdkMath.convertSecsToCentis(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 34)).intValue();
timeReal = JdkMath.convertSecsToCentis(matcher.group(UnifiedRegEx.DECORATOR_SIZE + 35)).intValue();
} else {
timeUser = TimesData.NO_DATA;
timeReal = TimesData.NO_DATA;
Expand Down Expand Up @@ -323,6 +332,15 @@ public boolean isEndstamp() {
return isEndStamp;
}

/**
* @return True if "To-space" is exhausted, false otherwise.
*/
public boolean isToSpaceExhausted() {
boolean isTooSpaceExhausted = false;
isTooSpaceExhausted = logEntry.matches("^.+ " + Constants.G1_TO_SPACE_EXHAUSTED + ".*");
return isTooSpaceExhausted;
}

protected void setClassSpace(Memory classSpace) {
this.classOccupancyInit = classSpace;
}
Expand Down
24 changes: 3 additions & 21 deletions src/main/java/org/eclipselabs/garbagecat/preprocess/jdk/unified/UnifiedPreprocessAction.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -363,7 +363,7 @@ public class UnifiedPreprocessAction implements PreprocessAction {
private static final String REGEX_RETAIN_BEGINNING_SAFEPOINT = "^(" + UnifiedRegEx.DECORATOR
+ " Entering safepoint region: " + UnifiedSafepoint.triggerRegEx() + ")$";

private static final Pattern REGEX_RETAIN_BEGINNING_SAFEPOINT_PATTERN = Pattern
public static final Pattern REGEX_RETAIN_BEGINNING_SAFEPOINT_PATTERN = Pattern
.compile(REGEX_RETAIN_BEGINNING_SAFEPOINT);

/**
Expand Down Expand Up @@ -1421,14 +1421,7 @@ public UnifiedPreprocessAction(String priorLogEntry, String logEntry, String nex
} else if ((matcher = REGEX_RETAIN_BEGINNING_SAFEPOINT_PATTERN.matcher(logEntry)).matches()) {
matcher.reset();
if (matcher.matches()) {
if (nextLogEntry == null || REGEX_RETAIN_MIDDLE_SAFEPOINT_PATTERN.matcher(nextLogEntry).matches()) {
// Non GC safepoint
this.logEntry = matcher.group(1);
context.add(PreprocessAction.NEWLINE);
} else {
// GC safepoint, output after GC event
entangledLogLines.add(matcher.group(1));
}
entangledLogLines.add(matcher.group(1));
}
context.add(TOKEN_BEGINNING_OF_UNIFIED_SAFEPOINT);
context.add(TOKEN);
Expand Down Expand Up @@ -1566,18 +1559,7 @@ public UnifiedPreprocessAction(String priorLogEntry, String logEntry, String nex
} else if ((matcher = REGEX_RETAIN_MIDDLE_SAFEPOINT_PATTERN.matcher(logEntry)).matches()) {
matcher.reset();
if (matcher.matches()) {
boolean haveBeginningSafepointLogging = false;
for (String logLine : entangledLogLines) {
if (logLine.matches(REGEX_RETAIN_BEGINNING_SAFEPOINT)) {
haveBeginningSafepointLogging = true;
}
}
if (haveBeginningSafepointLogging) {
entangledLogLines.add(matcher.group(1));
} else {
this.logEntry = matcher.group(1);
context.remove(PreprocessAction.NEWLINE);
}
entangledLogLines.add(matcher.group(1));
}
} else if ((matcher = REGEX_RETAIN_MIDDLE_SHENANDOAH_DATA_PATTERN.matcher(logEntry)).matches()) {
matcher.reset();
Expand Down
7 changes: 5 additions & 2 deletions src/main/java/org/eclipselabs/garbagecat/service/GcManager.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,6 +63,7 @@
import org.eclipselabs.garbagecat.domain.jdk.ShenandoahFullGcEvent;
import org.eclipselabs.garbagecat.domain.jdk.unified.UnifiedConcurrentEvent;
import org.eclipselabs.garbagecat.domain.jdk.unified.UnifiedG1YoungPauseEvent;
import org.eclipselabs.garbagecat.domain.jdk.unified.UnifiedG1YoungPrepareMixedEvent;
import org.eclipselabs.garbagecat.domain.jdk.unified.UnifiedHeaderEvent;
import org.eclipselabs.garbagecat.domain.jdk.unified.UnifiedSafepointEvent;
import org.eclipselabs.garbagecat.domain.jdk.unified.VmWarningEvent;
Expand Down Expand Up @@ -912,8 +913,10 @@ public void store(List<String> logLines, boolean reorder) {
if (event instanceof TriggerData) {
GcTrigger trigger = ((TriggerData) event).getTrigger();
if ((trigger == GcTrigger.TO_SPACE_EXHAUSTED || trigger == GcTrigger.TO_SPACE_OVERFLOW)
|| (event instanceof UnifiedG1YoungPauseEvent
&& ((UnifiedG1YoungPauseEvent) event).isToSpaceExhausted())) {
|| ((event instanceof UnifiedG1YoungPauseEvent
&& ((UnifiedG1YoungPauseEvent) event).isToSpaceExhausted())
|| (event instanceof UnifiedG1YoungPrepareMixedEvent
&& ((UnifiedG1YoungPrepareMixedEvent) event).isToSpaceExhausted()))) {
if (!jvmDao.getAnalysis().contains(Analysis.ERROR_G1_EVACUATION_FAILURE)) {
jvmDao.addAnalysis(Analysis.ERROR_G1_EVACUATION_FAILURE);
}
Expand Down
7 changes: 7 additions & 0 deletions src/main/java/org/eclipselabs/garbagecat/util/jdk/Analysis.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -82,6 +82,13 @@ public enum Analysis {
*/
ERROR_METASPACE_ALLOCATION_FAILURE("error.metaspace.allocation.failure"),

/**
* Property key for the JVM exiting due to
* {@link org.eclipselabs.garbagecat.util.jdk.unified.UnifiedSafepoint.Trigger#REPORT_JAVA_OUT_OF_MEMORY} (e.g.
* -XX:+ExitOnOutOfMemoryError).
*/
ERROR_OOME_EXIT("error.oome.exit"),

/**
* Property key for Metaspace::report_metadata_oome at the end of gc.log.
*/
Expand Down
24 changes: 19 additions & 5 deletions src/main/java/org/eclipselabs/garbagecat/util/jdk/unified/UnifiedSafepoint.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -42,15 +42,15 @@ public enum Trigger {
//
NO_VM_OPERATION, PARALLEL_GC_FAILED_ALLOCATION, PARALLEL_GC_SYSTEM_GC, PRINT_JNI, PRINT_THREADS,
//
REDEFINE_CLASSES, REVOKE_BIAS, SET_NOTIFY_JVMTI_EVENTS_MODE, SHENANDOAH_DEGENERATED_GC,
REDEFINE_CLASSES, REPORT_JAVA_OUT_OF_MEMORY, REVOKE_BIAS, SET_NOTIFY_JVMTI_EVENTS_MODE,
//
SHENANDOAH_FINAL_MARK_START_EVAC, SHENANDOAH_FINAL_UPDATE_REFS, SHENANDOAH_INIT_MARK,
SHENANDOAH_DEGENERATED_GC, SHENANDOAH_FINAL_MARK_START_EVAC, SHENANDOAH_FINAL_UPDATE_REFS,
//
SHENANDOAH_INIT_UPDATE_REFS, THREAD_DUMP, UNKNOWN, X_MARK_END, X_MARK_START, X_RELOCATE_START, Z_MARK_END,
SHENANDOAH_INIT_MARK, SHENANDOAH_INIT_UPDATE_REFS, THREAD_DUMP, UNKNOWN, X_MARK_END, X_MARK_START,
//
Z_MARK_END_OLD, Z_MARK_END_YOUNG, Z_MARK_START, Z_MARK_START_YOUNG, Z_MARK_START_YOUNG_AND_OLD,
X_RELOCATE_START, Z_MARK_END, Z_MARK_END_OLD, Z_MARK_END_YOUNG, Z_MARK_START, Z_MARK_START_YOUNG,
//
Z_RELOCATE_START, Z_RELOCATE_START_OLD, Z_RELOCATE_START_YOUNG
Z_MARK_START_YOUNG_AND_OLD, Z_RELOCATE_START, Z_RELOCATE_START_OLD, Z_RELOCATE_START_YOUNG
};

/**
Expand Down Expand Up @@ -357,6 +357,13 @@ public enum Trigger {
*/
public static final String REDEFINE_CLASSES = "RedefineClasses";

/**
* <p>
* OutOfMemoryError.
* </p>
*/
public static final String REPORT_JAVA_OUT_OF_MEMORY = "ReportJavaOutOfMemory";

/**
* <p>
* Biased locking is an optimization to reduce the overhead of uncontested locking. It assumes a thread owns a
Expand Down Expand Up @@ -598,6 +605,8 @@ public static final Trigger getTrigger(String triggerLiteral) {
return Trigger.PRINT_THREADS;
if (REDEFINE_CLASSES.matches(triggerLiteral))
return Trigger.REDEFINE_CLASSES;
if (REPORT_JAVA_OUT_OF_MEMORY.matches(triggerLiteral))
return Trigger.REPORT_JAVA_OUT_OF_MEMORY;
if (REVOKE_BIAS.matches(triggerLiteral))
return Trigger.REVOKE_BIAS;
if (SET_NOTIFY_JVMTI_EVENTS_MODE.matches(triggerLiteral))
Expand Down Expand Up @@ -768,6 +777,9 @@ public static final String getTriggerLiteral(Trigger trigger) {
case REDEFINE_CLASSES:
triggerLiteral = REDEFINE_CLASSES;
break;
case REPORT_JAVA_OUT_OF_MEMORY:
triggerLiteral = REPORT_JAVA_OUT_OF_MEMORY;
break;
case REVOKE_BIAS:
triggerLiteral = REVOKE_BIAS;
break;
Expand Down Expand Up @@ -919,6 +931,8 @@ public static final Trigger identifyTrigger(String trigger) {
return Trigger.PRINT_THREADS;
if (Trigger.REDEFINE_CLASSES.name().matches(trigger))
return Trigger.REDEFINE_CLASSES;
if (Trigger.REPORT_JAVA_OUT_OF_MEMORY.name().matches(trigger))
return Trigger.REPORT_JAVA_OUT_OF_MEMORY;
if (Trigger.REVOKE_BIAS.name().matches(trigger))
return Trigger.REVOKE_BIAS;
if (Trigger.SET_NOTIFY_JVMTI_EVENTS_MODE.name().matches(trigger))
Expand Down

0 comments on commit 24b6114

Please sign in to comment.