Skip to content

Commit

Permalink
chewiebug#216 also support parsing of phases for Serial, Parallel, CM…
Browse files Browse the repository at this point in the history 
…S, G1 and Shenandoah collectors
  • Loading branch information
@chewiebug
chewiebug committed Jun 10, 2019
1 parent 3dcc401 commit 2a2535c
Show file tree
Hide file tree
Showing 10 changed files with 265 additions and 27 deletions.
26 changes: 21 additions & 5 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -46,6 +46,7 @@
* For more information about Shenandoah see: <a href="https://wiki.openjdk.java.net/display/shenandoah/Main">Shenandoah Wiki at OpenJDK</a>
*/
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
Expand All @@ -58,7 +59,7 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
// Regex: ^(?:\[(?<time>[0-9-T:.+]*)])?(?:\[(?<uptime>[^s]*)s])?\[(?<level>[^]]+)]\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\((?<gcnumber>[0-9]+)\)[ ](?<type>([-.a-zA-Z ()]+|[a-zA-Z1 ()]+))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)
// note for the <type> 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(
"^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
"^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
);
private static final String GROUP_DECORATORS_TIME = "time";
private static final String GROUP_DECORATORS_UPTIME = "uptime";
Expand All @@ -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
Expand Down Expand Up @@ -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%)
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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) {
Expand Down
18 changes: 18 additions & 0 deletions src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
Expand Down
3 changes: 1 addition & 2 deletions src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}
Expand Down
39 changes: 39 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java
View file
Original file line number Diff line number Diff line change
@@ -1,16 +1,22 @@
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;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
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;

/**
Expand Down Expand Up @@ -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));
}

}
40 changes: 40 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java
View file
Original file line number Diff line number Diff line change
@@ -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;
Expand All @@ -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;

/**
Expand Down Expand Up @@ -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));
Expand Down
46 changes: 46 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java
View file
Original file line number Diff line number Diff line change
@@ -1,16 +1,22 @@
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;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
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;

/**
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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));
}


}
Loading

0 comments on commit 2a2535c

Please sign in to comment.