8141141: Young and Old gen PLAB stats are similar in output with -XX:+PrintPLAB
authortschatzl
Wed, 02 Mar 2016 15:57:48 +0100
changeset 36390 a2d991d1d628
parent 36389 1df45f48022b
child 36391 3989ccd3f3de
8141141: Young and Old gen PLAB stats are similar in output with -XX:+PrintPLAB Summary: Improve PLAB statistic by adding generation, output values are now in bytes, including units, and split it into multiple messages. Reviewed-by: brutisso, sjohanss
hotspot/src/share/vm/gc/cms/parNewGeneration.cpp
hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
hotspot/src/share/vm/gc/g1/g1EvacStats.cpp
hotspot/src/share/vm/gc/g1/g1EvacStats.hpp
hotspot/src/share/vm/gc/shared/plab.cpp
hotspot/src/share/vm/gc/shared/plab.hpp
hotspot/test/gc/g1/TestPLABOutput.java
hotspot/test/gc/g1/plab/TestPLABPromotion.java
hotspot/test/gc/g1/plab/TestPLABResize.java
hotspot/test/gc/g1/plab/lib/LogParser.java
--- a/hotspot/src/share/vm/gc/cms/parNewGeneration.cpp	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/src/share/vm/gc/cms/parNewGeneration.cpp	Wed Mar 02 15:57:48 2016 +0100
@@ -615,7 +615,7 @@
   : DefNewGeneration(rs, initial_byte_size, "PCopy"),
   _overflow_list(NULL),
   _is_alive_closure(this),
-  _plab_stats(YoungPLABSize, PLABWeight)
+  _plab_stats("Young", YoungPLABSize, PLABWeight)
 {
   NOT_PRODUCT(_overflow_counter = ParGCWorkQueueOverflowInterval;)
   NOT_PRODUCT(_num_par_pushes = 0;)
@@ -1008,9 +1008,7 @@
   from()->set_concurrent_iteration_safe_limit(from()->top());
   to()->set_concurrent_iteration_safe_limit(to()->top());
 
-  if (ResizePLAB) {
-    plab_stats()->adjust_desired_plab_sz();
-  }
+  plab_stats()->adjust_desired_plab_sz();
 
   TASKQUEUE_STATS_ONLY(thread_state_set.print_termination_stats());
   TASKQUEUE_STATS_ONLY(thread_state_set.print_taskqueue_stats());
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Wed Mar 02 15:57:48 2016 +0100
@@ -1760,8 +1760,8 @@
   _young_list(new YoungList(this)),
   _gc_time_stamp(0),
   _summary_bytes_used(0),
-  _survivor_evac_stats(YoungPLABSize, PLABWeight),
-  _old_evac_stats(OldPLABSize, PLABWeight),
+  _survivor_evac_stats("Young", YoungPLABSize, PLABWeight),
+  _old_evac_stats("Old", OldPLABSize, PLABWeight),
   _expand_heap_after_alloc_failure(true),
   _old_marking_cycles_started(0),
   _old_marking_cycles_completed(0),
--- a/hotspot/src/share/vm/gc/g1/g1EvacStats.cpp	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1EvacStats.cpp	Wed Mar 02 15:57:48 2016 +0100
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2016, 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
@@ -29,15 +29,26 @@
 #include "logging/log.hpp"
 #include "trace/tracing.hpp"
 
+void G1EvacStats::log_plab_allocation() {
+  PLABStats::log_plab_allocation();
+  log_debug(gc, plab)("%s other allocation: "
+                      "region end waste: " SIZE_FORMAT "B, "
+                      "regions filled: %u, "
+                      "direct allocated: " SIZE_FORMAT "B, "
+                      "failure used: " SIZE_FORMAT "B, "
+                      "failure wasted: " SIZE_FORMAT "B",
+                      _description,
+                      _region_end_waste * HeapWordSize,
+                      _regions_filled,
+                      _direct_allocated * HeapWordSize,
+                      _failure_used * HeapWordSize,
+                      _failure_waste * HeapWordSize);
+}
+
 void G1EvacStats::adjust_desired_plab_sz() {
+  log_plab_allocation();
+
   if (!ResizePLAB) {
-    log_debug(gc, plab)(" (allocated = " SIZE_FORMAT " wasted = " SIZE_FORMAT " "
-                        "unused = " SIZE_FORMAT " used = " SIZE_FORMAT " "
-                        "undo_waste = " SIZE_FORMAT " region_end_waste = " SIZE_FORMAT " "
-                        "regions filled = %u direct_allocated = " SIZE_FORMAT " "
-                        "failure_used = " SIZE_FORMAT " failure_waste = " SIZE_FORMAT ") ",
-                        _allocated, _wasted, _unused, used(), _undo_wasted, _region_end_waste,
-                        _regions_filled, _direct_allocated, _failure_used, _failure_waste);
     // Clear accumulators for next round.
     reset();
     return;
@@ -107,18 +118,19 @@
   // Latch the result
   _desired_net_plab_sz = plab_sz;
 
-  log_debug(gc, plab)(" (allocated = " SIZE_FORMAT " wasted = " SIZE_FORMAT " "
-                      "unused = " SIZE_FORMAT " used = " SIZE_FORMAT " "
-                      "undo_waste = " SIZE_FORMAT " region_end_waste = " SIZE_FORMAT " "
-                      "regions filled = %u direct_allocated = " SIZE_FORMAT " "
-                      "failure_used = " SIZE_FORMAT " failure_waste = " SIZE_FORMAT ") "
-                      " (plab_sz = " SIZE_FORMAT " desired_plab_sz = " SIZE_FORMAT ")",
-                      _allocated, _wasted, _unused, used(), _undo_wasted, _region_end_waste,
-                      _regions_filled, _direct_allocated, _failure_used, _failure_waste,
-                      cur_plab_sz, plab_sz);
-
+  log_sizing(cur_plab_sz, plab_sz);
   // Clear accumulators for next round.
   reset();
 }
 
+G1EvacStats::G1EvacStats(const char* description, size_t desired_plab_sz_, unsigned wt) :
+  PLABStats(description, desired_plab_sz_, wt),
+  _region_end_waste(0),
+  _regions_filled(0),
+  _direct_allocated(0),
+  _failure_used(0),
+  _failure_waste(0) {
+}
+
+
 G1EvacStats::~G1EvacStats() { }
--- a/hotspot/src/share/vm/gc/g1/g1EvacStats.hpp	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1EvacStats.hpp	Wed Mar 02 15:57:48 2016 +0100
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2016, 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
@@ -51,20 +51,15 @@
     _failure_waste = 0;
   }
 
+  virtual void log_plab_allocation();
+
  public:
-  G1EvacStats(size_t desired_plab_sz_, unsigned wt) : PLABStats(desired_plab_sz_, wt),
-    _region_end_waste(0), _regions_filled(0), _direct_allocated(0),
-    _failure_used(0), _failure_waste(0) {
-  }
+  G1EvacStats(const char* description, size_t desired_plab_sz_, unsigned wt);
+
+  ~G1EvacStats();
 
   virtual void adjust_desired_plab_sz();
 
-  size_t allocated() const { return _allocated; }
-  size_t wasted() const { return _wasted; }
-  size_t unused() const { return _unused; }
-  size_t used() const { return allocated() - (wasted() + unused()); }
-  size_t undo_wasted() const { return _undo_wasted; }
-
   uint regions_filled() const { return _regions_filled; }
   size_t region_end_waste() const { return _region_end_waste; }
   size_t direct_allocated() const { return _direct_allocated; }
@@ -77,8 +72,6 @@
   inline void add_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);
-
-  ~G1EvacStats();
 };
 
 #endif // SHARE_VM_GC_G1_G1EVACSTATS_HPP
--- a/hotspot/src/share/vm/gc/shared/plab.cpp	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/src/share/vm/gc/shared/plab.cpp	Wed Mar 02 15:57:48 2016 +0100
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2001, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2001, 2016, 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
@@ -110,6 +110,30 @@
   }
 }
 
+void PLABStats::log_plab_allocation() {
+  log_debug(gc, plab)("%s PLAB allocation: "
+                      "allocated: " SIZE_FORMAT "B, "
+                      "wasted: " SIZE_FORMAT "B, "
+                      "unused: " SIZE_FORMAT "B, "
+                      "used: " SIZE_FORMAT "B, "
+                      "undo waste: " SIZE_FORMAT "B, ",
+                      _description,
+                      _allocated * HeapWordSize,
+                      _wasted * HeapWordSize,
+                      _unused * HeapWordSize,
+                      used() * HeapWordSize,
+                      _undo_wasted * HeapWordSize);
+}
+
+void PLABStats::log_sizing(size_t calculated_words, size_t net_desired_words) {
+  log_debug(gc, plab)("%s sizing: "
+                      "calculated: " SIZE_FORMAT "B, "
+                      "actual: " SIZE_FORMAT "B",
+                      _description,
+                      calculated_words * HeapWordSize,
+                      net_desired_words * HeapWordSize);
+}
+
 // Calculates plab size for current number of gc worker threads.
 size_t PLABStats::desired_plab_sz(uint no_of_gc_workers) {
   return MAX2(min_size(), (size_t)align_object_size(_desired_net_plab_sz / no_of_gc_workers));
@@ -119,7 +143,13 @@
 // use. This should be called once at the end of parallel
 // scavenge; it clears the sensor accumulators.
 void PLABStats::adjust_desired_plab_sz() {
-  assert(ResizePLAB, "Not set");
+  log_plab_allocation();
+
+  if (!ResizePLAB) {
+    // Clear accumulators for next round.
+    reset();
+    return;
+  }
 
   assert(is_object_aligned(max_size()) && min_size() <= max_size(),
          "PLAB clipping computation may be incorrect");
@@ -150,8 +180,9 @@
   new_plab_sz = MIN2(max_size(), new_plab_sz);
   new_plab_sz = align_object_size(new_plab_sz);
   // Latch the result
-  log_trace(gc, plab)("plab_size = " SIZE_FORMAT " desired_net_plab_sz = " SIZE_FORMAT ") ", recent_plab_sz, new_plab_sz);
   _desired_net_plab_sz = new_plab_sz;
 
+  log_sizing(recent_plab_sz, new_plab_sz);
+
   reset();
 }
--- a/hotspot/src/share/vm/gc/shared/plab.hpp	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/src/share/vm/gc/shared/plab.hpp	Wed Mar 02 15:57:48 2016 +0100
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2001, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2001, 2016, 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
@@ -146,6 +146,8 @@
 // PLAB book-keeping.
 class PLABStats : public CHeapObj<mtGC> {
  protected:
+  const char* _description;   // Identifying string.
+
   size_t _allocated;          // Total allocated
   size_t _wasted;             // of which wasted (internal fragmentation)
   size_t _undo_wasted;        // of which wasted on undo (is not used for calculation of PLAB size)
@@ -160,8 +162,12 @@
     _undo_wasted = 0;
     _unused      = 0;
   }
+
+  virtual void log_plab_allocation();
+  virtual void log_sizing(size_t calculated, size_t net_desired);
  public:
-  PLABStats(size_t desired_net_plab_sz_, unsigned wt) :
+  PLABStats(const char* description, size_t desired_net_plab_sz_, unsigned wt) :
+    _description(description),
     _allocated(0),
     _wasted(0),
     _undo_wasted(0),
@@ -172,6 +178,12 @@
 
   virtual ~PLABStats() { }
 
+  size_t allocated() const { return _allocated; }
+  size_t wasted() const { return _wasted; }
+  size_t unused() const { return _unused; }
+  size_t used() const { return allocated() - (wasted() + unused()); }
+  size_t undo_wasted() const { return _undo_wasted; }
+
   static const size_t min_size() {
     return PLAB::min_size();
   }
--- a/hotspot/test/gc/g1/TestPLABOutput.java	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/test/gc/g1/TestPLABOutput.java	Wed Mar 02 15:57:48 2016 +0100
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 2016, 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
@@ -65,7 +65,7 @@
 
         System.out.println(output.getStdout());
 
-        String pattern = ".*GC\\(0\\) .*allocated = (\\d+).*";
+        String pattern = ".*GC\\(0\\) .*allocated: (\\d+).*";
         Pattern r = Pattern.compile(pattern);
         Matcher m = r.matcher(output.getStdout());
 
--- a/hotspot/test/gc/g1/plab/TestPLABPromotion.java	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/test/gc/g1/plab/TestPLABPromotion.java	Wed Mar 02 15:57:48 2016 +0100
@@ -23,7 +23,7 @@
 
  /*
  * @test TestPLABPromotion
- * @bug 8141278
+ * @bug 8141278 8141141
  * @summary Test PLAB promotion
  * @requires vm.gc=="G1" | vm.gc=="null"
  * @requires vm.opt.FlightRecorder != true
@@ -130,16 +130,15 @@
         long plabAllocatedOld;
         long directAllocatedOld;
         long memAllocated = testCase.getMemToFill();
-        long wordSize = Platform.is32bit() ? 4l : 8l;
         LogParser logParser = new LogParser(output);
 
         Map<String, Long> survivorStats = getPlabStats(logParser, LogParser.ReportType.SURVIVOR_STATS, GC_ID_SURVIVOR_STATS);
         Map<String, Long> oldStats = getPlabStats(logParser, LogParser.ReportType.OLD_STATS, GC_ID_OLD_STATS);
 
-        plabAllocatedSurvivor = wordSize * survivorStats.get("used");
-        directAllocatedSurvivor = wordSize * survivorStats.get("direct_allocated");
-        plabAllocatedOld = wordSize * oldStats.get("used");
-        directAllocatedOld = wordSize * oldStats.get("direct_allocated");
+        plabAllocatedSurvivor = survivorStats.get("used");
+        directAllocatedSurvivor = survivorStats.get("direct allocated");
+        plabAllocatedOld = oldStats.get("used");
+        directAllocatedOld = oldStats.get("direct allocated");
 
         System.out.printf("Survivor PLAB allocated:%17d Direct allocated: %17d Mem consumed:%17d%n", plabAllocatedSurvivor, directAllocatedSurvivor, memAllocated);
         System.out.printf("Old      PLAB allocated:%17d Direct allocated: %17d Mem consumed:%17d%n", plabAllocatedOld, directAllocatedOld, memAllocated);
--- a/hotspot/test/gc/g1/plab/TestPLABResize.java	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/test/gc/g1/plab/TestPLABResize.java	Wed Mar 02 15:57:48 2016 +0100
@@ -23,7 +23,7 @@
 
  /*
  * @test TestPLABResize
- * @bug 8141278
+ * @bug 8141278 8141141
  * @summary Test for PLAB resizing
  * @requires vm.gc=="G1" | vm.gc=="null"
  * @requires vm.opt.FlightRecorder != true
@@ -117,7 +117,7 @@
                 .map(item -> {
                     return item.getValue()
                             .get(LogParser.ReportType.SURVIVOR_STATS)
-                            .get("desired_plab_sz");
+                            .get("actual");
                 })
                 .collect(Collectors.toCollection(ArrayList::new));
 
--- a/hotspot/test/gc/g1/plab/lib/LogParser.java	Wed Mar 02 15:55:47 2016 +0100
+++ b/hotspot/test/gc/g1/plab/lib/LogParser.java	Wed Mar 02 15:57:48 2016 +0100
@@ -35,14 +35,12 @@
  *
  * Typical GC log with PLAB statistics (options - -Xlog:gc=debug,gc+plab=debug) looks like:
  *
- * [2,244s][info   ][gc     ] GC(30) Concurrent Mark abort
- * [2,245s][debug  ][gc,plab] GC(33)  (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 0 failure_waste = 0)  (plab_sz = 0 desired_plab_sz = 258)
- * [2,245s][debug  ][gc,plab] GC(33)  (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 0 failure_waste = 0)  (plab_sz = 0 desired_plab_sz = 258)
- * [2,245s][info   ][gc     ] GC(33) Pause Young (G1 Evacuation Pause) 127M->127M(128M) (2,244s, 2,245s) 0,899ms
- * [2,246s][debug  ][gc,plab] GC(34)  (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 0 failure_waste = 0)  (plab_sz = 0 desired_plab_sz = 258)
- * [2,246s][debug  ][gc,plab] GC(34)  (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 0 failure_waste = 0)  (plab_sz = 0 desired_plab_sz = 258)
- * [2,246s][info   ][gc     ] GC(34) Pause Initial Mark (G1 Evacuation Pause) 127M->127M(128M) (2,245s, 2,246s) 0,907ms
-
+ * [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
  */
 final public class LogParser {
 
@@ -53,7 +51,6 @@
      * Type of parsed log element.
      */
     public static enum ReportType {
-
         SURVIVOR_STATS,
         OLD_STATS
     }
@@ -64,8 +61,8 @@
 
     // 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+\\s+=\\s+\\d+");
+    // Pattern for extraction pair <name>: <numeric value>
+    private static final Pattern PAIRS_PATTERN = Pattern.compile("\\w* \\w+:\\s+\\d+");
 
     /**
      * Construct LogParser Object
@@ -108,24 +105,29 @@
                 if (matcher.find()) {
                     Map<ReportType,Map<String, Long>> oneReportItem;
                     ReportType reportType;
-                    // Second line in log is statistics for Old PLAB allocation
-                    if ( !allocationStatistics.containsKey(gc_id.get()) ) {
-                        oneReportItem = new EnumMap<>(ReportType.class);
+
+                    if (!allocationStatistics.containsKey(gc_id.get())) {
+                      allocationStatistics.put(gc_id.get(), new EnumMap<>(ReportType.class));
+                    }
+
+                    if ( line.contains("Young") ) {
                         reportType = ReportType.SURVIVOR_STATS;
-                        allocationStatistics.put(gc_id.get(), oneReportItem);
                     } else {
-                        oneReportItem = allocationStatistics.get(gc_id.get());
                         reportType = ReportType.OLD_STATS;
                     }
 
+                    oneReportItem = allocationStatistics.get(gc_id.get());
+                    if (!oneReportItem.containsKey(reportType)) {
+                      oneReportItem.put(reportType,new HashMap<String, Long>());
+                    }
+
                     // Extract all pairs from log.
-                    HashMap<String, Long> plabStats = new HashMap<>();
+                    Map<String, Long> plabStats = oneReportItem.get(reportType);
                     do {
                         String pair = matcher.group();
-                        String[] nameValue = pair.replaceAll(" ", "").split("=");
-                        plabStats.put(nameValue[0], Long.parseLong(nameValue[1]));
+                        String[] nameValue = pair.replaceAll(": ", ":").split(":");
+                        plabStats.put(nameValue[0].trim(), Long.parseLong(nameValue[1]));
                     } while (matcher.find());
-                    oneReportItem.put(reportType,plabStats);
                 }
             }
         }