Record and report safepoint information from logs

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<SafepointSummary> {
+
+        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<ApplicationStoppedTime.VMOperations> 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<ApplicationStoppedTime.VMOperations> reasons() {
+            return reasons;
+        }
+
+        public double totalTimeToSafepoint() {
+            return totalTimeToSafepoint;
+        }
+
+        @Override
+        public boolean hasWarning() {
+            return false;
+        }
+
+        @Override
+        public boolean isEmpty() {
+            return reasons.isEmpty();
+        }
+    }
+}

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 @@
         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 @@
         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;
 

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");

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 @@
 
     @Override
     public Set<EventSource> eventsProduced() {
-        return Set.of(EventSource.JVM);
+        return Set.of(EventSource.JVM, EventSource.SAFEPOINT);
     }
 
     public String getName() {
@@ -37,13 +49,28 @@
     }
 
     @Override
     protected void process(String line) {
 
         GCLogTrace trace = null;
 
         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 @@
                 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 @@
         }
     }
 
+    /**
+     * 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 ")) ||