8277814: ConcurrentRefineThread should report rate when deactivating

Reviewed-by: tschatzl, sjohanss

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2020, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2020, 2021, 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
@@ -32,6 +32,12 @@ G1ConcurrentRefineStats::G1ConcurrentRefineStats() :
   _dirtied_cards(0)
 {}
 
+double G1ConcurrentRefineStats::refinement_rate_ms() const {
+  // Report 0 when no time recorded because no refinement performed.
+  double secs = refinement_time().seconds();
+  return (secs > 0) ? (refined_cards() / (secs * MILLIUNITS)) : 0.0;
+}
+
 G1ConcurrentRefineStats&
 G1ConcurrentRefineStats::operator+=(const G1ConcurrentRefineStats& other) {
   _refinement_time += other._refinement_time;

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2020, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2020, 2021, 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
@@ -47,6 +47,9 @@ class G1ConcurrentRefineStats : public CHeapObj<mtGC> {
   // Number of refined cards.
   size_t refined_cards() const { return _refined_cards; }
 
+  // Refinement rate, in cards per ms.
+  double refinement_rate_ms() const;
+
   // Number of cards for which refinement was skipped because some other
   // thread had already refined them.
   size_t precleaned_cards() const { return _precleaned_cards; }

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

@@ -131,12 +131,12 @@ void G1ConcurrentRefineThread::run_service() {
     }
 
     total_stats += *_refinement_stats - start_stats;
-    log_debug(gc, refine)("Deactivated worker %d, off threshold: " SIZE_FORMAT
-                          ", current: " SIZE_FORMAT
-                          ", refined cards: " SIZE_FORMAT,
+    log_debug(gc, refine)("Deactivated worker %d, off threshold: %zu, "
+                          "cards: %zu, refined %zu, rate %1.2fc/ms",
                           _worker_id, _cr->deactivation_threshold(_worker_id),
                           G1BarrierSet::dirty_card_queue_set().num_cards(),
-                          total_stats.refined_cards());
+                          total_stats.refined_cards(),
+                          total_stats.refinement_rate_ms());
 
     if (os::supports_vtime()) {
       _vtime_accum = (os::elapsedVTime() - _vtime_start);