8290966: G1: Record number of PLAB filled and number of direct alloca…

…tions

Reviewed-by: sangheki, kbarrett

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

@@ -304,6 +304,8 @@ G1PLABAllocator::G1PLABAllocator(G1Allocator* allocator) :
     for (uint node_index = 0; node_index < length; node_index++) {
       _alloc_buffers[state][node_index] = new PLAB(word_sz);
     }
+    _num_plab_fills[state] = 0;
+    _num_direct_allocations[state] = 0;
   }
 }
 
@@ -336,6 +338,8 @@ HeapWord* G1PLABAllocator::allocate_direct_or_new_plab(G1HeapRegionAttr dest,
     PLAB* alloc_buf = alloc_buffer(dest, node_index);
     alloc_buf->retire();
 
+    _num_plab_fills[dest.type()]++;
+
     size_t actual_plab_size = 0;
     HeapWord* buf = _allocator->par_allocate_during_gc(dest,
                                                        required_in_plab,
@@ -344,15 +348,15 @@ HeapWord* G1PLABAllocator::allocate_direct_or_new_plab(G1HeapRegionAttr dest,
                                                        node_index);
 
     assert(buf == NULL || ((actual_plab_size >= required_in_plab) && (actual_plab_size <= plab_word_size)),
-           "Requested at minimum " SIZE_FORMAT ", desired " SIZE_FORMAT " words, but got " SIZE_FORMAT " at " PTR_FORMAT,
+           "Requested at minimum %zu, desired %zu words, but got %zu at " PTR_FORMAT,
            required_in_plab, plab_word_size, actual_plab_size, p2i(buf));
 
     if (buf != NULL) {
       alloc_buf->set_buf(buf, actual_plab_size);
 
       HeapWord* const obj = alloc_buf->allocate(word_sz);
       assert(obj != NULL, "PLAB should have been big enough, tried to allocate "
-                          SIZE_FORMAT " requiring " SIZE_FORMAT " PLAB size " SIZE_FORMAT,
+                          "%zu requiring %zu PLAB size %zu",
                           word_sz, required_in_plab, plab_word_size);
       return obj;
     }
@@ -363,6 +367,7 @@ HeapWord* G1PLABAllocator::allocate_direct_or_new_plab(G1HeapRegionAttr dest,
   HeapWord* result = _allocator->par_allocate_during_gc(dest, word_sz, node_index);
   if (result != NULL) {
     _direct_allocated[dest.type()] += word_sz;
+    _num_direct_allocations[dest.type()]++;
   }
   return result;
 }
@@ -380,8 +385,9 @@ void G1PLABAllocator::flush_and_retire_stats() {
         buf->flush_and_retire_stats(stats);
       }
     }
+    stats->add_num_plab_filled(_num_plab_fills[state]);
     stats->add_direct_allocated(_direct_allocated[state]);
-    _direct_allocated[state] = 0;
+    stats->add_num_direct_allocated(_num_direct_allocations[state]);
   }
 }
 

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

@@ -161,6 +161,10 @@ class G1PLABAllocator : public CHeapObj<mtGC> {
   // Number of words allocated directly (not counting PLAB allocation).
   size_t _direct_allocated[G1HeapRegionAttr::Num];
 
+  // Number of PLAB refills experienced so far.
+  size_t _num_plab_fills[G1HeapRegionAttr::Num];
+  size_t _num_direct_allocations[G1HeapRegionAttr::Num];
+
   void flush_and_retire_stats();
   inline PLAB* alloc_buffer(G1HeapRegionAttr dest, uint node_index) const;
   inline PLAB* alloc_buffer(region_type_t dest, uint node_index) const;

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

@@ -2572,7 +2572,8 @@ G1HeapSummary G1CollectedHeap::create_g1_heap_summary() {
 G1EvacSummary G1CollectedHeap::create_g1_evac_summary(G1EvacStats* stats) {
   return G1EvacSummary(stats->allocated(), stats->wasted(), stats->undo_wasted(),
                        stats->unused(), stats->used(), stats->region_end_waste(),
-                       stats->regions_filled(), stats->direct_allocated(),
+                       stats->regions_filled(), stats->num_plab_filled(),
+                       stats->direct_allocated(), stats->num_direct_allocated(),
                        stats->failure_used(), stats->failure_waste());
 }
 

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

@@ -33,15 +33,19 @@
 void G1EvacStats::log_plab_allocation() {
   PLABStats::log_plab_allocation();
   log_debug(gc, plab)("%s other allocation: "
-                      "region end waste: " SIZE_FORMAT "B, "
+                      "region end waste: %zuB, "
                       "regions filled: %u, "
-                      "direct allocated: " SIZE_FORMAT "B, "
-                      "failure used: " SIZE_FORMAT "B, "
-                      "failure wasted: " SIZE_FORMAT "B",
+                      "num plab filled: %zu, "
+                      "direct allocated: %zuB, "
+                      "num direct allocated: %zu, "
+                      "failure used: %zuB, "
+                      "failure wasted: %zuB",
                       _description,
                       _region_end_waste * HeapWordSize,
                       _regions_filled,
+                      _num_plab_filled,
                       _direct_allocated * HeapWordSize,
+                      _num_direct_allocated,
                       _failure_used * HeapWordSize,
                       _failure_waste * HeapWordSize);
 }
@@ -94,7 +98,9 @@ G1EvacStats::G1EvacStats(const char* description, size_t default_per_thread_plab
   PLABStats(description, default_per_thread_plab_size, default_per_thread_plab_size * ParallelGCThreads, wt),
   _region_end_waste(0),
   _regions_filled(0),
+  _num_plab_filled(0),
   _direct_allocated(0),
+  _num_direct_allocated(0),
   _failure_used(0),
   _failure_waste(0) {
 }

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

@@ -32,7 +32,9 @@ class G1EvacStats : public PLABStats {
  private:
   size_t _region_end_waste; // Number of words wasted due to skipping to the next region.
   uint   _regions_filled;   // Number of regions filled completely.
+  size_t _num_plab_filled; // Number of PLABs filled and retired.
   size_t _direct_allocated; // Number of words allocated directly into the regions.
+  size_t _num_direct_allocated; // Number of direct allocation attempts.
 
   // Number of words in live objects remaining in regions that ultimately suffered an
   // evacuation failure. This is used in the regions when the regions are made old regions.
@@ -46,7 +48,9 @@ class G1EvacStats : public PLABStats {
     PLABStats::reset();
     _region_end_waste = 0;
     _regions_filled = 0;
+    _num_plab_filled = 0;
     _direct_allocated = 0;
+    _num_direct_allocated = 0;
     _failure_used = 0;
     _failure_waste = 0;
   }
@@ -61,15 +65,19 @@ class G1EvacStats : public PLABStats {
   ~G1EvacStats();
 
   uint regions_filled() const { return _regions_filled; }
+  size_t num_plab_filled() const { return _num_plab_filled; }
   size_t region_end_waste() const { return _region_end_waste; }
   size_t direct_allocated() const { return _direct_allocated; }
+  size_t num_direct_allocated() const { return _num_direct_allocated; }
 
   // Amount of space in heapwords used in the failing regions when an evacuation failure happens.
   size_t failure_used() const { return _failure_used; }
   // Amount of space in heapwords wasted (unused) in the failing regions when an evacuation failure happens.
   size_t failure_waste() const { return _failure_waste; }
 
+  inline void add_num_plab_filled(size_t value);
   inline void add_direct_allocated(size_t value);
+  inline void add_num_direct_allocated(size_t value);
   inline void add_region_end_waste(size_t value);
   inline void add_failure_used_and_waste(size_t used, size_t waste);
 };

src/hotspot/share/gc/g1/g1EvacStats.inline.hpp

@@ -33,6 +33,14 @@ inline void G1EvacStats::add_direct_allocated(size_t value) {
   Atomic::add(&_direct_allocated, value);
 }
 
+inline void G1EvacStats::add_num_plab_filled(size_t value) {
+  Atomic::add(&_num_plab_filled, value);
+}
+
+inline void G1EvacStats::add_num_direct_allocated(size_t value) {
+  Atomic::add(&_num_direct_allocated, value);
+}
+
 inline void G1EvacStats::add_region_end_waste(size_t value) {
   Atomic::add(&_region_end_waste, value);
   Atomic::inc(&_regions_filled);

src/hotspot/share/gc/shared/gcHeapSummary.hpp

@@ -177,7 +177,9 @@ class G1EvacSummary : public StackObj {
 
   size_t _region_end_waste; // Number of words wasted due to skipping to the next region.
   uint   _regions_filled;   // Number of regions filled completely.
+  size_t _num_plab_filled;  // Number of PLABs refilled/retired.
   size_t _direct_allocated; // Number of words allocated directly into the regions.
+  size_t _num_direct_allocated; // Number of direct allocations.
 
   // Number of words in live objects remaining in regions that ultimately suffered an
   // evacuation failure. This is used in the regions when the regions are made old regions.
@@ -187,12 +189,23 @@ class G1EvacSummary : public StackObj {
   // end of regions.
   size_t _failure_waste;
 public:
-  G1EvacSummary(size_t allocated, size_t wasted, size_t undo_wasted, size_t unused,
-    size_t used, size_t region_end_waste, uint regions_filled, size_t direct_allocated,
-    size_t failure_used, size_t failure_waste) :
+  G1EvacSummary(size_t allocated,
+                size_t wasted,
+                size_t undo_wasted,
+                size_t unused,
+                size_t used,
+                size_t region_end_waste,
+                uint regions_filled,
+                size_t num_plab_filled,
+                size_t direct_allocated,
+                size_t num_direct_allocated,
+                size_t failure_used,
+                size_t failure_waste) :
     _allocated(allocated), _wasted(wasted), _undo_wasted(undo_wasted), _unused(unused),
-    _used(used),  _region_end_waste(region_end_waste), _regions_filled(regions_filled),
-    _direct_allocated(direct_allocated), _failure_used(failure_used), _failure_waste(failure_waste)
+    _used(used),  _region_end_waste(region_end_waste),
+    _regions_filled(regions_filled), _num_plab_filled(num_plab_filled),
+    _direct_allocated(direct_allocated),_num_direct_allocated(num_direct_allocated),
+    _failure_used(failure_used), _failure_waste(failure_waste)
   { }
 
   size_t allocated() const { return _allocated; }
@@ -202,7 +215,9 @@ class G1EvacSummary : public StackObj {
   size_t used() const { return _used; }
   size_t region_end_waste() const { return _region_end_waste; }
   uint regions_filled() const { return _regions_filled; }
+  size_t num_plab_filled() const { return _num_plab_filled; }
   size_t direct_allocated() const { return _direct_allocated; }
+  size_t num_direct_allocated() const { return _num_direct_allocated; }
   size_t failure_used() const { return _failure_used; }
   size_t failure_waste() const { return _failure_waste; }
 };

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

@@ -414,7 +414,9 @@
     <Field type="ulong" contentType="bytes" name="undoWaste" label="Undo Wasted" description="Total memory wasted due to allocation undo within PLABs" />
     <Field type="ulong" contentType="bytes" name="regionEndWaste" label="Region End Wasted" description="Total memory wasted at the end of regions due to refill" />
     <Field type="uint" name="regionsRefilled" label="Region Refills" description="Number of regions refilled" />
+    <Field type="ulong" name="numPlabsFilled" label="PLAB Fills" description="Number of PLABs filled" />
     <Field type="ulong" contentType="bytes" name="directAllocated" label="Allocated (direct)" description="Total memory allocated using direct allocation outside of PLABs" />
+    <Field type="ulong" name="numDirectAllocated" label="Direct allocations" description="Number of direct allocations" />
     <Field type="ulong" contentType="bytes" name="failureUsed" label="Used (failure)" description="Total memory occupied by objects in regions where evacuation failed" />
     <Field type="ulong" contentType="bytes" name="failureWaste" label="Wasted (failure)" description="Total memory left unused in regions where evacuation failed" />
   </Type>

test/hotspot/jtreg/gc/g1/plab/lib/LogParser.java

@@ -37,12 +37,12 @@
  *
  * Typical GC log with PLAB statistics (options - -Xlog:gc=debug,gc+plab=debug) looks like:
  *
- * [0.330s][debug][gc,plab  ] GC(0) Young PLAB allocation: allocated: 1825632B, wasted: 29424B, unused: 2320B, used: 1793888B, undo waste: 0B,
- * [0.330s][debug][gc,plab  ] GC(0) Young other allocation: region end waste: 0B, regions filled: 2, direct allocated: 271520B, failure used: 0B, failure wasted: 0B
- * [0.330s][debug][gc,plab  ] GC(0) Young sizing: calculated: 358776B, actual: 358776B
- * [0.330s][debug][gc,plab  ] GC(0) Old PLAB allocation: allocated: 427248B, wasted: 592B, unused: 368584B, used: 58072B, undo waste: 0B,
- * [0.330s][debug][gc,plab  ] GC(0) Old other allocation: region end waste: 0B, regions filled: 1, direct allocated: 41704B, failure used: 0B, failure wasted: 0B
- * [0.330s][debug][gc,plab  ] GC(0) Old sizing: calculated: 11608B, actual: 11608B
+ * [0.192s][debug][gc,plab     ] GC(0) Young PLAB allocation: allocated: 2867184B, wasted: 656B, unused: 252896B, used: 2613632B, undo waste: 0B,
+ * [0.192s][debug][gc,plab     ] GC(0) Young other allocation: region end waste: 0B, regions filled: 3, num plab filled: 30, direct allocated: 16400B, num direct allocated: 1, failure used: 0B, failure wasted: 0B
+ * [0.192s][debug][gc,plab     ] GC(0) Young sizing: calculated: 522720B, actual: 522720B
+ * [0.192s][debug][gc,plab     ] GC(0) Old PLAB allocation: allocated: 0B, wasted: 0B, unused: 0B, used: 0B, undo waste: 0B,
+ * [0.192s][debug][gc,plab     ] GC(0) Old other allocation: region end waste: 0B, regions filled: 0, num plab filled: 0, direct allocated: 0B, num direct allocated: 0, failure used: 0B, failure wasted: 0B
+ * [0.192s][debug][gc,plab     ] GC(0) Old sizing: calculated: 0B, actual: 2064B
  */
 final public class LogParser {
 
@@ -62,7 +62,8 @@ public static enum ReportType {
     // GC ID
     private static final Pattern GC_ID_PATTERN = Pattern.compile("\\[gc,plab\\s*\\] GC\\((\\d+)\\)");
     // Pattern for extraction pair <name>: <numeric value>
-    private static final Pattern PAIRS_PATTERN = Pattern.compile("\\w* \\w+:\\s+\\d+");
+    // This is a non-zero set of words separated by spaces followed by ":" and a value.
+    private static final Pattern PAIRS_PATTERN = Pattern.compile("(?:\\w+ )*\\w+:\\s+\\d+");
 
     /**
      * Construct LogParser object, parse log file with PLAB statistics and store it into report.
@@ -119,7 +120,7 @@ private PlabReport parseLines() throws NumberFormatException {
                         do {
                             String pair = matcher.group();
                             String[] nameValue = pair.replaceAll(": ", ":").split(":");
-                            plabInfo.put(nameValue[0].trim(), Long.parseLong(nameValue[1]));
+                            plabInfo.put(nameValue[0], Long.parseLong(nameValue[1]));
                         } while (matcher.find());
                     }
                 }
@@ -194,7 +195,7 @@ private Map<Long, PlabInfo> getSpecifiedStats(List<Long> gcIds, LogParser.Report
                         getEntries().entryStream()
                         .filter(gcLogItem -> extractId == gcIds.contains(gcLogItem.getKey()))
                         .collect(Collectors.toMap(gcLogItem -> gcLogItem.getKey(),
-                                        gcLogItem -> gcLogItem.getValue().get(type).filter(fieldNames)
+                                                  gcLogItem -> gcLogItem.getValue().get(type).filter(fieldNames)
                                 )
                         )
                  );