Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feature/258/jdk-17-parsing #259

Closed
wants to merge 1 commit into from
Closed

feature/258/jdk-17-parsing #259

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 11 additions & 5 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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