8219096: Merge print_termination_stats code with current logging
authortschatzl
Wed, 20 Feb 2019 14:30:33 +0100
changeset 53846 fe95464806a7
parent 53845 1807da9ad196
child 53847 74b616640b00
8219096: Merge print_termination_stats code with current logging Reviewed-by: lkorinth, kbarrett
src/hotspot/share/gc/g1/g1Allocator.cpp
src/hotspot/share/gc/g1/g1Allocator.hpp
src/hotspot/share/gc/g1/g1CollectedHeap.cpp
src/hotspot/share/gc/g1/g1CollectedHeap.hpp
src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp
src/hotspot/share/gc/g1/g1ParScanThreadState.cpp
src/hotspot/share/gc/g1/g1ParScanThreadState.hpp
test/hotspot/jtreg/gc/g1/TestGCLogMessages.java
--- a/src/hotspot/share/gc/g1/g1Allocator.cpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1Allocator.cpp	Wed Feb 20 14:30:33 2019 +0100
@@ -321,16 +321,26 @@
   }
 }
 
-void G1PLABAllocator::waste(size_t& wasted, size_t& undo_wasted) {
-  wasted = 0;
-  undo_wasted = 0;
+size_t G1PLABAllocator::waste() const {
+  size_t result = 0;
   for (uint state = 0; state < InCSetState::Num; state++) {
     PLAB * const buf = _alloc_buffers[state];
     if (buf != NULL) {
-      wasted += buf->waste();
-      undo_wasted += buf->undo_waste();
+      result += buf->waste();
     }
   }
+  return result;
+}
+
+size_t G1PLABAllocator::undo_waste() const {
+  size_t result = 0;
+  for (uint state = 0; state < InCSetState::Num; state++) {
+    PLAB * const buf = _alloc_buffers[state];
+    if (buf != NULL) {
+      result += buf->undo_waste();
+    }
+  }
+  return result;
 }
 
 bool G1ArchiveAllocator::_archive_check_enabled = false;
--- a/src/hotspot/share/gc/g1/g1Allocator.hpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1Allocator.hpp	Wed Feb 20 14:30:33 2019 +0100
@@ -155,7 +155,8 @@
 public:
   G1PLABAllocator(G1Allocator* allocator);
 
-  void waste(size_t& wasted, size_t& undo_wasted);
+  size_t waste() const;
+  size_t undo_waste() const;
 
   // Allocate word_sz words in dest, either directly into the regions or by
   // allocating a new PLAB. Returns the address of the allocated memory, NULL if
--- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp	Wed Feb 20 14:30:33 2019 +0100
@@ -3299,27 +3299,22 @@
 
         G1GCPhaseTimes* p = _g1h->g1_policy()->phase_times();
         p->add_time_secs(G1GCPhaseTimes::ObjCopy, worker_id, elapsed_sec - term_sec);
+
+        p->record_or_add_thread_work_item(G1GCPhaseTimes::ObjCopy,
+                                          worker_id,
+                                          pss->lab_waste_words() * HeapWordSize,
+                                          G1GCPhaseTimes::ObjCopyLABWaste);
+        p->record_or_add_thread_work_item(G1GCPhaseTimes::ObjCopy,
+                                          worker_id,
+                                          pss->lab_undo_waste_words() * HeapWordSize,
+                                          G1GCPhaseTimes::ObjCopyLABUndoWaste);
+
         p->record_time_secs(G1GCPhaseTimes::Termination, worker_id, term_sec);
         p->record_thread_work_item(G1GCPhaseTimes::Termination, worker_id, evac_term_attempts);
       }
 
       assert(pss->queue_is_empty(), "should be empty");
 
-      if (log_is_enabled(Debug, gc, task, stats)) {
-        MutexLockerEx x(ParGCRareEvent_lock, Mutex::_no_safepoint_check_flag);
-        size_t lab_waste;
-        size_t lab_undo_waste;
-        pss->waste(lab_waste, lab_undo_waste);
-        _g1h->print_termination_stats(worker_id,
-                                      (os::elapsedTime() - start_sec) * 1000.0,   /* elapsed time */
-                                      strong_roots_sec * 1000.0,                  /* strong roots time */
-                                      term_sec * 1000.0,                          /* evac term time */
-                                      evac_term_attempts,                         /* evac term attempts */
-                                      lab_waste,                                  /* alloc buffer waste */
-                                      lab_undo_waste                              /* undo waste */
-                                      );
-      }
-
       // Close the inner scope so that the ResourceMark and HandleMark
       // destructors are executed here and are included as part of the
       // "GC Worker Time".
@@ -3328,31 +3323,6 @@
   }
 };
 
-void G1CollectedHeap::print_termination_stats_hdr() {
-  log_debug(gc, task, stats)("GC Termination Stats");
-  log_debug(gc, task, stats)("     elapsed  --strong roots-- -------termination------- ------waste (KiB)------");
-  log_debug(gc, task, stats)("thr     ms        ms      %%        ms      %%    attempts  total   alloc    undo");
-  log_debug(gc, task, stats)("--- --------- --------- ------ --------- ------ -------- ------- ------- -------");
-}
-
-void G1CollectedHeap::print_termination_stats(uint worker_id,
-                                              double elapsed_ms,
-                                              double strong_roots_ms,
-                                              double term_ms,
-                                              size_t term_attempts,
-                                              size_t alloc_buffer_waste,
-                                              size_t undo_waste) const {
-  log_debug(gc, task, stats)
-              ("%3d %9.2f %9.2f %6.2f "
-               "%9.2f %6.2f " SIZE_FORMAT_W(8) " "
-               SIZE_FORMAT_W(7) " " SIZE_FORMAT_W(7) " " SIZE_FORMAT_W(7),
-               worker_id, elapsed_ms, strong_roots_ms, strong_roots_ms * 100 / elapsed_ms,
-               term_ms, term_ms * 100 / elapsed_ms, term_attempts,
-               (alloc_buffer_waste + undo_waste) * HeapWordSize / K,
-               alloc_buffer_waste * HeapWordSize / K,
-               undo_waste * HeapWordSize / K);
-}
-
 void G1CollectedHeap::complete_cleaning(BoolObjectClosure* is_alive,
                                         bool class_unloading_occurred) {
   uint num_workers = workers()->active_workers();
@@ -3763,8 +3733,6 @@
     G1RootProcessor root_processor(this, n_workers);
     G1ParTask g1_par_task(this, per_thread_states, _task_queues, &root_processor, n_workers);
 
-    print_termination_stats_hdr();
-
     workers()->run_task(&g1_par_task);
     end_par_time_sec = os::elapsedTime();
 
--- a/src/hotspot/share/gc/g1/g1CollectedHeap.hpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1CollectedHeap.hpp	Wed Feb 20 14:30:33 2019 +0100
@@ -738,16 +738,6 @@
   void pre_evacuate_collection_set();
   void post_evacuate_collection_set(G1EvacuationInfo& evacuation_info, G1ParScanThreadStateSet* pss);
 
-  // Print the header for the per-thread termination statistics.
-  static void print_termination_stats_hdr();
-  // Print actual per-thread termination statistics.
-  void print_termination_stats(uint worker_id,
-                               double elapsed_ms,
-                               double strong_roots_ms,
-                               double term_ms,
-                               size_t term_attempts,
-                               size_t alloc_buffer_waste,
-                               size_t undo_waste) const;
   // Update object copying statistics.
   void record_obj_copy_mem_stats();
 
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp	Wed Feb 20 14:30:33 2019 +0100
@@ -107,6 +107,11 @@
   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
 
+  _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
+  _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
+  _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
+  _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
+
   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp	Wed Feb 20 14:30:33 2019 +0100
@@ -93,6 +93,11 @@
     UpdateRSSkippedCards
   };
 
+  enum GCObjCopyWorkItems {
+    ObjCopyLABWaste,
+    ObjCopyLABUndoWaste
+  };
+
   enum GCOptCSetWorkItems {
       OptCSetScannedCards,
       OptCSetClaimedCards,
@@ -114,6 +119,9 @@
   WorkerDataArray<size_t>* _scan_rs_claimed_cards;
   WorkerDataArray<size_t>* _scan_rs_skipped_cards;
 
+  WorkerDataArray<size_t>* _obj_copy_lab_waste;
+  WorkerDataArray<size_t>* _obj_copy_lab_undo_waste;
+
   WorkerDataArray<size_t>* _opt_cset_scanned_cards;
   WorkerDataArray<size_t>* _opt_cset_claimed_cards;
   WorkerDataArray<size_t>* _opt_cset_skipped_cards;
--- a/src/hotspot/share/gc/g1/g1ParScanThreadState.cpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1ParScanThreadState.cpp	Wed Feb 20 14:30:33 2019 +0100
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2014, 2018, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2014, 2019, 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
@@ -106,8 +106,12 @@
   delete[] _oops_into_optional_regions;
 }
 
-void G1ParScanThreadState::waste(size_t& wasted, size_t& undo_wasted) {
-  _plab_allocator->waste(wasted, undo_wasted);
+size_t G1ParScanThreadState::lab_waste_words() const {
+  return _plab_allocator->waste();
+}
+
+size_t G1ParScanThreadState::lab_undo_waste_words() const {
+  return _plab_allocator->undo_waste();
 }
 
 #ifdef ASSERT
--- a/src/hotspot/share/gc/g1/g1ParScanThreadState.hpp	Wed Feb 20 08:10:40 2019 -0500
+++ b/src/hotspot/share/gc/g1/g1ParScanThreadState.hpp	Wed Feb 20 14:30:33 2019 +0100
@@ -127,9 +127,8 @@
   G1EvacuationRootClosures* closures() { return _closures; }
   uint worker_id() { return _worker_id; }
 
-  // Returns the current amount of waste due to alignment or not being able to fit
-  // objects within LABs and the undo waste.
-  virtual void waste(size_t& wasted, size_t& undo_wasted);
+  size_t lab_waste_words() const;
+  size_t lab_undo_waste_words() const;
 
   size_t* surviving_young_words() {
     // We add one to hide entry 0 which accumulates surviving words for
--- a/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java	Wed Feb 20 08:10:40 2019 -0500
+++ b/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java	Wed Feb 20 14:30:33 2019 +0100
@@ -106,6 +106,10 @@
         new LogMessageWithLevel("Scanned Cards", Level.DEBUG),
         new LogMessageWithLevel("Claimed Cards", Level.DEBUG),
         new LogMessageWithLevel("Skipped Cards", Level.DEBUG),
+        // Object Copy
+        new LogMessageWithLevel("Object Copy", Level.DEBUG),
+        new LogMessageWithLevel("Scanned Cards", Level.DEBUG),
+        new LogMessageWithLevel("Claimed Cards", Level.DEBUG),
         // Ext Root Scan
         new LogMessageWithLevel("Thread Roots", Level.TRACE),
         new LogMessageWithLevel("Universe Roots", Level.TRACE),