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
--- 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);
}
}
}