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 8cddca04..1e48f014 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java @@ -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]+)%\\))"; @@ -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 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 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 EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", @@ -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 -> should be logged only */ private static final List LOG_ONLY_STRINGS = Arrays.asList("Using", - "Heap region size", + "Heap region size", // jdk 11 + "Heap Region Size", // jdk 17 "Consider", "Heuristics ergonomically sets"); 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 64802709..7584412b 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java @@ -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 } @@ -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 } @@ -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); @@ -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); diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java b/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java index f717054a..a3c44309 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java @@ -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) diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java index 3bbb34be..112f5c33 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java @@ -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()); } @@ -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); @@ -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()); diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java index 022712f0..0f24eead 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java @@ -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; @@ -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" + @@ -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)); } @@ -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" + diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK17.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK17.java new file mode 100644 index 00000000..b50753d7 --- /dev/null +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK17.java @@ -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 gcEventIterator = (Iterator)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 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)); + + } +} \ No newline at end of file diff --git a/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-jdk17-full-concurrent-cycle-g1-gc-all-safepont,os-cpu.txt b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-jdk17-full-concurrent-cycle-g1-gc-all-safepont,os-cpu.txt new file mode 100644 index 00000000..72fef6dd --- /dev/null +++ b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-jdk17-full-concurrent-cycle-g1-gc-all-safepont,os-cpu.txt @@ -0,0 +1,137 @@ +[2022-01-29T16:34:51.642+0000][233ms][info][gc ] GC(5) Concurrent Mark Cycle +[2022-01-29T16:34:51.642+0000][233ms][info][gc,marking ] GC(5) Concurrent Clear Claimed Marks +[2022-01-29T16:34:51.643+0000][234ms][info][gc,marking ] GC(5) Concurrent Clear Claimed Marks 0.443ms +[2022-01-29T16:34:51.644+0000][235ms][info][gc,marking ] GC(5) Concurrent Scan Root Regions +[2022-01-29T16:34:51.644+0000][235ms][info][gc,marking ] GC(5) Concurrent Scan Root Regions 0.468ms +[2022-01-29T16:34:51.644+0000][235ms][info][gc,start ] GC(6) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.644+0000][236ms][info][gc,marking ] GC(5) Concurrent Mark +[2022-01-29T16:34:51.645+0000][236ms][info][gc,task ] GC(6) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.645+0000][236ms][info][gc,marking ] GC(5) Concurrent Mark From Roots +[2022-01-29T16:34:51.646+0000][237ms][info][gc,task ] GC(5) Using 1 workers of 1 for marking +[2022-01-29T16:34:51.649+0000][240ms][info][gc,phases ] GC(6) Pre Evacuate Collection Set: 1.0ms +[2022-01-29T16:34:51.650+0000][241ms][info][gc,phases ] GC(6) Merge Heap Roots: 0.1ms +[2022-01-29T16:34:51.650+0000][241ms][info][gc,phases ] GC(6) Evacuate Collection Set: 2.3ms +[2022-01-29T16:34:51.651+0000][242ms][info][gc,phases ] GC(6) Post Evacuate Collection Set: 0.9ms +[2022-01-29T16:34:51.651+0000][242ms][info][gc,phases ] GC(6) Other: 1.3ms +[2022-01-29T16:34:51.652+0000][243ms][info][gc,heap ] GC(6) Eden regions: 6->0(6) +[2022-01-29T16:34:51.652+0000][243ms][info][gc,heap ] GC(6) Survivor regions: 1->1(1) +[2022-01-29T16:34:51.652+0000][243ms][info][gc,heap ] GC(6) Old regions: 7->13 +[2022-01-29T16:34:51.653+0000][244ms][info][gc,heap ] GC(6) Archive regions: 2->2 +[2022-01-29T16:34:51.653+0000][244ms][info][gc,heap ] GC(6) Humongous regions: 0->0 +[2022-01-29T16:34:51.654+0000][245ms][info][gc,metaspace] GC(6) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.654+0000][245ms][info][gc ] GC(6) Pause Young (Normal) (G1 Evacuation Pause) 14M->14M(46M) 9.772ms +[2022-01-29T16:34:51.654+0000][246ms][info][gc,cpu ] GC(6) User=0.01s Sys=0.00s Real=0.01s +[2022-01-29T16:34:51.655+0000][246ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 1634200 ns, Reaching safepoint: 92800 ns, At safepoint: 11173200 ns, Total: 11266000 ns +[2022-01-29T16:34:51.656+0000][247ms][info][gc,start ] GC(7) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.656+0000][247ms][info][gc,task ] GC(7) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.660+0000][251ms][info][gc,phases ] GC(7) Pre Evacuate Collection Set: 0.2ms +[2022-01-29T16:34:51.661+0000][252ms][info][gc,phases ] GC(7) Merge Heap Roots: 0.2ms +[2022-01-29T16:34:51.661+0000][252ms][info][gc,phases ] GC(7) Evacuate Collection Set: 2.8ms +[2022-01-29T16:34:51.661+0000][252ms][info][gc,phases ] GC(7) Post Evacuate Collection Set: 0.4ms +[2022-01-29T16:34:51.661+0000][253ms][info][gc,phases ] GC(7) Other: 1.0ms +[2022-01-29T16:34:51.662+0000][253ms][info][gc,heap ] GC(7) Eden regions: 6->0(5) +[2022-01-29T16:34:51.662+0000][253ms][info][gc,heap ] GC(7) Survivor regions: 1->1(1) +[2022-01-29T16:34:51.662+0000][253ms][info][gc,heap ] GC(7) Old regions: 13->19 +[2022-01-29T16:34:51.662+0000][253ms][info][gc,heap ] GC(7) Archive regions: 2->2 +[2022-01-29T16:34:51.662+0000][254ms][info][gc,heap ] GC(7) Humongous regions: 0->0 +[2022-01-29T16:34:51.663+0000][254ms][info][gc,metaspace] GC(7) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.663+0000][254ms][info][gc ] GC(7) Pause Young (Normal) (G1 Evacuation Pause) 20M->20M(46M) 7.214ms +[2022-01-29T16:34:51.663+0000][254ms][info][gc,cpu ] GC(7) User=0.00s Sys=0.00s Real=0.01s +[2022-01-29T16:34:51.664+0000][255ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 695000 ns, Reaching safepoint: 284900 ns, At safepoint: 7921000 ns, Total: 8205900 ns +[2022-01-29T16:34:51.664+0000][256ms][info][gc,start ] GC(8) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.665+0000][256ms][info][gc,task ] GC(8) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.667+0000][259ms][info][gc,phases ] GC(8) Pre Evacuate Collection Set: 0.1ms +[2022-01-29T16:34:51.668+0000][259ms][info][gc,phases ] GC(8) Merge Heap Roots: 0.1ms +[2022-01-29T16:34:51.668+0000][259ms][info][gc,phases ] GC(8) Evacuate Collection Set: 1.0ms +[2022-01-29T16:34:51.669+0000][260ms][info][gc,phases ] GC(8) Post Evacuate Collection Set: 0.7ms +[2022-01-29T16:34:51.669+0000][260ms][info][gc,phases ] GC(8) Other: 1.0ms +[2022-01-29T16:34:51.669+0000][260ms][info][gc,heap ] GC(8) Eden regions: 5->0(3) +[2022-01-29T16:34:51.669+0000][261ms][info][gc,heap ] GC(8) Survivor regions: 1->1(1) +[2022-01-29T16:34:51.670+0000][261ms][info][gc,heap ] GC(8) Old regions: 19->24 +[2022-01-29T16:34:51.670+0000][261ms][info][gc,heap ] GC(8) Archive regions: 2->2 +[2022-01-29T16:34:51.670+0000][261ms][info][gc,heap ] GC(8) Humongous regions: 0->0 +[2022-01-29T16:34:51.670+0000][262ms][info][gc,metaspace] GC(8) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.671+0000][262ms][info][gc ] GC(8) Pause Young (Normal) (G1 Evacuation Pause) 25M->25M(46M) 6.217ms +[2022-01-29T16:34:51.671+0000][262ms][info][gc,cpu ] GC(8) User=0.01s Sys=0.00s Real=0.01s +[2022-01-29T16:34:51.671+0000][263ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 611400 ns, Reaching safepoint: 266400 ns, At safepoint: 6896400 ns, Total: 7162800 ns +[2022-01-29T16:34:51.672+0000][263ms][info][gc,start ] GC(9) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.672+0000][263ms][info][gc,task ] GC(9) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.675+0000][266ms][info][gc,phases ] GC(9) Pre Evacuate Collection Set: 0.1ms +[2022-01-29T16:34:51.676+0000][267ms][info][gc,phases ] GC(9) Merge Heap Roots: 0.1ms +[2022-01-29T16:34:51.676+0000][267ms][info][gc,phases ] GC(9) Evacuate Collection Set: 0.8ms +[2022-01-29T16:34:51.676+0000][267ms][info][gc,phases ] GC(9) Post Evacuate Collection Set: 1.4ms +[2022-01-29T16:34:51.677+0000][268ms][info][gc,phases ] GC(9) Other: 0.5ms +[2022-01-29T16:34:51.677+0000][268ms][info][gc,heap ] GC(9) Eden regions: 3->0(28) +[2022-01-29T16:34:51.677+0000][269ms][info][gc,heap ] GC(9) Survivor regions: 1->1(1) +[2022-01-29T16:34:51.678+0000][269ms][info][gc,heap ] GC(9) Old regions: 24->27 +[2022-01-29T16:34:51.678+0000][269ms][info][gc,heap ] GC(9) Archive regions: 2->2 +[2022-01-29T16:34:51.678+0000][269ms][info][gc,heap ] GC(9) Humongous regions: 0->0 +[2022-01-29T16:34:51.679+0000][270ms][info][gc,metaspace] GC(9) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.679+0000][270ms][info][gc ] GC(9) Pause Young (Normal) (G1 Evacuation Pause) 28M->28M(138M) 6.982ms +[2022-01-29T16:34:51.679+0000][270ms][info][gc,cpu ] GC(9) User=0.00s Sys=0.00s Real=0.00s +[2022-01-29T16:34:51.679+0000][271ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 430500 ns, Reaching safepoint: 201800 ns, At safepoint: 7434700 ns, Total: 7636500 ns +[2022-01-29T16:34:51.680+0000][272ms][info][gc,marking ] GC(5) Concurrent Mark From Roots 35.374ms +[2022-01-29T16:34:51.681+0000][272ms][info][gc,marking ] GC(5) Concurrent Preclean +[2022-01-29T16:34:51.681+0000][273ms][info][gc,marking ] GC(5) Concurrent Preclean 0.420ms +[2022-01-29T16:34:51.682+0000][273ms][info][gc,start ] GC(5) Pause Remark +[2022-01-29T16:34:51.683+0000][275ms][info][gc ] GC(5) Pause Remark 46M->46M(138M) 1.314ms +[2022-01-29T16:34:51.684+0000][275ms][info][gc,cpu ] GC(5) User=0.00s Sys=0.01s Real=0.00s +[2022-01-29T16:34:51.684+0000][275ms][info][safepoint ] Safepoint "G1Concurrent", Time since last: 2513300 ns, Reaching safepoint: 177200 ns, At safepoint: 2163400 ns, Total: 2340600 ns +[2022-01-29T16:34:51.685+0000][276ms][info][gc,marking ] GC(5) Concurrent Mark 40.340ms +[2022-01-29T16:34:51.685+0000][276ms][info][gc,marking ] GC(5) Concurrent Rebuild Remembered Sets +[2022-01-29T16:34:51.686+0000][277ms][info][gc,start ] GC(10) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.687+0000][278ms][info][gc,task ] GC(10) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.697+0000][288ms][info][gc,phases ] GC(10) Pre Evacuate Collection Set: 0.1ms +[2022-01-29T16:34:51.697+0000][288ms][info][gc,phases ] GC(10) Merge Heap Roots: 0.1ms +[2022-01-29T16:34:51.697+0000][289ms][info][gc,phases ] GC(10) Evacuate Collection Set: 8.7ms +[2022-01-29T16:34:51.698+0000][289ms][info][gc,phases ] GC(10) Post Evacuate Collection Set: 0.7ms +[2022-01-29T16:34:51.698+0000][289ms][info][gc,phases ] GC(10) Other: 0.8ms +[2022-01-29T16:34:51.698+0000][289ms][info][gc,heap ] GC(10) Eden regions: 28->0(19) +[2022-01-29T16:34:51.698+0000][290ms][info][gc,heap ] GC(10) Survivor regions: 1->4(4) +[2022-01-29T16:34:51.699+0000][290ms][info][gc,heap ] GC(10) Old regions: 27->52 +[2022-01-29T16:34:51.699+0000][290ms][info][gc,heap ] GC(10) Archive regions: 2->2 +[2022-01-29T16:34:51.699+0000][290ms][info][gc,heap ] GC(10) Humongous regions: 0->0 +[2022-01-29T16:34:51.699+0000][290ms][info][gc,metaspace] GC(10) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.699+0000][291ms][info][gc ] GC(10) Pause Young (Normal) (G1 Evacuation Pause) 56M->56M(138M) 13.221ms +[2022-01-29T16:34:51.700+0000][291ms][info][gc,cpu ] GC(10) User=0.00s Sys=0.01s Real=0.01s +[2022-01-29T16:34:51.700+0000][291ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 1746600 ns, Reaching safepoint: 157800 ns, At safepoint: 13667700 ns, Total: 13825500 ns +[2022-01-29T16:34:51.701+0000][292ms][info][gc,marking ] GC(5) Concurrent Rebuild Remembered Sets 15.514ms +[2022-01-29T16:34:51.701+0000][293ms][info][gc,start ] GC(5) Pause Cleanup +[2022-01-29T16:34:51.702+0000][293ms][info][gc ] GC(5) Pause Cleanup 67M->67M(138M) 0.371ms +[2022-01-29T16:34:51.702+0000][293ms][info][gc,cpu ] GC(5) User=0.00s Sys=0.00s Real=0.00s +[2022-01-29T16:34:51.702+0000][293ms][info][safepoint ] Safepoint "G1Concurrent", Time since last: 1375400 ns, Reaching safepoint: 249200 ns, At safepoint: 810500 ns, Total: 1059700 ns +[2022-01-29T16:34:51.703+0000][294ms][info][gc,marking ] GC(5) Concurrent Cleanup for Next Mark +[2022-01-29T16:34:51.703+0000][295ms][info][gc,start ] GC(11) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.704+0000][295ms][info][gc,task ] GC(11) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.706+0000][297ms][info][gc,phases ] GC(11) Pre Evacuate Collection Set: 0.1ms +[2022-01-29T16:34:51.706+0000][297ms][info][gc,phases ] GC(11) Merge Heap Roots: 0.1ms +[2022-01-29T16:34:51.707+0000][298ms][info][gc,phases ] GC(11) Evacuate Collection Set: 1.6ms +[2022-01-29T16:34:51.707+0000][298ms][info][gc,phases ] GC(11) Post Evacuate Collection Set: 0.4ms +[2022-01-29T16:34:51.707+0000][298ms][info][gc,phases ] GC(11) Other: 0.6ms +[2022-01-29T16:34:51.707+0000][298ms][info][gc,heap ] GC(11) Eden regions: 19->0(9) +[2022-01-29T16:34:51.707+0000][299ms][info][gc,heap ] GC(11) Survivor regions: 4->3(3) +[2022-01-29T16:34:51.708+0000][299ms][info][gc,heap ] GC(11) Old regions: 52->57 +[2022-01-29T16:34:51.708+0000][299ms][info][gc,heap ] GC(11) Archive regions: 2->2 +[2022-01-29T16:34:51.708+0000][300ms][info][gc,heap ] GC(11) Humongous regions: 0->0 +[2022-01-29T16:34:51.709+0000][300ms][info][gc,metaspace] GC(11) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.709+0000][300ms][info][gc ] GC(11) Pause Young (Normal) (G1 Evacuation Pause) 75M->60M(138M) 5.623ms +[2022-01-29T16:34:51.709+0000][300ms][info][gc,cpu ] GC(11) User=0.00s Sys=0.01s Real=0.00s +[2022-01-29T16:34:51.710+0000][301ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 927600 ns, Reaching safepoint: 123300 ns, At safepoint: 6218900 ns, Total: 6342200 ns +[2022-01-29T16:34:51.710+0000][302ms][info][gc,marking ] GC(5) Concurrent Cleanup for Next Mark 7.873ms +[2022-01-29T16:34:51.711+0000][303ms][info][gc,start ] GC(12) Pause Young (Normal) (G1 Evacuation Pause) +[2022-01-29T16:34:51.712+0000][304ms][info][gc,task ] GC(12) Using 1 workers of 1 for evacuation +[2022-01-29T16:34:51.716+0000][307ms][info][gc,phases ] GC(12) Pre Evacuate Collection Set: 0.1ms +[2022-01-29T16:34:51.717+0000][308ms][info][gc,phases ] GC(12) Merge Heap Roots: 0.1ms +[2022-01-29T16:34:51.717+0000][308ms][info][gc,phases ] GC(12) Evacuate Collection Set: 2.8ms +[2022-01-29T16:34:51.717+0000][308ms][info][gc,phases ] GC(12) Post Evacuate Collection Set: 0.5ms +[2022-01-29T16:34:51.717+0000][309ms][info][gc,phases ] GC(12) Other: 1.5ms +[2022-01-29T16:34:51.718+0000][309ms][info][gc,heap ] GC(12) Eden regions: 9->0(11) +[2022-01-29T16:34:51.718+0000][309ms][info][gc,heap ] GC(12) Survivor regions: 3->2(2) +[2022-01-29T16:34:51.718+0000][309ms][info][gc,heap ] GC(12) Old regions: 57->67 +[2022-01-29T16:34:51.718+0000][309ms][info][gc,heap ] GC(12) Archive regions: 2->2 +[2022-01-29T16:34:51.719+0000][310ms][info][gc,heap ] GC(12) Humongous regions: 0->0 +[2022-01-29T16:34:51.719+0000][310ms][info][gc,metaspace] GC(12) Metaspace: 258K(448K)->258K(448K) NonClass: 242K(320K)->242K(320K) Class: 15K(128K)->15K(128K) +[2022-01-29T16:34:51.719+0000][310ms][info][gc ] GC(12) Pause Young (Normal) (G1 Evacuation Pause) 69M->69M(138M) 7.590ms +[2022-01-29T16:34:51.719+0000][310ms][info][gc,cpu ] GC(12) User=0.01s Sys=0.00s Real=0.00s +[2022-01-29T16:34:51.719+0000][311ms][info][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 1634200 ns, Reaching safepoint: 114200 ns, At safepoint: 8121500 ns, Total: 8235700 ns +[2022-01-29T16:34:51.719+0000][311ms][info][gc ] GC(5) Concurrent Mark Cycle 77.704ms