diff --git a/IT/src/test/java/com/microsoft/gctoolkit/integration/UnifiedSafepointAggregationTest.java b/IT/src/test/java/com/microsoft/gctoolkit/integration/UnifiedSafepointAggregationTest.java new file mode 100644 index 000000000..ae1f05958 --- /dev/null +++ b/IT/src/test/java/com/microsoft/gctoolkit/integration/UnifiedSafepointAggregationTest.java @@ -0,0 +1,127 @@ +package com.microsoft.gctoolkit.integration; + +import com.microsoft.gctoolkit.GCToolKit; +import com.microsoft.gctoolkit.aggregator.Aggregates; +import com.microsoft.gctoolkit.aggregator.Aggregation; +import com.microsoft.gctoolkit.aggregator.Aggregator; +import com.microsoft.gctoolkit.aggregator.Collates; +import com.microsoft.gctoolkit.aggregator.EventSource; +import com.microsoft.gctoolkit.event.jvm.ApplicationStoppedTime; +import com.microsoft.gctoolkit.integration.io.TestLogFile; +import com.microsoft.gctoolkit.io.GCLogFile; +import com.microsoft.gctoolkit.io.SingleGCLogFile; +import com.microsoft.gctoolkit.jvm.JavaVirtualMachine; +import org.junit.jupiter.api.Tag; +import org.junit.jupiter.api.Test; + +import java.io.IOException; +import java.nio.file.Path; +import java.util.ArrayList; +import java.util.List; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.junit.jupiter.api.Assertions.fail; + +/** + * End to end coverage for the single safepoint line aggregation. + */ +@Tag("modulePath") +public class UnifiedSafepointAggregationTest { + + private SafepointSummary analyze(String logName) { + GCLogFile logFile = new SingleGCLogFile(Path.of(new TestLogFile(logName).getFile().getPath())); + GCToolKit gcToolKit = new GCToolKit(); + gcToolKit.loadAggregation(new SafepointSummary()); + JavaVirtualMachine machine = null; + try { + machine = gcToolKit.analyze(logFile); + } catch (IOException e) { + fail(e.getMessage()); + } + return machine.getAggregation(SafepointSummary.class).orElseGet(() -> { + fail("SAFEPOINT aggregation was not run for " + logName); + return null; + }); + } + + @Test + public void testZGCSafepoints() { + SafepointSummary summary = analyze("zgc/zgc.log"); + assertEquals(3478, summary.count(), "safepoint lines in zgc.log"); + assertTrue(summary.totalTimeToSafepoint() > 0.0d, "ZGC log should report time to safepoint"); + assertTrue(summary.reasons().contains(ApplicationStoppedTime.VMOperations.ZMarkStart), + "expected ZGC VM operations to be recognised"); + // All but the two "Cleanup" safepoints, which are not collections + assertEquals(3476, summary.gcPauseCount(), "ZGC safepoints attributed to a collection"); + } + + @Test + public void testG1Safepoints() { + SafepointSummary summary = analyze("g1gc/G1-80-16gbps2.log.0"); + assertEquals(2158, summary.count(), "safepoint lines in G1-80-16gbps2.log.0"); + assertTrue(summary.reasons().contains(ApplicationStoppedTime.VMOperations.G1CollectForAllocation)); + } + + @Test + public void testSerialSafepoints() { + SafepointSummary summary = analyze("serial/factorization-serialgc-tip.log"); + assertEquals(17, summary.count(), "safepoint lines in factorization-serialgc-tip.log"); + assertTrue(summary.reasons().contains(ApplicationStoppedTime.VMOperations.SerialGCCollect)); + } + + @Aggregates(EventSource.SAFEPOINT) + public static class SafepointAggregator extends Aggregator { + + public SafepointAggregator(SafepointSummary aggregation) { + super(aggregation); + register(ApplicationStoppedTime.class, this::process); + } + + private void process(ApplicationStoppedTime event) { + aggregation().record(event); + } + } + + @Collates(SafepointAggregator.class) + public static class SafepointSummary extends Aggregation { + + private final List reasons = new ArrayList<>(); + private double totalTimeToSafepoint = 0.0d; + private int gcPauseCount = 0; + + public void record(ApplicationStoppedTime event) { + reasons.add(event.getSafePointReason()); + if (event.isGCPause()) + gcPauseCount++; + if (event.hasTTSP()) + totalTimeToSafepoint += event.getTimeToStopThreads(); + } + + public int count() { + return reasons.size(); + } + + public int gcPauseCount() { + return gcPauseCount; + } + + public List reasons() { + return reasons; + } + + public double totalTimeToSafepoint() { + return totalTimeToSafepoint; + } + + @Override + public boolean hasWarning() { + return false; + } + + @Override + public boolean isEmpty() { + return reasons.isEmpty(); + } + } +} diff --git a/api/src/main/java/com/microsoft/gctoolkit/event/jvm/ApplicationStoppedTime.java b/api/src/main/java/com/microsoft/gctoolkit/event/jvm/ApplicationStoppedTime.java index 2176708f4..17998b5e4 100644 --- a/api/src/main/java/com/microsoft/gctoolkit/event/jvm/ApplicationStoppedTime.java +++ b/api/src/main/java/com/microsoft/gctoolkit/event/jvm/ApplicationStoppedTime.java @@ -6,14 +6,23 @@ public class ApplicationStoppedTime extends JVMEvent { - private static final double NO_TTSP = -1.0d; // negative times.. don't make sense + private static final double NOT_REPORTED = -1.0d; // negative times.. don't make sense + private static final int NO_THREAD_COUNT = -1; + + private static final double NO_TTSP = NOT_REPORTED; private final double timeToStopThreads; private final VMOperations safePointReason; private final boolean gcPause; + private double timeSinceLastSafepoint = NOT_REPORTED; + private double cleanupTime = NOT_REPORTED; + private double atSafepointTime = NOT_REPORTED; + private double leavingSafepointTime = NOT_REPORTED; + private int runnableThreads = NO_THREAD_COUNT; + private int totalThreads = NO_THREAD_COUNT; public ApplicationStoppedTime(DateTimeStamp timeStamp, double duration, double timeToStopThreads, VMOperations safePointReason) { - this(timeStamp, duration, timeToStopThreads, safePointReason, safePointReason.isCollection()); + this(timeStamp, duration, timeToStopThreads, safePointReason, safePointReason != null && safePointReason.isCollection()); } public ApplicationStoppedTime(DateTimeStamp timeStamp, double duration, boolean gcPause) { @@ -35,6 +44,27 @@ private ApplicationStoppedTime(DateTimeStamp timeStamp, double duration, this.gcPause = gcPause; } + /** + * Records the two phases that every safepoint line carries. + */ + public void recordPhases(double timeSinceLast, double atSafepoint) { + this.timeSinceLastSafepoint = timeSinceLast; + this.atSafepointTime = atSafepoint; + } + + public void recordCleanupTime(double cleanup) { + this.cleanupTime = cleanup; + } + + public void recordLeavingSafepointTime(double leavingSafepoint) { + this.leavingSafepointTime = leavingSafepoint; + } + + public void recordThreadCounts(int runnable, int total) { + this.runnableThreads = runnable; + this.totalThreads = total; + } + public double getTimeToStopThreads() { return this.timeToStopThreads; } @@ -53,10 +83,81 @@ public boolean isGCPause() { return this.gcPause; } + public double getTimeSinceLastSafepoint() { + return timeSinceLastSafepoint; + } + + public double getCleanupTime() { + return cleanupTime; + } + + public double getAtSafepointTime() { + return atSafepointTime; + } + + public double getLeavingSafepointTime() { + return leavingSafepointTime; + } + + public int getRunnableThreads() { + return runnableThreads; + } + + public int getTotalThreads() { + return totalThreads; + } + + public boolean hasTimeSinceLastSafepoint() { + return timeSinceLastSafepoint != NOT_REPORTED; + } + + public boolean hasCleanupTime() { + return cleanupTime != NOT_REPORTED; + } + + public boolean hasAtSafepointTime() { + return atSafepointTime != NOT_REPORTED; + } + + public boolean hasLeavingSafepointTime() { + return leavingSafepointTime != NOT_REPORTED; + } + + public boolean hasThreadCounts() { + return totalThreads != NO_THREAD_COUNT; + } + public enum VMOperations { - BulkRevokeBias(false), CGC_Operation(true), Cleanup(false), - Deoptimize(true), EnableBiasedLocking(false), Exit(false), - G1CollectForAllocation(true), RevokeBias(false); + BulkRevokeBias(false), CleanClassLoaderDataMetaspaces(false), CGC_Operation(true), + Cleanup(false), CollectForMetadataAllocation(true), Deoptimize(true), + EnableBiasedLocking(false), Exit(false), + G1CollectForAllocation(true), G1CollectFull(true), G1Concurrent(true), + G1TryInitiateConcMark(true), GenCollectForAllocation(true), GenCollectFull(true), + ICBufferFull(false), RevokeBias(false), SerialCollectForAllocation(true), + SerialGCCollect(true), + // The G1 concurrent cycle pauses, JDK 17 onwards + G1PauseCleanup(true), G1PauseRemark(true), + // Parallel. The first pair was renamed to the second between JDK 21 and JDK 25 + ParallelGCFailedAllocation(true), ParallelGCSystemGC(true), + ParallelCollectForAllocation(true), ParallelGCCollect(true), + // CMS, dropped after JDK 17 + GenCollectFullConcurrent(true), + // JDK 21 onwards + CollectForCodeCacheAllocation(true), + // Non generational ZGC + XMarkEnd(true), XMarkStart(true), XRelocateStart(true), + ZMarkEnd(true), ZMarkStart(true), ZRelocateStart(true), + // Generational ZGC + ZMarkEndOld(true), ZMarkEndYoung(true), ZMarkStartYoung(true), + ZMarkStartYoungAndOld(true), ZRelocateStartOld(true), ZRelocateStartYoung(true); + + public static VMOperations fromName(String name) { + try { + return valueOf(name); + } catch (IllegalArgumentException unknownOperation) { + return null; + } + } private final boolean collection; diff --git a/parser/src/main/java/com/microsoft/gctoolkit/parser/JVMPatterns.java b/parser/src/main/java/com/microsoft/gctoolkit/parser/JVMPatterns.java index be79e45a2..ad4323dc8 100644 --- a/parser/src/main/java/com/microsoft/gctoolkit/parser/JVMPatterns.java +++ b/parser/src/main/java/com/microsoft/gctoolkit/parser/JVMPatterns.java @@ -13,7 +13,10 @@ public interface JVMPatterns extends PreUnifiedTokens { //Total time for which application threads were stopped: 0.0006115 seconds, Stopping threads took: 0.0003832 seconds GCParseRule UNIFIED_LOGGING_APPLICATION_STOP_TIME_WITH_STOPPING_TIME = new GCParseRule("Unified Logging App stop time", "Total time for which application threads were stopped: " + TIME + " seconds, Stopping threads took: " + TIME + " seconds"); //[1.361s][info ][safepoint ] Safepoint "G1CollectForAllocation", Time since last: 295590960 ns, Reaching safepoint: 238882 ns, At safepoint: 23888872 ns, Total: 24127754 ns - GCParseRule UNIFIED_LOGGING_G1_SAFEPOINT = new GCParseRule("", "Safepoint " + SAFE_POINT_CAUSE + ", Time since last: (" + INTEGER + ") ns, Reaching safepoint: (" + INTEGER + ") ns, At safepoint: (" + INTEGER + ") ns, Total: (" + INTEGER + ") ns"); + //[2.803s][info][safepoint] Safepoint "ZMarkStartYoungAndOld", Time since last: 1367178708 ns, Reaching safepoint: 91483 ns, At safepoint: 33824 ns, Leaving safepoint: 38612 ns, Total: 163919 ns, Threads: 3 runnable, 23 total + GCParseRule UNIFIED_LOGGING_SAFEPOINT = new GCParseRule("Unified Logging Safepoint", "Safepoint " + SAFE_POINT_CAUSE + ", Time since last: (" + INTEGER + ") ns" + + ", Reaching safepoint: (" + INTEGER + ") ns" + ", (?:Cleanup: (" + INTEGER + ") ns, )?" + "At safepoint: (" + INTEGER + ") ns" + + ", (?:Leaving safepoint: (" + INTEGER + ") ns, )?" + "Total: (" + INTEGER + ") ns" + "(?:, Threads: (" + INTEGER + ") runnable, (" + INTEGER + ") total)?"); GCParseRule SIMPLE_APPLICATION_TIME = new GCParseRule("SIMPLE_APPLICATION_TIME", "Application time: " + TIME + " seconds"); GCParseRule APPLICATION_TIME = new GCParseRule("APPLICATION_TIME", DATE_TIMESTAMP + "Application time: " + TIME + " seconds"); diff --git a/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedJVMEventParser.java b/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedJVMEventParser.java index 26f3e759c..1eff938e8 100644 --- a/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedJVMEventParser.java +++ b/parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedJVMEventParser.java @@ -21,6 +21,18 @@ public class UnifiedJVMEventParser extends UnifiedGCLogParser implements JVMPatterns { private static final Logger LOGGER = Logger.getLogger(UnifiedJVMEventParser.class.getName()); + private static final double NANOS_PER_SECOND = 1_000_000_000.0d; + + private static final int VM_OPERATION_GROUP = 1; + private static final int TIME_SINCE_LAST_GROUP = 2; + private static final int REACHING_SAFEPOINT_GROUP = 3; + private static final int CLEANUP_GROUP = 4; + private static final int AT_SAFEPOINT_GROUP = 5; + private static final int LEAVING_SAFEPOINT_GROUP = 6; + private static final int TOTAL_GROUP = 7; + private static final int RUNNABLE_THREADS_GROUP = 8; + private static final int TOTAL_THREADS_GROUP = 9; + private DateTimeStamp timeStamp = new DateTimeStamp(0.0d); private ApplicationStoppedTime.VMOperations safePointReason = null; private boolean gcPause = false; @@ -29,7 +41,7 @@ public UnifiedJVMEventParser() {} @Override public Set eventsProduced() { - return Set.of(EventSource.JVM); + return Set.of(EventSource.JVM, EventSource.SAFEPOINT); } public String getName() { @@ -43,7 +55,22 @@ protected void process(String line) { try { - if ((trace = UNIFIED_LOGGING_APPLICATION_STOP_TIME_WITH_STOPPING_TIME.parse(line)) != null) { + if ((trace = UNIFIED_LOGGING_SAFEPOINT.parse(line)) != null) { + double total = nanosToSeconds(trace, TOTAL_GROUP); + ApplicationStoppedTime safepoint = new ApplicationStoppedTime(getClock().minus(total), total, + nanosToSeconds(trace, REACHING_SAFEPOINT_GROUP), + ApplicationStoppedTime.VMOperations.fromName(trace.getGroup(VM_OPERATION_GROUP))); + safepoint.recordPhases(nanosToSeconds(trace, TIME_SINCE_LAST_GROUP), nanosToSeconds(trace, AT_SAFEPOINT_GROUP)); + if (trace.groupNotNull(CLEANUP_GROUP)) + safepoint.recordCleanupTime(nanosToSeconds(trace, CLEANUP_GROUP)); + if (trace.groupNotNull(LEAVING_SAFEPOINT_GROUP)) + safepoint.recordLeavingSafepointTime(nanosToSeconds(trace, LEAVING_SAFEPOINT_GROUP)); + if (trace.groupNotNull(RUNNABLE_THREADS_GROUP)) + safepoint.recordThreadCounts(trace.getIntegerGroup(RUNNABLE_THREADS_GROUP), trace.getIntegerGroup(TOTAL_THREADS_GROUP)); + publish(safepoint); + safePointReason = null; + gcPause = false; + } else if ((trace = UNIFIED_LOGGING_APPLICATION_STOP_TIME_WITH_STOPPING_TIME.parse(line)) != null) { if (safePointReason != null) publish(new ApplicationStoppedTime(timeStamp, trace.getDoubleGroup(1), trace.getDoubleGroup(2), safePointReason)); else @@ -54,7 +81,7 @@ protected void process(String line) { gcPause = true; } else if ((trace = SAFEPOINT_REGION.parse(line)) != null) { timeStamp = getClock(); - safePointReason = ApplicationStoppedTime.VMOperations.valueOf(trace.getGroup(1)); + safePointReason = ApplicationStoppedTime.VMOperations.fromName(trace.getGroup(1)); } else if ((trace = LEAVING_SAFEPOINT.parse(line)) != null) { } //noop this one. @@ -72,6 +99,13 @@ else if ((trace = UNIFIED_LOGGING_APPLICATION_TIME.parse(line)) != null) { } } + /** + * Converts values in nanoseconds to seconds + */ + private static double nanosToSeconds(GCLogTrace trace, int group) { + return trace.getLongGroup(group) / NANOS_PER_SECOND; + } + private boolean isGCPause(String line) { return ((line.contains(" Pause Initial Mark")) || (line.contains(" Remark ")) || diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedSafepointParserTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedSafepointParserTest.java new file mode 100644 index 000000000..1160c22c3 --- /dev/null +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/UnifiedSafepointParserTest.java @@ -0,0 +1,282 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. +package com.microsoft.gctoolkit.parser; + +import com.microsoft.gctoolkit.event.jvm.ApplicationStoppedTime; +import com.microsoft.gctoolkit.event.jvm.JVMEvent; +import com.microsoft.gctoolkit.jvm.Diarizer; +import com.microsoft.gctoolkit.parser.jvm.UnifiedDiarizer; +import org.junit.jupiter.api.Test; + +import java.util.List; +import java.util.stream.Collectors; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** + * JDK 14 consolidated safepoint logging onto a single line (JDK-8221507). These tests cover that + * form, which is what every collector emits under -Xlog:safepoint on JDK 14 and later. + */ +public class UnifiedSafepointParserTest extends ParserTest { + + @Override + protected Diarizer diarizer() { + return new UnifiedDiarizer(); + } + + @Override + protected GCLogParser parser() { + return new UnifiedJVMEventParser(); + } + + private ApplicationStoppedTime parseSingleSafepoint(String line) { + List events = feedParser(new String[]{line}); + List stops = events.stream() + .filter(ApplicationStoppedTime.class::isInstance) + .map(ApplicationStoppedTime.class::cast) + .collect(Collectors.toList()); + assertEquals(1, stops.size(), "expected exactly one ApplicationStoppedTime from: " + line); + return stops.get(0); + } + + @Test + public void testG1Safepoint() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[1.361s][info][safepoint ] Safepoint \"G1CollectForAllocation\", Time since last: 295590960 ns, Reaching safepoint: 238882 ns, At safepoint: 23888872 ns, Total: 24127754 ns"); + + assertDoubleEquals(0.024127754d, stop.getDuration()); + assertDoubleEquals(0.000238882d, stop.getTimeToStopThreads()); + assertTrue(stop.hasTTSP()); + assertEquals(ApplicationStoppedTime.VMOperations.G1CollectForAllocation, stop.getSafePointReason()); + assertTrue(stop.isGCPause()); + // The line is written when the safepoint ends, so the event starts total seconds earlier. + // DateTimeStamp rounds to milliseconds, so 1.361 - 0.024127754 lands on 1.337. + assertDoubleEquals(1.337d, stop.getDateTimeStamp().getTimeStamp()); + + assertDoubleEquals(0.295590960d, stop.getTimeSinceLastSafepoint()); + assertDoubleEquals(0.023888872d, stop.getAtSafepointTime()); + // JDK 14 - 17 report neither of these + assertFalse(stop.hasCleanupTime()); + assertFalse(stop.hasLeavingSafepointTime()); + assertFalse(stop.hasThreadCounts()); + } + + @Test + public void testSerialSafepoint() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[0.773s][info][safepoint ] Safepoint \"SerialGCCollect\", Time since last: 477036488 ns, Reaching safepoint: 34173 ns, At safepoint: 130196669 ns, Total: 130230842 ns"); + + assertDoubleEquals(0.130230842d, stop.getDuration()); + assertDoubleEquals(0.000034173d, stop.getTimeToStopThreads()); + assertEquals(ApplicationStoppedTime.VMOperations.SerialGCCollect, stop.getSafePointReason()); + assertTrue(stop.isGCPause()); + } + + @Test + public void testZGCSafepoint() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[3.114s][info][safepoint ] Safepoint \"ZMarkStart\", Time since last: 1050386 ns, Reaching safepoint: 197300 ns, At safepoint: 1248300 ns, Total: 1445600 ns"); + + assertDoubleEquals(0.0014456d, stop.getDuration()); + assertDoubleEquals(0.0001973d, stop.getTimeToStopThreads()); + assertEquals(ApplicationStoppedTime.VMOperations.ZMarkStart, stop.getSafePointReason()); + assertTrue(stop.isGCPause()); + } + + /** + * JDK 21 reports a Cleanup phase between "Reaching safepoint" and "At safepoint". + */ + @Test + public void testSafepointWithCleanupPhase() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[1.136s][info][safepoint ] Safepoint \"XMarkStart\", Time since last: 190106589 ns, Reaching safepoint: 120017 ns, Cleanup: 62407 ns, At safepoint: 121268 ns, Total: 303692 ns"); + + assertDoubleEquals(0.000303692d, stop.getDuration()); + assertDoubleEquals(0.000120017d, stop.getTimeToStopThreads()); + assertEquals(ApplicationStoppedTime.VMOperations.XMarkStart, stop.getSafePointReason()); + assertTrue(stop.isGCPause()); + + assertDoubleEquals(0.190106589d, stop.getTimeSinceLastSafepoint()); + assertDoubleEquals(0.000062407d, stop.getCleanupTime()); + assertDoubleEquals(0.000121268d, stop.getAtSafepointTime()); + assertFalse(stop.hasLeavingSafepointTime()); + } + + /** + * Later JDK 21 builds add a "Leaving safepoint" phase as well. + */ + @Test + public void testSafepointWithCleanupAndLeavingPhases() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[0.557s][info][safepoint] Safepoint \"ICBufferFull\", Time since last: 328272185 ns, Reaching safepoint: 4929 ns, Cleanup: 156005 ns, At safepoint: 852 ns, Leaving safepoint: 811 ns, Total: 162597 ns"); + + assertDoubleEquals(0.000162597d, stop.getDuration()); + assertDoubleEquals(0.000004929d, stop.getTimeToStopThreads()); + assertEquals(ApplicationStoppedTime.VMOperations.ICBufferFull, stop.getSafePointReason()); + assertFalse(stop.isGCPause()); + + assertDoubleEquals(0.328272185d, stop.getTimeSinceLastSafepoint()); + assertDoubleEquals(0.000156005d, stop.getCleanupTime()); + assertDoubleEquals(0.000000852d, stop.getAtSafepointTime()); + assertDoubleEquals(0.000000811d, stop.getLeavingSafepointTime()); + assertFalse(stop.hasThreadCounts()); + } + + /** + * JDK 25 drops Cleanup, keeps Leaving safepoint, and appends a thread count after Total. + */ + @Test + public void testGenerationalZGCSafepointWithTrailingThreadCounts() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[2.803s][info][safepoint] Safepoint \"ZMarkStartYoungAndOld\", Time since last: 1367178708 ns, Reaching safepoint: 91483 ns, At safepoint: 33824 ns, Leaving safepoint: 38612 ns, Total: 163919 ns, Threads: 3 runnable, 23 total"); + + assertDoubleEquals(0.000163919d, stop.getDuration()); + assertDoubleEquals(0.000091483d, stop.getTimeToStopThreads()); + assertEquals(ApplicationStoppedTime.VMOperations.ZMarkStartYoungAndOld, stop.getSafePointReason()); + assertTrue(stop.isGCPause()); + + assertDoubleEquals(1.367178708d, stop.getTimeSinceLastSafepoint()); + assertFalse(stop.hasCleanupTime()); + assertDoubleEquals(0.000033824d, stop.getAtSafepointTime()); + assertDoubleEquals(0.000038612d, stop.getLeavingSafepointTime()); + assertTrue(stop.hasThreadCounts()); + assertEquals(3, stop.getRunnableThreads()); + assertEquals(23, stop.getTotalThreads()); + } + + /** + * HotSpot writes the phases such that they account for the whole safepoint. Verified against + * every safepoint line in the logs under gclogs, so it is a cheap check that the capture groups + * are aligned with the fields they are named for. + */ + @Test + public void testPhasesSumToTotal() { + List events = feedParser(new String[]{ + "[0.557s][info][safepoint] Safepoint \"ICBufferFull\", Time since last: 328272185 ns, Reaching safepoint: 4929 ns, Cleanup: 156005 ns, At safepoint: 852 ns, Leaving safepoint: 811 ns, Total: 162597 ns", + "[1.136s][info][safepoint] Safepoint \"XMarkStart\", Time since last: 190106589 ns, Reaching safepoint: 120017 ns, Cleanup: 62407 ns, At safepoint: 121268 ns, Total: 303692 ns", + "[1.361s][info][safepoint] Safepoint \"G1CollectForAllocation\", Time since last: 295590960 ns, Reaching safepoint: 238882 ns, At safepoint: 23888872 ns, Total: 24127754 ns", + "[2.803s][info][safepoint] Safepoint \"ZMarkStartYoungAndOld\", Time since last: 1367178708 ns, Reaching safepoint: 91483 ns, At safepoint: 33824 ns, Leaving safepoint: 38612 ns, Total: 163919 ns, Threads: 3 runnable, 23 total" + }); + + List stops = events.stream() + .filter(ApplicationStoppedTime.class::isInstance) + .map(ApplicationStoppedTime.class::cast) + .collect(Collectors.toList()); + assertEquals(4, stops.size()); + + for (ApplicationStoppedTime stop : stops) { + double sum = stop.getTimeToStopThreads() + stop.getAtSafepointTime() + + (stop.hasCleanupTime() ? stop.getCleanupTime() : 0.0d) + + (stop.hasLeavingSafepointTime() ? stop.getLeavingSafepointTime() : 0.0d); + assertEquals(stop.getDuration(), sum, 1.0e-9d, + "phases should account for the total for " + stop.getSafePointReason()); + } + } + + /** + * Time since last exceeds Integer.MAX_VALUE nanoseconds, so the values must be read as longs. + */ + @Test + public void testLargeNanosecondValues() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[20.947s][info][safepoint ] Safepoint \"SerialCollectForAllocation\", Time since last: 19109967274 ns, Reaching safepoint: 38663 ns, At safepoint: 264693508 ns, Total: 264732171 ns"); + + assertDoubleEquals(0.264732171d, stop.getDuration()); + assertDoubleEquals(0.000038663d, stop.getTimeToStopThreads()); + } + + /** + * HotSpot adds and removes VM operations every release, so an unknown name must still yield an + * event carrying the timings. Only the reason is lost. + */ + @Test + public void testUnknownVMOperationStillPublishesTimings() { + ApplicationStoppedTime stop = parseSingleSafepoint( + "[1.234s][info][safepoint] Safepoint \"SomeFutureVMOperation\", Time since last: 1000000 ns, Reaching safepoint: 5000 ns, At safepoint: 20000 ns, Total: 25000 ns"); + + assertDoubleEquals(0.000025d, stop.getDuration()); + assertDoubleEquals(0.000005d, stop.getTimeToStopThreads()); + assertNull(stop.getSafePointReason()); + assertFalse(stop.isGCPause()); + } + + /** + * Parallel and the JDK 21 G1 remark and cleanup pauses are collections, so they must be + * attributed to a GC rather than counted as an unrelated stop. + */ + @Test + public void testCollectionOperationsAreAttributedToAGC() { + String[] operations = {"ParallelGCFailedAllocation", "ParallelGCSystemGC", + "ParallelCollectForAllocation", "ParallelGCCollect", "G1PauseRemark", "G1PauseCleanup", + "CollectForMetadataAllocation"}; + + String[] lines = new String[operations.length]; + for (int i = 0; i < operations.length; i++) + lines[i] = "[1.234s][info][safepoint] Safepoint \"" + operations[i] + + "\", Time since last: 1000000 ns, Reaching safepoint: 5000 ns, At safepoint: 20000 ns, Total: 25000 ns"; + + List stops = feedParser(lines).stream() + .filter(ApplicationStoppedTime.class::isInstance) + .map(ApplicationStoppedTime.class::cast) + .collect(Collectors.toList()); + assertEquals(operations.length, stops.size()); + + for (int i = 0; i < operations.length; i++) { + assertEquals(ApplicationStoppedTime.VMOperations.valueOf(operations[i]), stops.get(i).getSafePointReason()); + assertTrue(stops.get(i).isGCPause(), operations[i] + " should be attributed to a collection"); + } + } + + /** + * The JDK 9 - 13 form must keep working. + */ + @Test + public void testLegacySafepointRegionStillParses() { + List events = feedParser(new String[]{ + "[0.648s][info][safepoint ] Entering safepoint region: RevokeBias", + "[0.648s][info][safepoint ] Leaving safepoint region", + "[0.648s][info][safepoint ] Total time for which application threads were stopped: 0.0006115 seconds, Stopping threads took: 0.0003832 seconds" + }); + + ApplicationStoppedTime stop = events.stream() + .filter(ApplicationStoppedTime.class::isInstance) + .map(ApplicationStoppedTime.class::cast) + .findFirst() + .orElse(null); + + assertNotNull(stop); + assertDoubleEquals(0.0006115d, stop.getDuration()); + assertDoubleEquals(0.0003832d, stop.getTimeToStopThreads()); + assertEquals(ApplicationStoppedTime.VMOperations.RevokeBias, stop.getSafePointReason()); + // The JDK 9 - 13 form carries no phase breakdown + assertFalse(stop.hasAtSafepointTime()); + assertFalse(stop.hasTimeSinceLastSafepoint()); + } + + /** + * An unrecognised operation must not cost us the timings on the JDK 9 - 13 form either. + */ + @Test + public void testLegacyUnknownVMOperationStillPublishesTimings() { + List events = feedParser(new String[]{ + "[0.648s][info][safepoint ] Entering safepoint region: SomeFutureVMOperation", + "[0.648s][info][safepoint ] Leaving safepoint region", + "[0.648s][info][safepoint ] Total time for which application threads were stopped: 0.0006115 seconds, Stopping threads took: 0.0003832 seconds" + }); + + ApplicationStoppedTime stop = events.stream() + .filter(ApplicationStoppedTime.class::isInstance) + .map(ApplicationStoppedTime.class::cast) + .findFirst() + .orElse(null); + + assertNotNull(stop); + assertDoubleEquals(0.0006115d, stop.getDuration()); + assertDoubleEquals(0.0003832d, stop.getTimeToStopThreads()); + assertNull(stop.getSafePointReason()); + } +} diff --git a/parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/JVMPatternsTest.java b/parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/JVMPatternsTest.java index a3f9fb95e..7184f5d89 100644 --- a/parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/JVMPatternsTest.java +++ b/parser/src/test/java/com/microsoft/gctoolkit/parser/patterns/JVMPatternsTest.java @@ -32,8 +32,8 @@ public void testEuropeanFormatedApplicationTime() { string = "Total time for which application threads were stopped: 0.0006115 seconds, Stopping threads took: 0.0003832 seconds"; assertNotNull(UNIFIED_LOGGING_APPLICATION_STOP_TIME_WITH_STOPPING_TIME.parse(string)); - string = "Safepoint \"G1CollectForAllocation\", Time since last: 295590960 ns, Reaching safepoint: 238882 ns, At safepoint: 23888872 ns, Total: 24127754 ns)"; - assertNotNull(UNIFIED_LOGGING_G1_SAFEPOINT.parse(string)); + string = "Safepoint \"G1CollectForAllocation\", Time since last: 295590960 ns, Reaching safepoint: 238882 ns, At safepoint: 23888872 ns, Total: 24127754 ns"; + assertNotNull(UNIFIED_LOGGING_SAFEPOINT.parse(string)); } }