diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index 1b8073b0..a7f0c249 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -46,6 +46,7 @@
* For more information about Shenandoah see: Shenandoah Wiki at OpenJDK
*/
public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
+ // TODO also parse "Allocation Stall (main)" events
// matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
// Input: [0.693s][info][gc ] GC(0) Pause Init Mark 1.070ms
@@ -58,7 +59,7 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
// Regex: ^(?:\[(?[0-9-T:.+]*)])?(?:\[(?[^s]*)s])?\[(?[^]]+)]\[(?:(?[^] ]+)[ ]*)][ ]GC\((?[0-9]+)\)[ ](?([-.a-zA-Z ()]+|[a-zA-Z1 ()]+))(?:(?:[ ](?[0-9]{1}.*))|$)
// note for the part: easiest would have been to use [^0-9]+, but the G1 events don't fit there, because of the number in their name
private static final Pattern PATTERN_DECORATORS = Pattern.compile(
- "^(?:\\[(?[0-9-T:.+]*)])?(?:\\[(?[^s]*)s])?\\[(?[^]]+)]\\[(?:(?[^] ]+)[ ]*)][ ]GC\\((?[0-9]+)\\)[ ](?[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?[0-9]{1}.*))|$)"
+ "^(?:\\[(?[0-9-T:.+]*)])?(?:\\[(?[^s]*)s])?\\[(?[^]]+)]\\[(?:(?[^] ]+)[ ]*)][ ]GC\\((?[0-9]+)\\)[ ](?(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?[0-9]{1}.*))|$)"
);
private static final String GROUP_DECORATORS_TIME = "time";
private static final String GROUP_DECORATORS_UPTIME = "uptime";
@@ -75,7 +76,7 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
private static final String PATTERN_MEMORY_STRING = "(([0-9]+)([BKMG])->([0-9]+)([BKMG])\\(([0-9]+)([BKMG])\\))";
private static final String PATTERN_HEAP_MEMORY_PERCENTAGE_STRING = "(([0-9]+)([BKMG])[ ](\\([0-9]+%\\)))";
- private static final String PATTERN_MEMORY_PERCENTAGE_STRING = "(([0-9]+)([BKMG])\\([0-9]+%\\)->([0-9]+)([BKMG])\\([0-9]+%\\))";
+ private static final String PATTERN_MEMORY_PERCENTAGE_STRING = "(([0-9]+)([BKMG])\\(([0-9]+)%\\)->([0-9]+)([BKMG])\\(([0-9]+)%\\))";
// Input: 1.070ms
// Group 1: 1.070
@@ -134,8 +135,10 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
private static final int GROUP_MEMORY_PERCENTAGE = 1;
private static final int GROUP_MEMORY_PERCENTAGE_BEFORE = 2;
private static final int GROUP_MEMORY_PERCENTAGE_BEFORE_UNIT = 3;
- private static final int GROUP_MEMORY_PERCENTAGE_AFTER = 4;
- private static final int GROUP_MEMORY_PERCENTAGE_AFTER_UNIT = 5;
+ private static final int GROUP_MEMORY_PERCENTAGE_BEFORE_PERCENTAGE = 4;
+ private static final int GROUP_MEMORY_PERCENTAGE_AFTER = 5;
+ private static final int GROUP_MEMORY_PERCENTAGE_AFTER_UNIT = 6;
+ private static final int GROUP_MEMORY_PERCENTAGE_AFTER_PERCENTAGE = 7;
// Input: 300M (1%)
// Group 1: 300M (1%)
@@ -251,7 +254,16 @@ private AbstractGCEvent handleTagGcPhasesTail(ParseContext context, AbstractG
AbstractGCEvent parentEvent = context.getPartialEventsMap().get(event.getNumber() + "");
if (parentEvent instanceof GCEventUJL) {
returnEvent = parseTail(context, returnEvent, tail);
- parentEvent.addPhase(returnEvent);
+ // ZGC logs concurrent events as phases of one gc event -> don't add them to the phases list
+ // to comply with the current GCViewer implementation, which expects concurrent events in a separate list.
+ // If later insights suggest keeping the concurrent events as part of one gc event, GCModel#add and
+ // maybe some renderers need to be adjusted
+ if (returnEvent.isConcurrent()) {
+ return returnEvent;
+ } else {
+ parentEvent.addPhase(returnEvent);
+ return null;
+ }
}
return null;
@@ -478,6 +490,10 @@ private void setMemoryWithPercentage(AbstractGCEvent event, Matcher matcher)
Integer.parseInt(matcher.group(GROUP_MEMORY_PERCENTAGE_BEFORE)), matcher.group(GROUP_MEMORY_PERCENTAGE_BEFORE_UNIT).charAt(0), matcher.group(GROUP_MEMORY_PERCENTAGE)));
event.setPostUsed(getDataReaderTools().getMemoryInKiloByte(
Integer.parseInt(matcher.group(GROUP_MEMORY_PERCENTAGE_AFTER)), matcher.group(GROUP_MEMORY_PERCENTAGE_AFTER_UNIT).charAt(0), matcher.group(GROUP_MEMORY_PERCENTAGE)));
+
+ if (event.getTotal() == 0 && Integer.parseInt(matcher.group(GROUP_MEMORY_PERCENTAGE_BEFORE_PERCENTAGE)) != 0) {
+ event.setTotal(event.getPostUsed() / Integer.parseInt(matcher.group(GROUP_MEMORY_PERCENTAGE_AFTER_PERCENTAGE)) * 100);
+ }
}
private void setDateStampIfPresent(AbstractGCEvent event, String dateStampAsString) {
diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
index 91002a51..e6d02364 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
@@ -634,6 +634,19 @@ public String toString() {
public static final Type UJL_PAUSE_YOUNG = new Type("Pause Young", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_PAUSE_FULL = new Type("Pause Full", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
+ // unified jvm logging serial / cms event phase types
+ public static final Type UJL_SERIAL_PHASE_MARK_LIFE_OBJECTS = new Type("Phase 1: Mark live objects", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_SERIAL_PHASE_COMPUTE_NEW_OBJECT_ADDRESSES = new Type("Phase 2: Compute new object addresses", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_SERIAL_PHASE_ADJUST_POINTERS = new Type("Phase 3: Adjust pointers", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_SERIAL_PHASE_MOVE_OBJECTS = new Type("Phase 4: Move objects", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+
+ // unified jvm logging parallel event phase types
+ public static final Type UJL_PARALLEL_PHASE_MARKING = new Type("Marking Phase", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_PARALLEL_PHASE_SUMMARY = new Type("Summary Phase", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_PARALLEL_PHASE_ADJUST_ROOTS = new Type("Adjust Roots", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_PARALLEL_PHASE_COMPACTION = new Type("Compaction Phase", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_PARALLEL_PHASE_POST_COMPACT = new Type("Post Compact", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+
// unified jvm logging cms / g1 event types
public static final Type UJL_PAUSE_INITIAL_MARK = new Type("Pause Initial Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE, CollectionType.CONCURRENCY_HELPER);
public static final Type UJL_PAUSE_REMARK = new Type("Pause Remark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE, CollectionType.CONCURRENCY_HELPER);
@@ -656,6 +669,11 @@ public String toString() {
public static final Type UJL_G1_OLD = new Type("Old regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
public static final Type UJL_G1_HUMongous = new Type("Humongous regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
+ public static final Type UJL_G1_PHASE_PRE_EVACUATE_COLLECTION_SET = new Type("Pre Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_G1_PHASE_EVACUATE_COLLECTION_SET = new Type("Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_G1_PHASE_POST_EVACUATE_COLLECTION_SET = new Type("Post Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+ public static final Type UJL_G1_PHASE_OTHER = new Type("Other", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
+
// unified jvm logging shenandoah event types
public static final Type UJL_SHEN_INIT_MARK = new Type("Pause Init Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
public static final Type UJL_SHEN_FINAL_MARK = new Type("Pause Final Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java b/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java
index 11598a28..45e9bbc1 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java
@@ -141,8 +141,7 @@ public static GCModel getGCModelFromLogFile(String fileName, FOLDER folderName,
assertThat("reader from factory", reader.getClass().getName(), is(expectedDataReaderClass.getName()));
GCModel model = reader.read();
- // TODO: add support for "[gc,phases" in all gc algorithms
- // assertThat("number of errors", handler.getCount(), is(0));
+ assertThat("number of errors", handler.getCount(), is(0));
return model;
}
}
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java
index 95fa2266..31138213 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java
@@ -1,9 +1,13 @@
package com.tagtraum.perf.gcviewer.imp;
+import static org.hamcrest.Matchers.closeTo;
import static org.hamcrest.Matchers.is;
import static org.junit.Assert.assertThat;
+import java.io.ByteArrayInputStream;
import java.io.IOException;
+import java.io.InputStream;
+import java.util.logging.Level;
import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
@@ -11,6 +15,8 @@
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
import com.tagtraum.perf.gcviewer.model.GCModel;
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.GcResourceFile;
import org.junit.Test;
/**
@@ -138,4 +144,37 @@ public void parseGcAllSafepointOsCpu() throws Exception {
assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true));
}
+ @Test
+ public void testParseFullGcWithPhases() throws Exception {
+ TestLogHandler handler = new TestLogHandler();
+ handler.setLevel(Level.WARNING);
+ GCResource gcResource = new GcResourceFile("byteArray");
+ gcResource.getLogger().addHandler(handler);
+ InputStream in = new ByteArrayInputStream(
+ ("[0.315s][info][gc,start ] GC(5) Pause Full (Allocation Failure)\n" +
+ "[0.315s][info][gc ] GC(3) Concurrent Sweep 0.817ms\n" +
+ "[0.315s][info][gc,cpu ] GC(3) User=0.00s Sys=0.00s Real=0.00s\n" +
+ "[0.315s][info][gc,phases,start] GC(5) Phase 1: Mark live objects\n" +
+ "[0.316s][info][gc,phases ] GC(5) Phase 1: Mark live objects 1.154ms\n" +
+ "[0.316s][info][gc,phases,start] GC(5) Phase 2: Compute new object addresses\n" +
+ "[0.317s][info][gc,phases ] GC(5) Phase 2: Compute new object addresses 0.391ms\n" +
+ "[0.317s][info][gc,phases,start] GC(5) Phase 3: Adjust pointers\n" +
+ "[0.317s][info][gc,phases ] GC(5) Phase 3: Adjust pointers 0.575ms\n" +
+ "[0.317s][info][gc,phases,start] GC(5) Phase 4: Move objects\n" +
+ "[0.324s][info][gc,phases ] GC(5) Phase 4: Move objects 6.493ms\n" +
+ "[0.324s][info][gc ] GC(5) Pause Full (Allocation Failure) 119M->33M(150M) 9.509ms\n"
+ ).getBytes());
+
+ DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+ GCModel model = reader.read();
+
+ assertThat("number of warnings", handler.getCount(), is(0));
+ assertThat("number of events", model.size(), is(2));
+ assertThat("event type", model.get(1).getExtendedType().getType(), is(Type.UJL_PAUSE_FULL));
+ assertThat("event pause", model.get(1).getPause(), closeTo(0.009509, 0.0000001));
+
+ assertThat("phases", model.getGcEventPhases().size(), is(4));
+ assertThat("phase 1", model.getGcEventPhases().get(Type.UJL_SERIAL_PHASE_MARK_LIFE_OBJECTS.getName()).getSum(), closeTo(0.001154, 0.0000001));
+ }
+
}
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java
index deee20b6..e9b0d084 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java
@@ -1,11 +1,15 @@
package com.tagtraum.perf.gcviewer.imp;
+import static org.hamcrest.Matchers.closeTo;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.is;
import static org.junit.Assert.assertThat;
+import java.io.ByteArrayInputStream;
import java.io.IOException;
+import java.io.InputStream;
import java.util.Iterator;
+import java.util.logging.Level;
import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
@@ -14,6 +18,8 @@
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
import com.tagtraum.perf.gcviewer.model.GCEventUJL;
import com.tagtraum.perf.gcviewer.model.GCModel;
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.GcResourceFile;
import org.junit.Test;
/**
@@ -189,6 +195,40 @@ public void parseGcAllSafepointOsCpuWithToSpaceExhausted() throws Exception {
testHeapSizing(gcEventUJL.getPerm(), "metaspace", 3648, 3648, 1056768);
}
+ @Test
+ public void testParseGcWithPhases() throws Exception {
+ TestLogHandler handler = new TestLogHandler();
+ handler.setLevel(Level.WARNING);
+ GCResource gcResource = new GcResourceFile("byteArray");
+ gcResource.getLogger().addHandler(handler);
+ InputStream in = new ByteArrayInputStream(
+ ("[0.200s][info][gc,start ] GC(0) Pause Young (G1 Evacuation Pause)\n" +
+ "[0.200s][info][gc,task ] GC(0) Using 4 workers of 4 for evacuation\n" +
+ "[0.207s][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.0ms\n" +
+ "[0.207s][info][gc,phases ] GC(0) Evacuate Collection Set: 6.4ms\n" +
+ "[0.207s][info][gc,phases ] GC(0) Post Evacuate Collection Set: 0.3ms\n" +
+ "[0.207s][info][gc,phases ] GC(0) Other: 0.3ms\n" +
+ "[0.207s][info][gc,heap ] GC(0) Eden regions: 14->0(8)\n" +
+ "[0.207s][info][gc,heap ] GC(0) Survivor regions: 0->2(2)\n" +
+ "[0.207s][info][gc,heap ] GC(0) Old regions: 0->11\n" +
+ "[0.207s][info][gc,heap ] GC(0) Humongous regions: 0->0\n" +
+ "[0.207s][info][gc,metaspace ] GC(0) Metaspace: 3644K->3644K(1056768K)\n" +
+ "[0.207s][info][gc ] GC(0) Pause Young (G1 Evacuation Pause) 14M->12M(128M) 7.033ms\n"
+ ).getBytes());
+
+ DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+ GCModel model = reader.read();
+
+ assertThat("number of warnings", handler.getCount(), is(0));
+ assertThat("number of events", model.size(), is(1));
+ assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_PAUSE_YOUNG));
+ assertThat("event pause", model.get(0).getPause(), closeTo(0.007033, 0.0000001));
+
+ assertThat("phases", model.getGcEventPhases().size(), is(4));
+ assertThat("phase 1", model.getGcEventPhases().get(Type.UJL_G1_PHASE_PRE_EVACUATE_COLLECTION_SET.getName() + ":").getSum(), closeTo(0.0, 0.00001));
+ assertThat("phase 2", model.getGcEventPhases().get(Type.UJL_G1_PHASE_EVACUATE_COLLECTION_SET.getName() + ":").getSum(), closeTo(0.0064, 0.00001));
+ }
+
private void testHeapSizing(AbstractGCEvent event, String testName, int expectedBefore, int expectedAfter, int expectedTotal) {
assertThat(testName + " before", event.getPreUsed(), is(expectedBefore));
assertThat(testName + " after", event.getPostUsed(), is(expectedAfter));
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java
index 6068fefc..1100b678 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java
@@ -1,9 +1,13 @@
package com.tagtraum.perf.gcviewer.imp;
+import static org.hamcrest.Matchers.closeTo;
import static org.hamcrest.Matchers.is;
import static org.junit.Assert.assertThat;
+import java.io.ByteArrayInputStream;
import java.io.IOException;
+import java.io.InputStream;
+import java.util.logging.Level;
import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
@@ -11,6 +15,8 @@
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
import com.tagtraum.perf.gcviewer.model.GCModel;
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.GcResourceFile;
import org.junit.Test;
/**
@@ -58,6 +64,8 @@ public void parseGcAllSafepointOsCpu() throws Exception {
assertThat("amount of gc events", model.getGCPause().getN(), is(4));
assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1));
assertThat("amount of full gc events", model.getFullGCPause().getN(), is(4));
+ assertThat("amount of phase types", model.getGcEventPhases().size(), is(5));
+ assertThat("amount of events for phase 1 types", model.getGcEventPhases().get(Type.UJL_PARALLEL_PHASE_MARKING.getName()).getN(), is(4));
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
AbstractGCEvent event1 = model.get(0);
@@ -90,4 +98,42 @@ public void parseGcAllSafepointOsCpu() throws Exception {
false);
}
+ @Test
+ public void testParseFullGcWithPhases() throws Exception {
+ TestLogHandler handler = new TestLogHandler();
+ handler.setLevel(Level.WARNING);
+ GCResource gcResource = new GcResourceFile("byteArray");
+ gcResource.getLogger().addHandler(handler);
+ InputStream in = new ByteArrayInputStream(
+ ("[1.499s][info][gc,start ] GC(4) Pause Full (Ergonomics)\n" +
+ "[1.499s][info][gc,phases,start] GC(4) Marking Phase\n" +
+ "[1.504s][info][gc,phases ] GC(4) Marking Phase 4.370ms\n" +
+ "[1.504s][info][gc,phases,start] GC(4) Summary Phase\n" +
+ "[1.504s][info][gc,phases ] GC(4) Summary Phase 0.039ms\n" +
+ "[1.504s][info][gc,phases,start] GC(4) Adjust Roots\n" +
+ "[1.507s][info][gc,phases ] GC(4) Adjust Roots 2.971ms\n" +
+ "[1.507s][info][gc,phases,start] GC(4) Compaction Phase\n" +
+ "[1.520s][info][gc,phases ] GC(4) Compaction Phase 13.004ms\n" +
+ "[1.520s][info][gc,phases,start] GC(4) Post Compact\n" +
+ "[1.522s][info][gc,phases ] GC(4) Post Compact 2.222ms\n" +
+ "[1.522s][info][gc,heap ] GC(4) PSYoungGen: 5105K->0K(38400K)\n" +
+ "[1.522s][info][gc,heap ] GC(4) ParOldGen: 79662K->45521K(87552K)\n" +
+ "[1.522s][info][gc,metaspace ] GC(4) Metaspace: 15031K->15031K(1062912K)\n" +
+ "[1.522s][info][gc ] GC(4) Pause Full (Ergonomics) 82M->44M(123M) 23.271ms\n" +
+ "[1.523s][info][gc,cpu ] GC(4) User=0.05s Sys=0.00s Real=0.02s\n"
+ ).getBytes());
+
+ DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+ GCModel model = reader.read();
+
+ assertThat("number of warnings", handler.getCount(), is(0));
+ assertThat("number of events", model.size(), is(1));
+ assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_PAUSE_FULL));
+ assertThat("event pause", model.get(0).getPause(), closeTo(0.023271, 0.0000001));
+
+ assertThat("phases", model.getGcEventPhases().size(), is(5));
+ assertThat("phase 1", model.getGcEventPhases().get(Type.UJL_PARALLEL_PHASE_MARKING.getName()).getSum(), closeTo(0.00437, 0.0000001));
+ }
+
+
}
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java
index 9698cd89..709d1737 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java
@@ -127,4 +127,35 @@ public void testParseUnknownGcType() throws Exception {
assertThat("warning message", handler.getLogRecords().get(0).getMessage(), startsWith("Failed to parse gc event ("));
}
+ @Test
+ public void testParseFullGcWithPhases() throws Exception {
+ TestLogHandler handler = new TestLogHandler();
+ handler.setLevel(Level.WARNING);
+ GCResource gcResource = new GcResourceFile("byteArray");
+ gcResource.getLogger().addHandler(handler);
+ InputStream in = new ByteArrayInputStream(
+ ("[1.145s][info][gc,start ] GC(4) Pause Full (Allocation Failure)"
+ + "\n[1.145s][info][gc,phases,start] GC(4) Phase 1: Mark live objects"
+ + "\n[1.149s][info][gc,phases ] GC(4) Phase 1: Mark live objects 3.978ms"
+ + "\n[1.149s][info][gc,phases,start] GC(4) Phase 2: Compute new object addresses"
+ + "\n[1.151s][info][gc,phases ] GC(4) Phase 2: Compute new object addresses 1.245ms"
+ + "\n[1.151s][info][gc,phases,start] GC(4) Phase 3: Adjust pointers"
+ + "\n[1.153s][info][gc,phases ] GC(4) Phase 3: Adjust pointers 2.388ms"
+ + "\n[1.153s][info][gc,phases,start] GC(4) Phase 4: Move objects"
+ + "\n[1.156s][info][gc,phases ] GC(4) Phase 4: Move objects 3.136ms"
+ + "\n[1.157s][info][gc ] GC(4) Pause Full (Allocation Failure) 81M->17M(92M) 11.537ms"
+ ).getBytes());
+
+ DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+ GCModel model = reader.read();
+
+ assertThat("number of warnings", handler.getCount(), is(0));
+ assertThat("number of events", model.size(), is(1));
+ assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_PAUSE_FULL));
+ assertThat("event pause", model.get(0).getPause(), closeTo(0.011537, 0.0000001));
+
+ assertThat("phases", model.getGcEventPhases().size(), is(4));
+ assertThat("phase 1", model.getGcEventPhases().get(Type.UJL_SERIAL_PHASE_MARK_LIFE_OBJECTS.getName()).getSum(), closeTo(0.003978, 0.0000001));
+ }
+
}
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java
index 242d1c1e..84b1a17e 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java
@@ -6,8 +6,11 @@
import static org.hamcrest.Matchers.startsWith;
import static org.junit.Assert.assertThat;
+import java.io.ByteArrayInputStream;
import java.io.IOException;
+import java.io.InputStream;
import java.time.ZonedDateTime;
+import java.util.logging.Level;
import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
@@ -16,6 +19,8 @@
import com.tagtraum.perf.gcviewer.model.ConcurrentGCEvent;
import com.tagtraum.perf.gcviewer.model.GCEvent;
import com.tagtraum.perf.gcviewer.model.GCModel;
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.GcResourceFile;
import com.tagtraum.perf.gcviewer.util.DateHelper;
import org.junit.Test;
@@ -181,4 +186,38 @@ public void parseDateTimeStamps() throws Exception {
assertThat("generation", event2.getGeneration(), is(AbstractGCEvent.Generation.TENURED));
}
+ @Test
+ public void testParseFullGcWithPhases() throws Exception {
+ TestLogHandler handler = new TestLogHandler();
+ handler.setLevel(Level.WARNING);
+ GCResource gcResource = new GcResourceFile("byteArray");
+ gcResource.getLogger().addHandler(handler);
+ InputStream in = new ByteArrayInputStream(
+ ("[1,331s][info][gc,start ] GC(0) Pause Full (System.gc())\n" +
+ "[1,332s][info][gc,phases,start ] GC(0) Phase 1: Mark live objects\n" +
+ "[1,334s][info][gc,stringtable ] GC(0) Cleaned string and symbol table, strings: 1755 processed, 19 removed, symbols: 23807 processed, 0 removed\n" +
+ "[1,334s][info][gc,phases ] GC(0) Phase 1: Mark live objects 2,911ms\n" +
+ "[1,334s][info][gc,phases,start ] GC(0) Phase 2: Compute new object addresses\n" +
+ "[1,335s][info][gc,phases ] GC(0) Phase 2: Compute new object addresses 0,501ms\n" +
+ "[1,335s][info][gc,phases,start ] GC(0) Phase 3: Adjust pointers\n" +
+ "[1,336s][info][gc,phases ] GC(0) Phase 3: Adjust pointers 1,430ms\n" +
+ "[1,336s][info][gc,phases,start ] GC(0) Phase 4: Move objects\n" +
+ "[1,337s][info][gc,phases ] GC(0) Phase 4: Move objects 0,619ms\n" +
+ "[1,337s][info][gc ] GC(0) Pause Full (System.gc()) 10M->1M(128M) 5,636ms\n"
+ ).getBytes());
+
+ DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+ GCModel model = reader.read();
+
+ assertThat("number of warnings", handler.getCount(), is(0));
+ assertThat("number of events", model.size(), is(1));
+ assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_PAUSE_FULL));
+ assertThat("event pause", model.get(0).getPause(), closeTo(0.005636, 0.0000001));
+
+ assertThat("phases", model.getGcEventPhases().size(), is(4));
+ assertThat("phase 1",
+ model.getGcEventPhases().get(Type.UJL_SERIAL_PHASE_MARK_LIFE_OBJECTS.getName()).getSum(),
+ closeTo(0.002911, 0.0000001));
+ }
+
}
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java
index e2432447..25bbb79c 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java
@@ -16,6 +16,15 @@
* Test unified java logging ZGC algorithm in OpenJDK 11
*/
public class TestDataReaderUJLZGC {
+ private static final int CONCURRENT_MARK_INDEX = 0;
+ private static final int CONCURRENT_PROCESS_REFERENCES_INDEX = 1;
+ private static final int CONCURRENT_RESET_RELOCATION_SET_INDEX = 2;
+ private static final int CONCURRENT_DESTROY_DETACHED_PAGES_INDEX = 3;
+ private static final int CONCURRENT_SELECT_RELOCATION_SET_INDEX = 4;
+ private static final int CONCURRENT_PREPARE_RELOCATION_SET_INDEX = 5;
+ private static final int CONCURRENT_RELOCATE_INDEX = 6;
+
+
private GCModel gcAllModel;
private GCModel gcDefaultModel;
@@ -37,18 +46,18 @@ public void tearDown() {
@Test
public void testGcAll() {
- assertThat("size", gcAllModel.size(), is(1));
+ assertThat("size", gcAllModel.size(), is(8));
assertThat("amount of gc event types", gcAllModel.getGcEventPauses().size(), is(1));
assertThat("amount of gc events", gcAllModel.getGCPause().getN(), is(1));
assertThat("amount of full gc event types", gcAllModel.getFullGcEventPauses().size(), is(0));
- assertThat("amount of gc phases event types", gcAllModel.getGcEventPhases().size(), is(10));
+ assertThat("amount of gc phases event types", gcAllModel.getGcEventPhases().size(), is(3));
assertThat("amount of full gc events", gcAllModel.getFullGCPause().getN(), is(0));
- assertThat("amount of concurrent pause types", gcAllModel.getConcurrentEventPauses().size(), is(0));
+ assertThat("amount of concurrent pause types", gcAllModel.getConcurrentEventPauses().size(), is(7));
}
@Test
public void testGcAllGarbageCollection() {
- AbstractGCEvent garbageCollectionEvent = gcAllModel.get(0);
+ AbstractGCEvent garbageCollectionEvent = gcAllModel.get(gcAllModel.size()-1);
UnittestHelper.testMemoryPauseEvent(garbageCollectionEvent,
"Garbage Collection",
AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION,
@@ -60,7 +69,7 @@ public void testGcAllGarbageCollection() {
@Test
public void testGcAllPauseMarkStart() {
- AbstractGCEvent pauseMarkStartEvent = gcAllModel.get(0).getPhases().get(0);
+ AbstractGCEvent pauseMarkStartEvent = gcAllModel.getGCEvents().next().getPhases().get(0);
UnittestHelper.testMemoryPauseEvent(pauseMarkStartEvent,
"Pause Mark Start",
AbstractGCEvent.Type.UJL_ZGC_PAUSE_MARK_START,
@@ -72,7 +81,7 @@ public void testGcAllPauseMarkStart() {
@Test
public void testGcAllConcurrentMark() {
- AbstractGCEvent concurrentMarkEvent = gcAllModel.get(0).getPhases().get(1);
+ AbstractGCEvent concurrentMarkEvent = gcAllModel.get(CONCURRENT_MARK_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentMarkEvent,
"Concurrent Mark",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_MARK,
@@ -84,7 +93,7 @@ public void testGcAllConcurrentMark() {
@Test
public void testGcAllPauseMarkEnd() {
- AbstractGCEvent pauseMarkEndEvent = gcAllModel.get(0).getPhases().get(2);
+ AbstractGCEvent pauseMarkEndEvent = gcAllModel.getGCEvents().next().getPhases().get(1);
UnittestHelper.testMemoryPauseEvent(pauseMarkEndEvent,
"Pause Mark End",
AbstractGCEvent.Type.UJL_ZGC_PAUSE_MARK_END,
@@ -96,7 +105,7 @@ public void testGcAllPauseMarkEnd() {
@Test
public void testGcAllConcurrentNonref() {
- AbstractGCEvent concurrentNonrefEvent = gcAllModel.get(0).getPhases().get(3);
+ AbstractGCEvent concurrentNonrefEvent = gcAllModel.get(CONCURRENT_PROCESS_REFERENCES_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentNonrefEvent,
"Concurrent Process Non-Strong References",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_NONREF,
@@ -108,7 +117,7 @@ public void testGcAllConcurrentNonref() {
@Test
public void testGcAllConcurrentResetRelocSet() {
- AbstractGCEvent concurrentResetRelocSetEvent = gcAllModel.get(0).getPhases().get(4);
+ AbstractGCEvent concurrentResetRelocSetEvent = gcAllModel.get(CONCURRENT_RESET_RELOCATION_SET_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentResetRelocSetEvent,
"Concurrent Reset Relocation Set",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_RESET_RELOC_SET,
@@ -120,7 +129,7 @@ public void testGcAllConcurrentResetRelocSet() {
@Test
public void testGcAllConcurrentDetachedPages() {
- AbstractGCEvent concurrentDetachedPagesEvent = gcAllModel.get(0).getPhases().get(5);
+ AbstractGCEvent concurrentDetachedPagesEvent = gcAllModel.get(CONCURRENT_DESTROY_DETACHED_PAGES_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentDetachedPagesEvent,
"Concurrent Destroy Detached Pages",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_DETATCHED_PAGES,
@@ -132,7 +141,7 @@ public void testGcAllConcurrentDetachedPages() {
@Test
public void testGcAllConcurrentSelectRelocSet() {
- AbstractGCEvent concurrentSelectRelocSetEvent = gcAllModel.get(0).getPhases().get(6);
+ AbstractGCEvent concurrentSelectRelocSetEvent = gcAllModel.get(CONCURRENT_SELECT_RELOCATION_SET_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentSelectRelocSetEvent,
"Concurrent Select Relocation Set",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_SELECT_RELOC_SET,
@@ -144,7 +153,7 @@ public void testGcAllConcurrentSelectRelocSet() {
@Test
public void testGcAllConcurrentPrepareRelocSet() {
- AbstractGCEvent concurrentPrepareRelocSetEvent = gcAllModel.get(0).getPhases().get(7);
+ AbstractGCEvent concurrentPrepareRelocSetEvent = gcAllModel.get(CONCURRENT_PREPARE_RELOCATION_SET_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentPrepareRelocSetEvent,
"Concurrent Prepare Relocation Set",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_PREPARE_RELOC_SET,
@@ -156,7 +165,7 @@ public void testGcAllConcurrentPrepareRelocSet() {
@Test
public void testGcAllPauseRelocateStart() {
- AbstractGCEvent pauseRelocateStartEvent = gcAllModel.get(0).getPhases().get(8);
+ AbstractGCEvent pauseRelocateStartEvent = gcAllModel.getGCEvents().next().getPhases().get(2);
UnittestHelper.testMemoryPauseEvent(pauseRelocateStartEvent,
"Pause Relocate Start",
AbstractGCEvent.Type.UJL_ZGC_PAUSE_RELOCATE_START,
@@ -168,7 +177,7 @@ public void testGcAllPauseRelocateStart() {
@Test
public void testGcAllConcurrentRelocate() {
- AbstractGCEvent concurrentRelocateEvent = gcAllModel.get(0).getPhases().get(9);
+ AbstractGCEvent concurrentRelocateEvent = gcAllModel.get(CONCURRENT_RELOCATE_INDEX);
UnittestHelper.testMemoryPauseEvent(concurrentRelocateEvent,
"Concurrent Relocate",
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_RELOCATE,
@@ -206,7 +215,7 @@ public void testGcDefaultWarmup() {
"Warmup heap",
AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION,
0,
- 1024 * 208, 1024 * 164, 0,
+ 1024 * 208, 1024 * 164, 1024 * 164 / 16 * 100,
AbstractGCEvent.Generation.TENURED,
false);
}
@@ -218,7 +227,7 @@ public void testGcDefaultProactive() {
"Proactive heap",
AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION,
0,
- 1024 * 19804, 1024 * 20212, 0,
+ 1024 * 19804, 1024 * 20212, 20212 * 1024 / 10 * 100,
AbstractGCEvent.Generation.TENURED,
false);
}
@@ -230,7 +239,7 @@ public void testGcDefaultAllocationRate() {
"Allocation Rate heap",
AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION,
0,
- 1024 * 502, 1024 * 716, 0,
+ 1024 * 502, 1024 * 716, 716 * 1024 / 70 * 100,
AbstractGCEvent.Generation.TENURED,
false);
}
@@ -242,8 +251,9 @@ public void testDefaultGcSystemGc() {
"System.gc() heap",
AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION,
0,
- 1024 * 10124, 1024 * 5020, 0,
+ 1024 * 10124, 1024 * 5020, 5020 * 1024 / 5 * 100,
AbstractGCEvent.Generation.TENURED,
false);
}
+
}
\ No newline at end of file
diff --git a/src/test/resources/openjdk/unified-jvm-logging/SampleShenandoahAllocationFailure.txt b/src/test/resources/openjdk/unified-jvm-logging/SampleShenandoahAllocationFailure.txt
index bac605be..2b8bcfd3 100644
--- a/src/test/resources/openjdk/unified-jvm-logging/SampleShenandoahAllocationFailure.txt
+++ b/src/test/resources/openjdk/unified-jvm-logging/SampleShenandoahAllocationFailure.txt
@@ -6,8 +6,8 @@
[29.675s][info][gc,phases ] GC(831) Phase 1: Mark live objects 17.256ms
[29.675s][info][gc,phases,start] GC(831) Phase 2: Compute new object addresses
[29.699s][info][gc,phases ] GC(831) Phase 2: Compute new object addresses 23.568ms
-[29.699s][info][gc,phases,start] GC(831) Phase 2: Adjust pointers
-[29.725s][info][gc,phases ] GC(831) Phase 2: Adjust pointers 26.061ms
+[29.699s][info][gc,phases,start] GC(831) Phase 3: Adjust pointers
+[29.725s][info][gc,phases ] GC(831) Phase 3: Adjust pointers 26.061ms
[29.725s][info][gc,phases,start] GC(831) Phase 4: Move objects
[43.914s][info][gc,phases ] GC(831) Phase 4: Move objects 14078.141ms
[43.948s][info][gc ] GC(831) Pause Full (Allocation Failure) 7943M->6013M(8192M) 14289.335ms
\ No newline at end of file