Skip to content

Commit

Permalink
improve parsing of OpenJdk 17 G1 logs
Browse files Browse the repository at this point in the history
  • Loading branch information
@chewiebug
chewiebug committed Apr 19, 2022
1 parent aa49fcd commit fd90b9d
Show file tree
Hide file tree
Showing 7 changed files with 299 additions and 12 deletions.
16 changes: 11 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 @@ -72,11 +72,12 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
private static final String GROUP_DECORATORS_GC_TYPE = "type";
private static final String GROUP_DECORATORS_TAIL = "tail";

private static final Pattern PATTERN_HEAP_REGION_SIZE = Pattern.compile("^Heap region size: ([0-9]+)M$");
private static final Pattern PATTERN_HEAP_REGION_SIZE = Pattern.compile("^Heap [Rr]egion [Ss]ize: ([0-9]+)M$");
private static final int GROUP_HEAP_REGION_SIZE = 1;

private static final String PATTERN_PAUSE_STRING = "([0-9]+[.,][0-9]+)ms";
private static final String PATTERN_MEMORY_STRING = "(([0-9]+)([BKMG])->([0-9]+)([BKMG])\\(([0-9]+)([BKMG])\\))";
/** 257K(448K)->257K(448K) - first "(448K)" is optional */
private static final String PATTERN_MEMORY_STRING = "(([0-9]+)([BKMG])(?:\\([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]+)%\\))";
Expand Down Expand Up @@ -162,7 +163,7 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
private static final String TAG_SAFEPOINT = "safepoint";

/** list of strings, that must be part of the gc log line to be considered for parsing */
private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES, Type.APPLICATION_STOPPED_TIME.getName());
private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES, Type.APPLICATION_STOPPED_TIME.getName(), "Heap Region Size");
/** list of strings, that target gc log lines, that - although part of INCLUDE_STRINGS - are not considered a gc event */
private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC",
"[debug",
Expand All @@ -172,10 +173,15 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
"[gc,phases,start",
"Trigger: ",
"Failed to allocate",
"Cancelling GC");
"Cancelling GC",
"CDS archive(s) mapped at", // metaspace preamble since JDK 17
"Compressed class space mapped at", // metaspace preamble since JDK 17
"Narrow klass base" // metaspace preamble since JDK 17
);
/** list of strings, that are gc log lines, but not a gc event -&gt; should be logged only */
private static final List<String> LOG_ONLY_STRINGS = Arrays.asList("Using",
"Heap region size",
"Heap region size", // jdk 11
"Heap Region Size", // jdk 17
"Consider",
"Heuristics ergonomically sets");

Expand Down
5 changes: 5 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 @@ -293,6 +293,7 @@ public boolean isConcurrentCollectionStart() {
|| (getExtendedType().getName().equals(Type.UJL_CMS_CONCURRENT_MARK.getName()) && getPause() > 0.000001) // Universal jvm logging, CMS
|| getExtendedType().getName().equals(Type.G1_CONCURRENT_MARK_START.getName()) // G1
|| (getExtendedType().getName().equals(Type.UJL_G1_CONCURRENT_CYCLE.getName()) && getPause() < 0.00001) // Universal jvm logging, G1
|| (getExtendedType().getName().equals(Type.UJL_G1_CONCURRENT_MARK_CYCLE.getName()) && getPause() < 0.00001) // Universal jvm logging, G1 since JDK 17
|| getExtendedType().getName().equals(Type.UJL_SHEN_CONCURRENT_RESET.getName()); // Universal Jvm logging, Shenandoah
}

Expand All @@ -302,6 +303,7 @@ public boolean isConcurrentCollectionEnd() {
|| (getExtendedType().getName().equals(Type.UJL_CMS_CONCURRENT_RESET.getName()) && getPause() > 0.0000001) // Universal jvm logging, CMS
|| getExtendedType().getName().equals(Type.G1_CONCURRENT_CLEANUP_END.getName()) // G1
|| (getExtendedType().getName().equals(Type.UJL_G1_CONCURRENT_CYCLE.getName()) && getPause() > 0.0000001) // Universal jvm logging, G1
|| (getExtendedType().getName().equals(Type.UJL_G1_CONCURRENT_MARK_CYCLE.getName()) && getPause() > 0.0000001) // Universal jvm logging, G1 since JDK 17
|| getExtendedType().getName().equals(Type.UJL_SHEN_CONCURRENT_CLEANUP.getName()); // Universal jvm logging, Shenandoah
}

Expand Down Expand Up @@ -663,6 +665,8 @@ public String toString() {
public static final Type UJL_G1_PAUSE_MIXED = new Type("Pause Mixed", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
public static final Type UJL_G1_TO_SPACE_EXHAUSTED = new Type("To-space exhausted", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC);
public static final Type UJL_G1_CONCURRENT_CYCLE = new Type("Concurrent Cycle", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_G1_CONCURRENT_MARK_CYCLE = new Type("Concurrent Mark Cycle", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_G1_CONCURRENT_UNDO_CYCLE = new Type("Concurrent Undo Cycle", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
public static final Type UJL_G1_PAUSE_CLEANUP = new Type("Pause Cleanup", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE, CollectionType.CONCURRENCY_HELPER);
public static final Type UJL_G1_EDEN = new Type("Eden regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION);
public static final Type UJL_G1_SURVIVOR = new Type("Survivor regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION);
Expand All @@ -671,6 +675,7 @@ public String toString() {
public static final Type UJL_G1_ARCHIVE = new Type("Archive 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_MERGE_HEAP_ROOTS = new Type("Merge Heap Roots", 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);
Expand Down
9 changes: 7 additions & 2 deletions src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -450,8 +450,13 @@ else if (abstractEvent instanceof VmOperationEvent) {
private void addConcurrentGcEvent(ConcurrentGCEvent concEvent) {
concurrentGCEvents.add(concEvent);

DoubleData pauses = getDoubleData(concEvent.getExtendedType().getName(), concurrentGcEventPauses);
pauses.add(concEvent.getPause());
// With UJL concurrent events usually have a "start" and an "end" event with the same name.
// The "start" event does not have a pause, the end event does. For the statistic, ignore the start event;
// otherwise the concurrent events are counted twice and distort statistics.
if (concEvent.getPause() > 0.0000001) {
DoubleData pauses = getDoubleData(concEvent.getExtendedType().getName(), concurrentGcEventPauses);
pauses.add(concEvent.getPause());
}

if (concEvent.hasMemoryInformation() && concEvent.isConcurrentCollectionEnd()) {
// register postConcurrentCycleUsedSizes, if event contains memory information. Otherwise deduce it (see in handling of GCEvent)
Expand Down
6 changes: 3 additions & 3 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -332,7 +332,7 @@ public void printTenuringDistribution() throws Exception {
GCModel model = reader.read();

assertEquals("number of events", 11, model.size());
assertEquals("number of concurrent events", 4, model.getConcurrentEventPauses().size());
assertEquals("number of concurrent events", 2, model.getConcurrentEventPauses().size());

assertEquals("number of errors", 0, handler.getCount());
}
Expand All @@ -352,7 +352,7 @@ public void printApplicationTimePrintTenuringDistribution() throws Exception {
GCModel model = reader.read();

assertEquals("number of events", 9, model.size());
assertEquals("number of concurrent events", 2, model.getConcurrentEventPauses().size());
assertEquals("number of concurrent events", 1, model.getConcurrentEventPauses().size());

GCEvent youngEvent = (GCEvent) model.get(0);
assertEquals("gc pause (young)", 0.00784501, youngEvent.getPause(), 0.000000001);
Expand Down Expand Up @@ -398,7 +398,7 @@ public void printHeapAtGcWithConcurrentEvents() throws Exception {
GCModel model = reader.read();

assertEquals("number of events", 3, model.size());
assertEquals("number of concurrent events", 2, model.getConcurrentEventPauses().size());
assertEquals("number of concurrent events", 1, model.getConcurrentEventPauses().size());

ConcurrentGCEvent concurrentEvent = (ConcurrentGCEvent) model.get(0);
assertEquals("GC concurrent-root-region-scan-end expected", "GC concurrent-root-region-scan-end", concurrentEvent.getTypeAsString());
Expand Down
10 changes: 8 additions & 2 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
import com.tagtraum.perf.gcviewer.UnittestHelper;
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
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;
Expand Down Expand Up @@ -120,7 +121,8 @@ public void testFullGcWithPhases() throws Exception {
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);
InputStream in = new ByteArrayInputStream(
("[1.204s][info][gc,task ] GC(15) Using 3 workers of 4 for full compaction\n" +
("[2021-05-24T13:51:48.779+0000][21ms][info][gc,heap] Heap region size: 1M\n" +
"[1.204s][info][gc,task ] GC(15) Using 3 workers of 4 for full compaction\n" +
"[1.204s][info][gc,start ] GC(15) Pause Full (G1 Evacuation Pause)\n" +
"[1.204s][info][gc,phases,start] GC(15) Phase 1: Mark live objects\n" +
"[1.207s][info][gc,stringtable ] GC(15) Cleaned string and symbol table, strings: 7381 processed, 70 removed, symbols: 49128 processed, 10 removed\n" +
Expand All @@ -147,6 +149,9 @@ public void testFullGcWithPhases() throws Exception {

assertThat("number of warnings", handler.getCount(), is(0));
assertThat("number of events", model.size(), is(2));
GCEvent tenuredEvent = ((GCEvent)model.get(0)).getTenured();
assertThat("tenured event pre", tenuredEvent.getPreUsed(), is(128 * 1024));
assertThat("tenured event post", tenuredEvent.getPostUsed(), is(62 * 1024));
assertThat("total heap", model.get(0).getTotal(), is(128 * 1024));
}

Expand All @@ -157,7 +162,8 @@ public void testPauseYoungConcurrentStartMetadataGcThreshold() throws Exception
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);
InputStream in = new ByteArrayInputStream(
("[1.459s][info][gc,start ] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold)\n" +
("[2021-05-24T13:51:48.779+0000][21ms][info][gc,heap] Heap region size: 1M\n" +
"[1.459s][info][gc,start ] GC(1) Pause Young (Concurrent Start) (Metadata GC Threshold)\n" +
"[1.459s][info][gc,task ] GC(1) Using 8 workers of 8 for evacuation\n" +
"[1.464s][info][gc,phases ] GC(1) Pre Evacuate Collection Set: 0.0ms\n" +
"[1.464s][info][gc,phases ] GC(1) Evacuate Collection Set: 4.1ms\n" +
Expand Down
128 changes: 128 additions & 0 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK17.java
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,128 @@
package com.tagtraum.perf.gcviewer.imp;

import static org.hamcrest.Matchers.closeTo;
import static org.hamcrest.Matchers.is;
import static org.hamcrest.Matchers.notNullValue;
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;
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 org.junit.Test;

/**
* Test unified java logging G1 algorithm in OpenJDK 17
*/
public class TestDataReaderUJLG1JDK17 {
private GCModel getGCModelFromLogFile(String fileName) throws IOException {
return UnittestHelper.getGCModelFromLogFile(fileName, FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class);
}

@Test
public void testG1MetaspacePreamble() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);
InputStream in = new ByteArrayInputStream(
("[2022-01-29T16:34:51.445+0000][36ms][info][gc,metaspace] CDS archive(s) mapped at: [0x0000000800000000-0x0000000800bcf000-0x0000000800bcf000), size 12382208, SharedBaseAddress: 0x0000000800000000, ArchiveRelocationMode: 0.\n" +
"[2022-01-29T16:34:51.445+0000][36ms][info][gc,metaspace] Compressed class space mapped at: 0x0000000800c00000-0x0000000840c00000, reserved size: 1073741824\n" +
"[2022-01-29T16:34:51.445+0000][36ms][info][gc,metaspace] Narrow klass base: 0x0000000800000000, Narrow klass shift: 3, Narrow klass range: 0x100000000\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(0));
}

@Test
public void testG1PauseYoungNormal() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);
InputStream in = new ByteArrayInputStream(
("[2022-04-19T19:34:40.899+0000][23ms][info][gc,init] Heap Region Size: 2M\n" +
"[2022-01-29T16:34:51.601+0000][192ms][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)\n" +
"[2022-01-29T16:34:51.601+0000][192ms][info][gc,task ] GC(0) Using 1 workers of 1 for evacuation\n" +
"[2022-01-29T16:34:51.608+0000][199ms][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.2ms\n" +
"[2022-01-29T16:34:51.608+0000][199ms][info][gc,phases ] GC(0) Merge Heap Roots: 0.2ms\n" +
"[2022-01-29T16:34:51.609+0000][200ms][info][gc,phases ] GC(0) Evacuate Collection Set: 4.8ms\n" +
"[2022-01-29T16:34:51.609+0000][200ms][info][gc,phases ] GC(0) Post Evacuate Collection Set: 1.0ms\n" +
"[2022-01-29T16:34:51.609+0000][200ms][info][gc,phases ] GC(0) Other: 0.9ms\n" +
"[2022-01-29T16:34:51.609+0000][201ms][info][gc,heap ] GC(0) Eden regions: 2->0(1)\n" +
"[2022-01-29T16:34:51.610+0000][201ms][info][gc,heap ] GC(0) Survivor regions: 0->1(1)\n" +
"[2022-01-29T16:34:51.610+0000][201ms][info][gc,heap ] GC(0) Old regions: 0->1\n" +
"[2022-01-29T16:34:51.610+0000][201ms][info][gc,heap ] GC(0) Archive regions: 2->2\n" +
"[2022-01-29T16:34:51.610+0000][202ms][info][gc,heap ] GC(0) Humongous regions: 0->0\n" +
"[2022-01-29T16:34:51.611+0000][202ms][info][gc,metaspace] GC(0) Metaspace: 257K(448K)->257K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K)\n" +
"[2022-01-29T16:34:51.611+0000][203ms][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 2M->2M(18M) 10.669ms\n" +
"[2022-01-29T16:34:51.612+0000][203ms][info][gc,cpu ] GC(0) User=0.00s Sys=0.00s Real=0.01s\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));
Iterator<GCEvent> gcEventIterator = (Iterator<GCEvent>)model.get(0).details();
GCEvent tenuredEvent = ((GCEvent)model.get(0)).getTenured();
assertThat("tenured event", tenuredEvent, notNullValue());
assertThat("tenured event pre", tenuredEvent.getPreUsed(), is(2 * 2048));
assertThat("tenured event post", tenuredEvent.getPostUsed(), is(3 * 2048));
}

@Test
public void testG1FullConcurrentMarkCycle() throws Exception {
GCModel model = getGCModelFromLogFile("sample-ujl-jdk17-full-concurrent-cycle-g1-gc-all-safepont,os-cpu.txt");
assertThat("size", model.size(), is(11));
assertThat("concurrent event count", model.getConcurrentEventPauses().size(), is(1));

Iterator<ConcurrentGCEvent> concurrentGCEventIterator = model.getConcurrentGCEvents();
ConcurrentGCEvent concurrentGCEvent = concurrentGCEventIterator.next();
assertThat("concurrent event, start", concurrentGCEvent.isConcurrentCollectionStart(), is(true));
assertThat("iterator hasNext", concurrentGCEventIterator.hasNext(), is(true));

ConcurrentGCEvent concurrentGCEventEnd = concurrentGCEventIterator.next();
assertThat("concurrent event, end", concurrentGCEventEnd.isConcurrentCollectionEnd(), is(true));
assertThat("concurrent event, duration", concurrentGCEventEnd.getPause(), closeTo(0.077704, 0.000001));

assertThat("iterator is finished", concurrentGCEventIterator.hasNext(), is(false));
}

@Test
public void testG1ConcurrentUndoCycle() throws IOException {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
GCResource gcResource = new GcResourceFile("byteArray");
gcResource.getLogger().addHandler(handler);
InputStream in = new ByteArrayInputStream(
("[2022-04-19T19:34:58.116+0000][17241ms][info][gc ] GC(822) Concurrent Undo Cycle\n" +
"[2022-04-19T19:34:58.117+0000][17241ms][info][gc,marking ] GC(822) Concurrent Cleanup for Next Mark\n" +
"[2022-04-19T19:34:58.118+0000][17243ms][info][gc,marking ] GC(822) Concurrent Cleanup for Next Mark 1.819ms\n" +
"[2022-04-19T19:34:58.119+0000][17243ms][info][gc ] GC(822) Concurrent Undo Cycle 2.662ms\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("Concurrent undo Cycle", model.get(0).getPause(), closeTo(0.0, 0.01));
assertThat("Concurrent undo Cycle with Pause", model.get(1).getPause(), closeTo(0.002662, 0.000001));

}
}
Loading

0 comments on commit fd90b9d

Please sign in to comment.