8269914: Factor out heap printing for G1 young and full gc

8270018: Add scoped object for g1 young gc JFR notification

Reviewed-by: ayang, iwalulya, kbarrett

Author: Thomas Schatzl

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

@@ -91,7 +91,7 @@ bool G1Allocator::is_retained_old_region(HeapRegion* hr) {
   return _retained_old_gc_alloc_region == hr;
 }
 
-void G1Allocator::reuse_retained_old_region(G1EvacuationInfo& evacuation_info,
+void G1Allocator::reuse_retained_old_region(G1EvacuationInfo* evacuation_info,
                                             OldGCAllocRegion* old,
                                             HeapRegion** retained_old) {
   HeapRegion* retained_region = *retained_old;
@@ -120,11 +120,11 @@ void G1Allocator::reuse_retained_old_region(G1EvacuationInfo& evacuation_info,
     _g1h->old_set_remove(retained_region);
     old->set(retained_region);
     _g1h->hr_printer()->reuse(retained_region);
-    evacuation_info.set_alloc_regions_used_before(retained_region->used());
+    evacuation_info->set_alloc_regions_used_before(retained_region->used());
   }
 }
 
-void G1Allocator::init_gc_alloc_regions(G1EvacuationInfo& evacuation_info) {
+void G1Allocator::init_gc_alloc_regions(G1EvacuationInfo* evacuation_info) {
   assert_at_safepoint_on_vm_thread();
 
   _survivor_is_full = false;
@@ -140,14 +140,14 @@ void G1Allocator::init_gc_alloc_regions(G1EvacuationInfo& evacuation_info) {
                             &_retained_old_gc_alloc_region);
 }
 
-void G1Allocator::release_gc_alloc_regions(G1EvacuationInfo& evacuation_info) {
+void G1Allocator::release_gc_alloc_regions(G1EvacuationInfo* evacuation_info) {
   uint survivor_region_count = 0;
   for (uint node_index = 0; node_index < _num_alloc_regions; node_index++) {
     survivor_region_count += survivor_gc_alloc_region(node_index)->count();
     survivor_gc_alloc_region(node_index)->release();
   }
-  evacuation_info.set_allocation_regions(survivor_region_count +
-                                         old_gc_alloc_region()->count());
+  evacuation_info->set_allocation_regions(survivor_region_count +
+                                          old_gc_alloc_region()->count());
 
   // If we have an old GC alloc region to release, we'll save it in
   // _retained_old_gc_alloc_region. If we don't

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

@@ -68,7 +68,7 @@ class G1Allocator : public CHeapObj<mtGC> {
   void set_survivor_full();
   void set_old_full();
 
-  void reuse_retained_old_region(G1EvacuationInfo& evacuation_info,
+  void reuse_retained_old_region(G1EvacuationInfo* evacuation_info,
                                  OldGCAllocRegion* old,
                                  HeapRegion** retained);
 
@@ -105,8 +105,8 @@ class G1Allocator : public CHeapObj<mtGC> {
   void init_mutator_alloc_regions();
   void release_mutator_alloc_regions();
 
-  void init_gc_alloc_regions(G1EvacuationInfo& evacuation_info);
-  void release_gc_alloc_regions(G1EvacuationInfo& evacuation_info);
+  void init_gc_alloc_regions(G1EvacuationInfo* evacuation_info);
+  void release_gc_alloc_regions(G1EvacuationInfo* evacuation_info);
   void abandon_gc_alloc_regions();
   bool is_retained_old_region(HeapRegion* hr);
 

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

@@ -980,7 +980,11 @@ class PostCompactionPrinterClosure: public HeapRegionClosure {
     : _hr_printer(hr_printer) { }
 };
 
-void G1CollectedHeap::print_hrm_post_compaction() {
+void G1CollectedHeap::print_heap_after_full_collection() {
+  // Post collection region logging.
+  // We should do this after we potentially resize the heap so
+  // that all the COMMIT / UNCOMMIT events are generated before
+  // the compaction events.
   if (_hr_printer.is_active()) {
     PostCompactionPrinterClosure cl(hr_printer());
     heap_region_iterate(&cl);
@@ -1092,17 +1096,6 @@ void G1CollectedHeap::verify_after_full_collection() {
   _ref_processor_cm->verify_no_references_recorded();
 }
 
-void G1CollectedHeap::print_heap_after_full_collection(G1HeapTransition* heap_transition) {
-  // Post collection logging.
-  // We should do this after we potentially resize the heap so
-  // that all the COMMIT / UNCOMMIT events are generated before
-  // the compaction events.
-  print_hrm_post_compaction();
-  heap_transition->print();
-  print_heap_after_gc();
-  print_heap_regions();
-}
-
 bool G1CollectedHeap::do_full_collection(bool explicit_gc,
                                          bool clear_all_soft_refs,
                                          bool do_maximum_compaction) {
@@ -2572,9 +2565,6 @@ void G1CollectedHeap::trace_heap(GCWhen::Type when, const GCTracer* gc_tracer) {
 void G1CollectedHeap::gc_prologue(bool full) {
   assert(InlineCacheBuffer::is_empty(), "should have cleaned up ICBuffer");
 
-  // This summary needs to be printed before incrementing total collections.
-  rem_set()->print_periodic_summary_info("Before GC RS summary", total_collections());
-
   // Update common counters.
   increment_total_collections(full /* full gc */);
   if (full || collector_state()->in_concurrent_start_gc()) {
@@ -2607,9 +2597,6 @@ void G1CollectedHeap::gc_epilogue(bool full) {
     increment_old_marking_cycles_completed(false /* concurrent */, true /* liveness_completed */);
   }
 
-  // We are at the end of the GC. Total collections has already been increased.
-  rem_set()->print_periodic_summary_info("After GC RS summary", total_collections() - 1);
-
 #if COMPILER2_OR_JVMCI
   assert(DerivedPointerTable::is_empty(), "derived pointer present");
 #endif
@@ -2622,9 +2609,6 @@ void G1CollectedHeap::gc_epilogue(bool full) {
   // policy with the new heap occupancy
   Universe::heap()->update_capacity_and_used_at_gc();
 
-  // Print NUMA statistics.
-  _numa->print_statistics();
-
   _collection_pause_end = Ticks::now();
 
   _free_card_set_memory_task->notify_new_stats(&_young_gen_card_set_stats,
@@ -2813,10 +2797,10 @@ void G1CollectedHeap::start_new_collection_set() {
   phase_times()->record_start_new_cset_time_ms((os::elapsedTime() - start) * 1000.0);
 }
 
-void G1CollectedHeap::calculate_collection_set(G1EvacuationInfo& evacuation_info, double target_pause_time_ms) {
+void G1CollectedHeap::calculate_collection_set(G1EvacuationInfo* evacuation_info, double target_pause_time_ms) {
 
   _collection_set.finalize_initial_collection_set(target_pause_time_ms, &_survivor);
-  evacuation_info.set_collectionset_regions(collection_set()->region_length() +
+  evacuation_info->set_collectionset_regions(collection_set()->region_length() +
                                             collection_set()->optional_region_length());
 
   _cm->verify_no_collection_set_oops();
@@ -2946,6 +2930,64 @@ class G1YoungGCTraceTime {
   }
 };
 
+G1HeapPrinterMark::G1HeapPrinterMark(G1CollectedHeap* g1h) : _g1h(g1h), _heap_transition(g1h) {
+  // This summary needs to be printed before incrementing total collections.
+  _g1h->rem_set()->print_periodic_summary_info("Before GC RS summary", _g1h->total_collections());
+  _g1h->print_heap_before_gc();
+  _g1h->print_heap_regions();
+}
+
+G1HeapPrinterMark::~G1HeapPrinterMark() {
+  _g1h->policy()->print_age_table();
+  _g1h->rem_set()->print_coarsen_stats();
+  // We are at the end of the GC. Total collections has already been increased.
+  _g1h->rem_set()->print_periodic_summary_info("After GC RS summary", _g1h->total_collections() - 1);
+
+  _heap_transition.print();
+  _g1h->print_heap_regions();
+  _g1h->print_heap_after_gc();
+  // Print NUMA statistics.
+  _g1h->numa()->print_statistics();
+}
+
+G1JFRTracerMark::G1JFRTracerMark(STWGCTimer* timer, GCTracer* tracer) :
+  _timer(timer), _tracer(tracer) {
+
+  _timer->register_gc_start();
+  _tracer->report_gc_start(G1CollectedHeap::heap()->gc_cause(), _timer->gc_start());
+  G1CollectedHeap::heap()->trace_heap_before_gc(_tracer);
+}
+
+G1JFRTracerMark::~G1JFRTracerMark() {
+  G1CollectedHeap::heap()->trace_heap_after_gc(_tracer);
+  _timer->register_gc_end();
+  _tracer->report_gc_end(_timer->gc_end(), _timer->time_partitions());
+}
+
+class G1YoungGCJFRTracerMark : public G1JFRTracerMark {
+  G1EvacuationInfo _evacuation_info;
+
+  G1NewTracer* tracer() const { return (G1NewTracer*)_tracer; }
+
+public:
+
+  G1EvacuationInfo* evacuation_info() { return &_evacuation_info; }
+
+  G1YoungGCJFRTracerMark(STWGCTimer* gc_timer_stw, G1NewTracer* gc_tracer_stw, GCCause::Cause cause) :
+    G1JFRTracerMark(gc_timer_stw, gc_tracer_stw), _evacuation_info() { }
+
+  void report_pause_type(G1GCPauseType type) {
+    tracer()->report_young_gc_pause(type);
+  }
+
+  ~G1YoungGCJFRTracerMark() {
+    G1CollectedHeap* g1h = G1CollectedHeap::heap();
+
+    tracer()->report_evacuation_info(&_evacuation_info);
+    tracer()->report_tenuring_threshold(g1h->policy()->tenuring_threshold());
+  }
+};
+
 void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_pause_time_ms) {
   GCIdMark gc_id_mark;
 
@@ -2954,14 +2996,8 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
 
   policy()->note_gc_start();
 
-  gc_tracer_report_gc_start();
-
   wait_for_root_region_scanning();
 
-  print_heap_before_gc();
-  print_heap_regions();
-  trace_heap_before_gc(_gc_tracer_stw);
-
   // We should not be doing concurrent start unless the concurrent mark thread is running
   if (!_cm_thread->should_terminate()) {
     // This call will decide whether this pause is a concurrent start
@@ -2984,8 +3020,6 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
 
   // Inner scope for scope based logging, timers, and stats collection
   {
-    G1EvacuationInfo evacuation_info;
-
     GCTraceCPUTime tcpu;
 
     G1YoungGCTraceTime tm(gc_cause());
@@ -2996,12 +3030,14 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
     active_workers = workers()->update_active_workers(active_workers);
     log_info(gc,task)("Using %u workers of %u for evacuation", active_workers, workers()->total_workers());
 
+    // JFR
+    G1YoungGCJFRTracerMark jtm(_gc_timer_stw, _gc_tracer_stw, gc_cause());
     // JStat/MXBeans
     G1MonitoringScope ms(g1mm(),
                          false /* full_gc */,
                          collector_state()->in_mixed_phase() /* all_memory_pools_affected */);
 
-    G1HeapTransition heap_transition(this);
+    G1HeapPrinterMark hpm(this);
 
     {
       IsGCActiveMark x;
@@ -3025,15 +3061,15 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
         // of the collection set!).
         _allocator->release_mutator_alloc_regions();
 
-        calculate_collection_set(evacuation_info, target_pause_time_ms);
+        calculate_collection_set(jtm.evacuation_info(), target_pause_time_ms);
 
         G1RedirtyCardsQueueSet rdcqs(G1BarrierSet::dirty_card_queue_set().allocator());
         G1ParScanThreadStateSet per_thread_states(this,
                                                   &rdcqs,
                                                   workers()->active_workers(),
                                                   collection_set()->young_region_length(),
                                                   collection_set()->optional_region_length());
-        pre_evacuate_collection_set(evacuation_info, &per_thread_states);
+        pre_evacuate_collection_set(jtm.evacuation_info(), &per_thread_states);
 
         bool may_do_optional_evacuation = _collection_set.optional_region_length() != 0;
         // Actually do the work...
@@ -3042,7 +3078,7 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
         if (may_do_optional_evacuation) {
           evacuate_optional_collection_set(&per_thread_states);
         }
-        post_evacuate_collection_set(evacuation_info, &rdcqs, &per_thread_states);
+        post_evacuate_collection_set(jtm.evacuation_info(), &rdcqs, &per_thread_states);
 
         start_new_collection_set();
 
@@ -3061,7 +3097,7 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
 
         // Need to report the collection pause now since record_collection_pause_end()
         // modifies it to the next state.
-        _gc_tracer_stw->report_young_gc_pause(collector_state()->young_gc_pause_type(concurrent_operation_is_full_mark));
+        jtm.report_pause_type(collector_state()->young_gc_pause_type(concurrent_operation_is_full_mark));
 
         double sample_end_time_sec = os::elapsedTime();
         double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
@@ -3074,16 +3110,9 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
     }
 
     policy()->print_phases();
-    heap_transition.print();
 
     TASKQUEUE_STATS_ONLY(print_taskqueue_stats());
     TASKQUEUE_STATS_ONLY(reset_taskqueue_stats());
-
-    print_heap_after_gc();
-    print_heap_regions();
-    trace_heap_after_gc(_gc_tracer_stw);
-
-    gc_tracer_report_gc_end(concurrent_operation_is_full_mark, evacuation_info);
   }
   // It should now be safe to tell the concurrent mark thread to start
   // without its logging output interfering with the logging output
@@ -3514,7 +3543,7 @@ class G1PrepareEvacuationTask : public AbstractGangTask {
   }
 };
 
-void G1CollectedHeap::pre_evacuate_collection_set(G1EvacuationInfo& evacuation_info, G1ParScanThreadStateSet* per_thread_states) {
+void G1CollectedHeap::pre_evacuate_collection_set(G1EvacuationInfo* evacuation_info, G1ParScanThreadStateSet* per_thread_states) {
   _bytes_used_during_gc = 0;
 
   _expand_heap_after_alloc_failure = true;
@@ -3782,7 +3811,7 @@ void G1CollectedHeap::evacuate_optional_collection_set(G1ParScanThreadStateSet*
   _collection_set.abandon_optional_collection_set(per_thread_states);
 }
 
-void G1CollectedHeap::post_evacuate_collection_set(G1EvacuationInfo& evacuation_info,
+void G1CollectedHeap::post_evacuate_collection_set(G1EvacuationInfo* evacuation_info,
                                                    G1RedirtyCardsQueueSet* rdcqs,
                                                    G1ParScanThreadStateSet* per_thread_states) {
   G1GCPhaseTimes* p = phase_times();
@@ -3803,19 +3832,16 @@ void G1CollectedHeap::post_evacuate_collection_set(G1EvacuationInfo& evacuation_
 
   post_evacuate_cleanup_1(per_thread_states, rdcqs);
 
-  post_evacuate_cleanup_2(&_preserved_marks_set, rdcqs, &evacuation_info, per_thread_states->surviving_young_words());
+  post_evacuate_cleanup_2(&_preserved_marks_set, rdcqs, evacuation_info, per_thread_states->surviving_young_words());
 
   assert_used_and_recalculate_used_equal(this);
 
   rebuild_free_region_list();
 
   record_obj_copy_mem_stats();
 
-  evacuation_info.set_collectionset_used_before(collection_set()->bytes_used_before());
-  evacuation_info.set_bytes_used(_bytes_used_during_gc);
-
-  policy()->print_age_table();
-  rem_set()->print_coarsen_stats();
+  evacuation_info->set_collectionset_used_before(collection_set()->bytes_used_before());
+  evacuation_info->set_bytes_used(_bytes_used_during_gc);
 }
 
 void G1CollectedHeap::record_obj_copy_mem_stats() {