8346568: G1: Other time can be negative

Reviewed-by: tschatzl, iwalulya

Author: Sangheon Kim

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

@@ -193,6 +193,7 @@ void G1GCPhaseTimes::reset() {
   _cur_region_register_time = 0.0;
   _cur_verify_before_time_ms = 0.0;
   _cur_verify_after_time_ms = 0.0;
+  _cur_prepare_concurrent_task_time_ms = 0.0;
 
   for (int i = 0; i < GCParPhasesSentinel; i++) {
     if (_gc_par_phases[i] != nullptr) {
@@ -407,10 +408,7 @@ void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 }
 
 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
-  const double pre_concurrent_start_ms = average_time_ms(ResetMarkingState) +
-                                         average_time_ms(NoteStartOfMark);
-
-  const double sum_ms = pre_concurrent_start_ms +
+  const double sum_ms = _cur_prepare_concurrent_task_time_ms +
                         _cur_pre_evacuate_prepare_time_ms +
                         _recorded_young_cset_choice_time_ms +
                         _recorded_non_young_cset_choice_time_ms +
@@ -419,9 +417,12 @@ double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 
   info_time("Pre Evacuate Collection Set", sum_ms);
 
-  if (pre_concurrent_start_ms > 0.0) {
-    debug_phase(_gc_par_phases[ResetMarkingState]);
-    debug_phase(_gc_par_phases[NoteStartOfMark]);
+  // Concurrent tasks of ResetMarkingState and NoteStartOfMark are triggered during
+  // young collection. However, their execution time are not included in _gc_pause_time_ms.
+  if (_cur_prepare_concurrent_task_time_ms > 0.0) {
+    debug_time("Prepare Concurrent Start", _cur_prepare_concurrent_task_time_ms);
+    debug_phase(_gc_par_phases[ResetMarkingState], 1);
+    debug_phase(_gc_par_phases[NoteStartOfMark], 1);
   }
 
   debug_time("Pre Evacuate Prepare", _cur_pre_evacuate_prepare_time_ms);
@@ -545,6 +546,11 @@ void G1GCPhaseTimes::print_other(double accounted_ms) const {
   info_time("Other", _gc_pause_time_ms - accounted_ms);
 }
 
+// Root-region-scan-wait, verify-before and verify-after are part of young GC,
+// but these are not measured by G1Policy. i.e. these are not included in
+// G1Policy::record_young_collection_start() and record_young_collection_end().
+// In addition, these are not included in G1GCPhaseTimes::_gc_pause_time_ms.
+// See G1YoungCollector::collect().
 void G1GCPhaseTimes::print(bool evacuation_failed) {
   if (_root_region_scan_wait_time_ms > 0.0) {
     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
@@ -559,15 +565,13 @@ void G1GCPhaseTimes::print(bool evacuation_failed) {
 
   double accounted_ms = 0.0;
 
-  accounted_ms += _root_region_scan_wait_time_ms;
-  accounted_ms += _cur_verify_before_time_ms;
-
   accounted_ms += print_pre_evacuate_collection_set();
   accounted_ms += print_evacuate_initial_collection_set();
   accounted_ms += print_evacuate_optional_collection_set();
   accounted_ms += print_post_evacuate_collection_set(evacuation_failed);
 
-  accounted_ms += _cur_verify_after_time_ms;
+  assert(_gc_pause_time_ms >= accounted_ms, "GC pause time(%.3lfms) cannot be "
+         "smaller than the sum of each phase(%.3lfms).", _gc_pause_time_ms, accounted_ms);
 
   print_other(accounted_ms);
 

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2013, 2024, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2013, 2025, 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
@@ -177,12 +177,12 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
 
   double _cur_merge_heap_roots_time_ms;
   double _cur_optional_merge_heap_roots_time_ms;
+  // Included in above merge and optional-merge time.
+  double _cur_distribute_log_buffers_time_ms;
 
   double _cur_prepare_merge_heap_roots_time_ms;
   double _cur_optional_prepare_merge_heap_roots_time_ms;
 
-  double _cur_distribute_log_buffers_time_ms;
-
   double _cur_pre_evacuate_prepare_time_ms;
 
   double _cur_post_evacuate_cleanup_1_time_ms;
@@ -192,6 +192,7 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   double _cur_ref_proc_time_ms;
 
   double _cur_collection_start_sec;
+  // Not included in _gc_pause_time_ms
   double _root_region_scan_wait_time_ms;
 
   double _external_accounted_time_ms;
@@ -211,9 +212,13 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
 
   double _cur_region_register_time;
 
+  // Not included in _gc_pause_time_ms
   double _cur_verify_before_time_ms;
   double _cur_verify_after_time_ms;
 
+  // Time spent to trigger concurrent tasks of ResetMarkingState and NoteStartOfMark.
+  double _cur_prepare_concurrent_task_time_ms;
+
   ReferenceProcessorPhaseTimes _ref_phase_times;
   WeakProcessorTimes _weak_phase_times;
 
@@ -318,6 +323,10 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
     _cur_ref_proc_time_ms = ms;
   }
 
+  void record_prepare_concurrent_task_time_ms(double ms) {
+    _cur_prepare_concurrent_task_time_ms = ms;
+  }
+
   void record_root_region_scan_wait_time(double time_ms) {
     _root_region_scan_wait_time_ms = time_ms;
   }
@@ -389,8 +398,11 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   double cur_collection_par_time_ms() {
     return _cur_collection_initial_evac_time_ms +
            _cur_optional_evac_time_ms +
+           _cur_prepare_merge_heap_roots_time_ms +
            _cur_merge_heap_roots_time_ms +
-           _cur_optional_merge_heap_roots_time_ms;
+           _cur_optional_prepare_merge_heap_roots_time_ms +
+           _cur_optional_merge_heap_roots_time_ms +
+           _cur_collection_nmethod_list_cleanup_time_ms;
   }
 
   double cur_expand_heap_time_ms() {

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

@@ -1445,6 +1445,7 @@ void G1RemSet::print_merge_heap_roots_stats() {
 
 void G1RemSet::merge_heap_roots(bool initial_evacuation) {
   G1CollectedHeap* g1h = G1CollectedHeap::heap();
+  G1GCPhaseTimes* pt = g1h->phase_times();
 
   {
     Ticks start = Ticks::now();
@@ -1453,9 +1454,9 @@ void G1RemSet::merge_heap_roots(bool initial_evacuation) {
 
     Tickspan total = Ticks::now() - start;
     if (initial_evacuation) {
-      g1h->phase_times()->record_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
+      pt->record_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
     } else {
-      g1h->phase_times()->record_or_add_optional_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
+      pt->record_or_add_optional_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
     }
   }
 
@@ -1465,6 +1466,8 @@ void G1RemSet::merge_heap_roots(bool initial_evacuation) {
   uint const num_workers = initial_evacuation ? workers->active_workers() :
                                                 MIN2(workers->active_workers(), (uint)increment_length);
 
+  Ticks start = Ticks::now();
+
   {
     G1MergeHeapRootsTask cl(_scan_state, num_workers, initial_evacuation);
     log_debug(gc, ergo)("Running %s using %u workers for %zu regions",
@@ -1483,6 +1486,12 @@ void G1RemSet::merge_heap_roots(bool initial_evacuation) {
   }
 
   print_merge_heap_roots_stats();
+
+  if (initial_evacuation) {
+    pt->record_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
+  } else {
+    pt->record_or_add_optional_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
+  }
 }
 
 void G1RemSet::complete_evac_phase(bool has_more_than_one_evacuation_phase) {

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

@@ -486,7 +486,9 @@ void G1YoungCollector::pre_evacuate_collection_set(G1EvacInfo* evacuation_info)
   calculate_collection_set(evacuation_info, policy()->max_pause_time_ms());
 
   if (collector_state()->in_concurrent_start_gc()) {
+    Ticks start = Ticks::now();
     concurrent_mark()->pre_concurrent_start(_gc_cause);
+    phase_times()->record_prepare_concurrent_task_time_ms((Ticks::now() - start).seconds() * 1000.0);
   }
 
   // Please see comment in g1CollectedHeap.hpp and
@@ -743,11 +745,7 @@ void G1YoungCollector::evacuate_initial_collection_set(G1ParScanThreadStateSet*
                                                       bool has_optional_evacuation_work) {
   G1GCPhaseTimes* p = phase_times();
 
-  {
-    Ticks start = Ticks::now();
-    rem_set()->merge_heap_roots(true /* initial_evacuation */);
-    p->record_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
-  }
+  rem_set()->merge_heap_roots(true /* initial_evacuation */);
 
   Tickspan task_time;
   const uint num_workers = workers()->active_workers();
@@ -812,6 +810,7 @@ void G1YoungCollector::evacuate_next_optional_regions(G1ParScanThreadStateSet* p
   Tickspan total_processing = Ticks::now() - start_processing;
 
   G1GCPhaseTimes* p = phase_times();
+  p->record_or_add_optional_evac_time(task_time.seconds() * 1000.0);
   p->record_or_add_nmethod_list_cleanup_time((total_processing - task_time).seconds() * 1000.0);
 }
 
@@ -830,17 +829,9 @@ void G1YoungCollector::evacuate_optional_collection_set(G1ParScanThreadStateSet*
       break;
     }
 
-    {
-      Ticks start = Ticks::now();
-      rem_set()->merge_heap_roots(false /* initial_evacuation */);
-      phase_times()->record_or_add_optional_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
-    }
+    rem_set()->merge_heap_roots(false /* initial_evacuation */);
 
-    {
-      Ticks start = Ticks::now();
-      evacuate_next_optional_regions(per_thread_states);
-      phase_times()->record_or_add_optional_evac_time((Ticks::now() - start).seconds() * 1000.0);
-    }
+    evacuate_next_optional_regions(per_thread_states);
 
     rem_set()->complete_evac_phase(true /* has_more_than_one_evacuation_phase */);
   }