8196341: Add JFR events for parallel phases of G1

Reviewed-by: tschatzl, sangheki

src/hotspot/share/gc/g1/g1CollectedHeap.cpp

@@ -3169,18 +3169,24 @@ void G1CollectedHeap::preserve_mark_during_evac_failure(uint worker_id, oop obj,
 }
 
 bool G1ParEvacuateFollowersClosure::offer_termination() {
+  EventGCPhaseParallel event;
   G1ParScanThreadState* const pss = par_scan_state();
   start_term_time();
   const bool res = terminator()->offer_termination();
   end_term_time();
+  event.commit(GCId::current(), pss->worker_id(), G1GCPhaseTimes::phase_name(G1GCPhaseTimes::Termination));
   return res;
 }
 
 void G1ParEvacuateFollowersClosure::do_void() {
+  EventGCPhaseParallel event;
   G1ParScanThreadState* const pss = par_scan_state();
   pss->trim_queue();
+  event.commit(GCId::current(), pss->worker_id(), G1GCPhaseTimes::phase_name(G1GCPhaseTimes::ObjCopy));
   do {
+    EventGCPhaseParallel event;
     pss->steal_and_trim_queue(queues());
+    event.commit(GCId::current(), pss->worker_id(), G1GCPhaseTimes::phase_name(G1GCPhaseTimes::ObjCopy));
   } while (!offer_termination());
 }
 
@@ -4050,6 +4056,7 @@ public:
         break;
       }
 
+      EventGCPhaseParallel event;
       double start_time = os::elapsedTime();
 
       end = MIN2(end, _num_work_items);
@@ -4064,9 +4071,11 @@ public:
         if (is_young) {
           young_time += time_taken;
           has_young_time = true;
+          event.commit(GCId::current(), worker_id, G1GCPhaseTimes::phase_name(G1GCPhaseTimes::YoungFreeCSet));
         } else {
           non_young_time += time_taken;
           has_non_young_time = true;
+          event.commit(GCId::current(), worker_id, G1GCPhaseTimes::phase_name(G1GCPhaseTimes::NonYoungFreeCSet));
         }
         start_time = end_time;
       }

src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp

@@ -465,6 +465,48 @@ void G1GCPhaseTimes::print() {
   }
 }
 
+const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
+  static const char* names[] = {
+      "GCWorkerStart",
+      "ExtRootScan",
+      "ThreadRoots",
+      "StringTableRoots",
+      "UniverseRoots",
+      "JNIRoots",
+      "ObjectSynchronizerRoots",
+      "ManagementRoots",
+      "SystemDictionaryRoots",
+      "CLDGRoots",
+      "JVMTIRoots",
+      "CMRefRoots",
+      "WaitForStrongCLD",
+      "WeakCLDRoots",
+      "SATBFiltering",
+      "UpdateRS",
+      "ScanHCC",
+      "ScanRS",
+      "CodeRoots",
+#if INCLUDE_AOT
+      "AOTCodeRoots",
+#endif
+      "ObjCopy",
+      "Termination",
+      "Other",
+      "GCWorkerTotal",
+      "GCWorkerEnd",
+      "StringDedupQueueFixup",
+      "StringDedupTableFixup",
+      "RedirtyCards",
+      "YoungFreeCSet",
+      "NonYoungFreeCSet"
+      //GCParPhasesSentinel only used to tell end of enum
+      };
+
+  STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
+
+  return names[phase];
+}
+
 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
   _pss(pss),
   _start(Ticks::now()),
@@ -490,7 +532,7 @@ void G1EvacPhaseWithTrimTimeTracker::stop() {
 }
 
 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
-  _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id) {
+  _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() {
   if (_phase_times != NULL) {
     _start_time = Ticks::now();
   }
@@ -499,6 +541,7 @@ G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
   if (_phase_times != NULL) {
     _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
+    _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
   }
 }
 

src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp

@@ -27,6 +27,7 @@
 
 #include "gc/shared/referenceProcessorPhaseTimes.hpp"
 #include "gc/shared/weakProcessorPhaseTimes.hpp"
+#include "jfr/jfrEvents.hpp"
 #include "logging/logLevel.hpp"
 #include "memory/allocation.hpp"
 #include "utilities/macros.hpp"
@@ -190,6 +191,7 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads);
   void note_gc_start();
   void print();
+  static const char* phase_name(GCParPhases phase);
 
   // record the time a phase took in seconds
   void record_time_secs(GCParPhases phase, uint worker_i, double secs);
@@ -385,6 +387,7 @@ protected:
   G1GCPhaseTimes::GCParPhases _phase;
   G1GCPhaseTimes* _phase_times;
   uint _worker_id;
+  EventGCPhaseParallel _event;
 public:
   G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id);
   virtual ~G1GCParPhaseTimesTracker();

src/hotspot/share/gc/g1/g1RemSet.cpp

@@ -40,6 +40,7 @@
 #include "gc/g1/heapRegionRemSet.hpp"
 #include "gc/shared/gcTraceTime.inline.hpp"
 #include "gc/shared/suspendibleThreadSet.hpp"
+#include "jfr/jfrEvents.hpp"
 #include "memory/iterator.hpp"
 #include "memory/resourceArea.hpp"
 #include "oops/access.inline.hpp"
@@ -339,6 +340,7 @@ void G1ScanRSForRegionClosure::scan_card(MemRegion mr, uint region_idx_for_card)
 }
 
 void G1ScanRSForRegionClosure::scan_rem_set_roots(HeapRegion* r) {
+  EventGCPhaseParallel event;
   uint const region_idx = r->hrm_index();
 
   if (_scan_state->claim_iter(region_idx)) {
@@ -392,10 +394,13 @@ void G1ScanRSForRegionClosure::scan_rem_set_roots(HeapRegion* r) {
 
     scan_card(mr, region_idx_for_card);
   }
+  event.commit(GCId::current(), _worker_i, G1GCPhaseTimes::phase_name(G1GCPhaseTimes::ScanRS));
 }
 
 void G1ScanRSForRegionClosure::scan_strong_code_roots(HeapRegion* r) {
+  EventGCPhaseParallel event;
   r->strong_code_roots_do(_pss->closures()->weak_codeblobs());
+  event.commit(GCId::current(), _worker_i, G1GCPhaseTimes::phase_name(G1GCPhaseTimes::CodeRoots));
 }
 
 bool G1ScanRSForRegionClosure::do_heap_region(HeapRegion* r) {

src/hotspot/share/jfr/metadata/metadata.xml

@@ -435,6 +435,13 @@
     <Field type="string" name="name" label="Name" />
   </Event>
 
+  <Event name="GCPhaseParallel" category="Java Virtual Machine, GC, Phases" label="GC Phase Parallel"
+         startTime="true" thread="true" description="GC phases for parallel workers">
+    <Field type="uint" name="gcId" label="GC Identifier" relation="GcId"/>
+    <Field type="uint" name="gcWorkerId" label="GC Worker Identifier" />
+    <Field type="string" name="name" label="Name" />
+  </Event>
+  
   <Event name="AllocationRequiringGC" category="Java Virtual Machine, GC, Detailed" label="Allocation Requiring GC" thread="true" stackTrace="true"
     startTime="false">
     <Field type="uint" name="gcId" label="Pending GC Identifier" relation="GcId" />

src/jdk.jfr/share/conf/jfr/default.jfc

@@ -382,6 +382,11 @@
       <setting name="enabled" control="gc-enabled-normal">true</setting>
     </event>
 
+    <event name="jdk.GCPhaseParallel">
+      <setting name="enabled" control="gc-enabled-normal">true</setting>
+      <setting name="threshold">0 ms</setting>
+    </event>
+ 
     <event name="jdk.G1BasicIHOP">
       <setting name="enabled" control="gc-enabled-normal">true</setting>
     </event>

src/jdk.jfr/share/conf/jfr/profile.jfc

@@ -382,6 +382,11 @@
       <setting name="enabled" control="gc-enabled-normal">true</setting>
     </event>
 
+    <event name="jdk.GCPhaseParallel">
+      <setting name="enabled" control="gc-enabled-normal">true</setting>
+      <setting name="threshold">0 ms</setting>
+    </event>
+    
     <event name="jdk.G1BasicIHOP">
       <setting name="enabled" control="gc-enabled-normal">true</setting>
     </event>

test/jdk/TEST.groups

@@ -504,6 +504,7 @@ needs_g1gc = \
   jdk/jfr/event/gc/collection/TestYoungGarbageCollectionEventWithG1New.java \
   jdk/jfr/event/gc/collection/TestGCEventMixedWithG1FullCollection.java \
   jdk/jfr/event/gc/collection/TestGCEventMixedWithG1ConcurrentMark.java \
+  jdk/jfr/event/gc/collection/TestG1ParallelPhases.java \
   jdk/jfr/event/gc/objectcount/TestObjectCountAfterGCEventWithG1FullCollection.java \
   jdk/jfr/event/gc/objectcount/TestObjectCountAfterGCEventWithG1ConcurrentMark.java \
   jdk/jfr/event/gc/heapsummary/TestHeapSummaryEventG1.java

test/jdk/jdk/jfr/event/gc/collection/TestG1ParallelPhases.java

@@ -0,0 +1,183 @@
+/*
+ * Copyright (c) 2018, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.  Oracle designates this
+ * particular file as subject to the "Classpath" exception as provided
+ * by Oracle in the LICENSE file that accompanied this code.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+package jdk.jfr.event.gc.collection;
+
+import static java.lang.System.gc;
+import static java.lang.Thread.sleep;
+import static java.util.Set.of;
+import static java.util.stream.Collectors.joining;
+import static java.util.stream.Collectors.toList;
+import static java.util.stream.Collectors.toSet;
+import static java.util.stream.IntStream.range;
+import static jdk.jfr.event.gc.collection.Provoker.provokeMixedGC;
+import static jdk.test.lib.Asserts.assertEquals;
+import static jdk.test.lib.Asserts.assertTrue;
+import static jdk.test.lib.jfr.Events.fromRecording;
+import static sun.hotspot.WhiteBox.getWhiteBox;
+
+import java.io.IOException;
+import java.lang.ref.WeakReference;
+import java.math.BigDecimal;
+import java.util.ArrayList;
+import java.util.Collection;
+import java.util.List;
+import java.util.Set;
+
+import jdk.jfr.Recording;
+import jdk.test.lib.Asserts;
+import jdk.test.lib.jfr.EventNames;
+import sun.hotspot.WhiteBox;
+
+/**
+ * @test
+ * @key jfr
+ * @requires vm.hasJFR
+ * @requires vm.gc == "G1" | vm.gc == null
+ * @library /test/lib /test/jdk
+ * @build sun.hotspot.WhiteBox
+ * @run main ClassFileInstaller sun.hotspot.WhiteBox
+ * @run main/othervm -XX:+UnlockExperimentalVMOptions -XX:MaxTenuringThreshold=1 -Xms20M -Xmx20M
+ *      -XX:G1MixedGCLiveThresholdPercent=100 -XX:G1HeapWastePercent=0 -XX:G1HeapRegionSize=1m
+ *      -XX:+UseG1GC -XX:+UseStringDeduplication
+ *      -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI
+ *      jdk.jfr.event.gc.collection.TestG1ParallelPhases
+ */
+
+public class TestG1ParallelPhases {
+    public static List<WeakReference<byte[]>> weakRefs;
+
+    public static void main(String[] args) throws IOException {
+        Recording recording = new Recording();
+        recording.enable(EventNames.GCPhaseParallel);
+        recording.start();
+
+        // create more weak garbage than can fit in this heap (-Xmx20m), will force collection of weak references
+        weakRefs = range(1, 100)
+            .mapToObj(n -> new WeakReference<>(new byte[1_000_000]))
+            .collect(toList()); // force evaluation of lazy stream (all weak refs must be created)
+
+        final var MEG = 1024 * 1024;
+        provokeMixedGC(1 * MEG);
+        recording.stop();
+
+        Set<String> usedPhases = fromRecording(recording).stream()
+            .map(e -> e.getValue("name").toString())
+            .collect(toSet());
+
+        Set<String> allPhases = of(
+            "ExtRootScan",
+            "ThreadRoots",
+            "StringTableRoots",
+            "UniverseRoots",
+            "JNIRoots",
+            "ObjectSynchronizerRoots",
+            "ManagementRoots",
+            "SystemDictionaryRoots",
+            "CLDGRoots",
+            "JVMTIRoots",
+            "CMRefRoots",
+            "WaitForStrongCLD",
+            "WeakCLDRoots",
+            "SATBFiltering",
+            "UpdateRS",
+            "ScanHCC",
+            "ScanRS",
+            "CodeRoots",
+            "ObjCopy",
+            "Termination",
+            "StringDedupQueueFixup",
+            "StringDedupTableFixup",
+            "RedirtyCards",
+       //     "PreserveCMReferents",
+            "NonYoungFreeCSet",
+            "YoungFreeCSet"
+        );
+
+        assertTrue(usedPhases.equals(allPhases), "Compare events expected and received"
+            + ", Not found phases: " + allPhases.stream().filter(p -> !usedPhases.contains(p)).collect(joining(", "))
+            + ", Not expected phases: " + usedPhases.stream().filter(p -> !allPhases.contains(p)).collect(joining(", ")));
+    }
+}
+
+/**
+ * Utility class to guarantee a mixed GC. The class allocates several arrays and
+ * promotes them to the oldgen. After that it tries to provoke mixed GC by
+ * allocating new objects.
+ */
+class Provoker {
+    private static void allocateOldObjects(
+            List<byte[]> liveOldObjects,
+            int g1HeapRegionSize,
+            int arraySize) {
+
+        var toUnreachable = new ArrayList<byte[]>();
+
+        // Allocates buffer and promotes it to the old gen. Mix live and dead old objects.
+        // allocate about two regions of old memory. At least one full old region will guarantee
+        // mixed collection in the future
+        range(0, g1HeapRegionSize/arraySize).forEach(n -> {
+            liveOldObjects.add(new byte[arraySize]);
+            toUnreachable.add(new byte[arraySize]);
+        });
+
+        // Do two young collections, MaxTenuringThreshold=1 will force promotion.
+        getWhiteBox().youngGC();
+        getWhiteBox().youngGC();
+
+        // Check it is promoted & keep alive
+        Asserts.assertTrue(getWhiteBox().isObjectInOldGen(liveOldObjects), "List of the objects is suppose to be in OldGen");
+        Asserts.assertTrue(getWhiteBox().isObjectInOldGen(toUnreachable), "List of the objects is suppose to be in OldGen");
+    }
+
+    private static void waitTillCMCFinished(int sleepTime) {
+        while (getWhiteBox().g1InConcurrentMark()) {
+              try {sleep(sleepTime);} catch (Exception e) {}
+        }
+    }
+
+    /**
+    * The necessary condition for guaranteed mixed GC is running in VM with the following flags:
+    * -XX:+UnlockExperimentalVMOptions -XX:MaxTenuringThreshold=1 -Xms{HEAP_SIZE}M
+    * -Xmx{HEAP_SIZE}M -XX:G1MixedGCLiveThresholdPercent=100 -XX:G1HeapWastePercent=0
+    * -XX:G1HeapRegionSize={REGION_SIZE}m
+    *
+    * @param provokeSize The size to allocate to provoke the start of a mixed gc (half heap size?)
+    * @param g1HeapRegionSize The size of your regions in bytes
+    */
+    public static void provokeMixedGC(int g1HeapRegionSize) {
+        final var arraySize = 20_000;
+        var liveOldObjects = new ArrayList<byte[]>();
+        allocateOldObjects(liveOldObjects, g1HeapRegionSize, arraySize);
+        waitTillCMCFinished(10);
+        getWhiteBox().g1StartConcMarkCycle();
+        waitTillCMCFinished(10);
+        getWhiteBox().youngGC();
+        getWhiteBox().youngGC();
+
+        // check that liveOldObjects still alive
+        assertTrue(getWhiteBox().isObjectInOldGen(liveOldObjects), "List of the objects is suppose to be in OldGen");
+    }
+}

test/lib/jdk/test/lib/jfr/EventNames.java

@@ -128,6 +128,7 @@ public class EventNames {
     public final static String G1EvacuationOldStatistics = PREFIX + "G1EvacuationOldStatistics";
     public final static String G1BasicIHOP = PREFIX + "G1BasicIHOP";
     public final static String AllocationRequiringGC = PREFIX + "AllocationRequiringGC";
+    public final static String GCPhaseParallel = PREFIX + "GCPhaseParallel";
 
     // Compiler
     public final static String Compilation = PREFIX + "Compilation";