8337031: Improvements to CompilationMemoryStatistic

Reviewed-by: kvn, stuefe
This commit is contained in:
Ashutosh Mehra 2024-07-31 01:36:37 +00:00
parent 1c6fef8f1c
commit e63d01654e
6 changed files with 154 additions and 97 deletions

View File

@ -51,29 +51,36 @@
#include "utilities/quickSort.hpp"
#include "utilities/resourceHash.hpp"
ArenaStatCounter::ArenaStatCounter() :
_current(0), _start(0), _peak(0),
_na(0), _ra(0),
_limit(0), _hit_limit(false), _limit_in_process(false),
_na_at_peak(0), _ra_at_peak(0), _live_nodes_at_peak(0)
{}
ArenaStatCounter::ArenaStatCounter() {
reset();
}
size_t ArenaStatCounter::peak_since_start() const {
return _peak > _start ? _peak - _start : 0;
void ArenaStatCounter::reset() {
_current = 0;
_peak = 0;
_current_by_tag.clear();
_peak_by_tag.clear();
_limit = 0;
_hit_limit = false;
_limit_in_process = false;
_live_nodes_at_peak = 0;
_active = false;
}
void ArenaStatCounter::start(size_t limit) {
_peak = _start = _current;
reset();
_active = true;
_limit = limit;
_hit_limit = false;
}
void ArenaStatCounter::end(){
void ArenaStatCounter::end() {
_limit = 0;
_hit_limit = false;
_active = false;
}
void ArenaStatCounter::update_c2_node_count() {
assert(_active, "compilaton has not yet started");
#ifdef COMPILER2
CompilerThread* const th = Thread::current()->as_Compiler_thread();
const CompileTask* const task = th->task();
@ -90,33 +97,27 @@ void ArenaStatCounter::update_c2_node_count() {
// Account an arena allocation or de-allocation.
bool ArenaStatCounter::account(ssize_t delta, int tag) {
assert(_active, "compilaton has not yet started");
bool rc = false;
#ifdef ASSERT
// Note: if this fires, we free more arena memory under the scope of the
// CompilationMemoryHistoryMark than we allocate. This cannot be since we
// assume arena allocations in CompilerThread to be stack bound and symmetric.
assert(delta >= 0 || ((ssize_t)_current + delta) >= 0,
"Negative overflow (d=%zd %zu %zu %zu)", delta, _current, _start, _peak);
"Negative overflow (d=%zd %zu %zu)", delta, _current, _peak);
#endif
// Update totals
_current += delta;
// Update detail counter
switch ((Arena::Tag)tag) {
case Arena::Tag::tag_ra: _ra += delta; break;
case Arena::Tag::tag_node: _na += delta; break;
default: // ignore
break;
};
_current_by_tag.add(tag, delta);
// Did we reach a peak?
if (_current > _peak) {
_peak = _current;
assert(delta > 0, "Sanity (%zu %zu %zu)", _current, _start, _peak);
_na_at_peak = _na;
_ra_at_peak = _ra;
assert(delta > 0, "Sanity (%zu %zu)", _current, _peak);
update_c2_node_count();
_peak_by_tag = _current_by_tag;
rc = true;
// Did we hit the memory limit?
if (!_hit_limit && _limit > 0 && peak_since_start() > _limit) {
if (!_hit_limit && _limit > 0 && _peak > _limit) {
_hit_limit = true;
}
}
@ -124,9 +125,15 @@ bool ArenaStatCounter::account(ssize_t delta, int tag) {
}
void ArenaStatCounter::print_on(outputStream* st) const {
st->print("%zu [na %zu ra %zu]", peak_since_start(), _na_at_peak, _ra_at_peak);
st->print("%zu [", _peak);
for (int tag = 0; tag < _peak_by_tag.element_count(); tag++) {
if (_peak_by_tag.counter(tag) > 0) {
st->print("%s %zu ", _peak_by_tag.tag_name(tag), _peak_by_tag.counter(tag));
}
}
st->print("]");
#ifdef ASSERT
st->print(" (%zu->%zu->%zu)", _start, _peak, _current);
st->print(" (%zu->%zu)", _peak, _current);
#endif
}
@ -186,10 +193,8 @@ class MemStatEntry : public CHeapObj<mtInternal> {
// peak usage, bytes, over all arenas
size_t _total;
// usage in node arena when total peaked
size_t _na_at_peak;
// usage in resource area when total peaked
size_t _ra_at_peak;
// usage per arena tag when total peaked
ArenaCountersByTag _peak_by_tag;
// number of nodes (c2 only) when total peaked
unsigned _live_nodes_at_peak;
const char* _result;
@ -199,8 +204,9 @@ public:
MemStatEntry(FullMethodName method)
: _method(method), _comptype(compiler_c1),
_time(0), _num_recomp(0), _thread(nullptr), _limit(0),
_total(0), _na_at_peak(0), _ra_at_peak(0), _live_nodes_at_peak(0),
_total(0), _live_nodes_at_peak(0),
_result(nullptr) {
_peak_by_tag.clear();
}
void set_comptype(CompilerType comptype) { _comptype = comptype; }
@ -210,8 +216,7 @@ public:
void inc_recompilation() { _num_recomp++; }
void set_total(size_t n) { _total = n; }
void set_na_at_peak(size_t n) { _na_at_peak = n; }
void set_ra_at_peak(size_t n) { _ra_at_peak = n; }
void set_peak_by_tag(ArenaCountersByTag peak_by_tag) { _peak_by_tag = peak_by_tag; }
void set_live_nodes_at_peak(unsigned n) { _live_nodes_at_peak = n; }
void set_result(const char* s) { _result = s; }
@ -219,21 +224,34 @@ public:
size_t total() const { return _total; }
static void print_legend(outputStream* st) {
#define LEGEND_KEY_FMT "%11s"
st->print_cr("Legend:");
st->print_cr(" total : memory allocated via arenas while compiling");
st->print_cr(" NA : ...how much in node arenas (if c2)");
st->print_cr(" RA : ...how much in resource areas");
st->print_cr(" result : Result: 'ok' finished successfully, 'oom' hit memory limit, 'err' compilation failed");
st->print_cr(" #nodes : ...how many nodes (c2 only)");
st->print_cr(" limit : memory limit, if set");
st->print_cr(" time : time of last compilation (sec)");
st->print_cr(" type : compiler type");
st->print_cr(" #rc : how often recompiled");
st->print_cr(" thread : compiler thread");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "total", "memory allocated via arenas while compiling");
for (int tag = 0; tag < Arena::tag_count(); tag++) {
st->print_cr(" " LEGEND_KEY_FMT ": %s", Arena::tag_name[tag], Arena::tag_desc[tag]);
}
st->print_cr(" " LEGEND_KEY_FMT ": %s", "result", "Result: 'ok' finished successfully, 'oom' hit memory limit, 'err' compilation failed");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "#nodes", "...how many nodes (c2 only)");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "limit", "memory limit, if set");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "time", "time taken for last compilation (sec)");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "type", "compiler type");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "#rc", "how often recompiled");
st->print_cr(" " LEGEND_KEY_FMT ": %s", "thread", "compiler thread");
#undef LEGEND_KEY_FMT
}
static void print_header(outputStream* st) {
st->print_cr("total NA RA result #nodes limit time type #rc thread method");
#define SIZE_FMT "%-10s"
st->print(SIZE_FMT, "total");
for (int tag = 0; tag < Arena::tag_count(); tag++) {
st->print(SIZE_FMT, Arena::tag_name[tag]);
}
#define HDR_FMT1 "%-8s%-8s%-8s%-8s"
#define HDR_FMT2 "%-6s%-4s%-19s%s"
st->print(HDR_FMT1, "result", "#nodes", "limit", "time");
st->print(HDR_FMT2, "type", "#rc", "thread", "method");
st->print_cr("");
}
void print_on(outputStream* st, bool human_readable) const {
@ -247,21 +265,14 @@ public:
}
col += 10; st->fill_to(col);
// NA
if (human_readable) {
st->print(PROPERFMT " ", PROPERFMTARGS(_na_at_peak));
} else {
st->print("%zu ", _na_at_peak);
for (int tag = 0; tag < Arena::tag_count(); tag++) {
if (human_readable) {
st->print(PROPERFMT " ", PROPERFMTARGS(_peak_by_tag.counter(tag)));
} else {
st->print("%zu ", _peak_by_tag.counter(tag));
}
col += 10; st->fill_to(col);
}
col += 10; st->fill_to(col);
// RA
if (human_readable) {
st->print(PROPERFMT " ", PROPERFMTARGS(_ra_at_peak));
} else {
st->print("%zu ", _ra_at_peak);
}
col += 10; st->fill_to(col);
// result?
st->print("%s ", _result ? _result : "");
@ -296,7 +307,7 @@ public:
col += 4; st->fill_to(col);
// Thread
st->print(PTR_FORMAT " ", p2i(_thread));
st->print(PTR_FORMAT " ", p2i(_thread));
// MethodName
char buf[1024];
@ -341,7 +352,7 @@ class MemStatTable :
public:
void add(const FullMethodName& fmn, CompilerType comptype,
size_t total, size_t na_at_peak, size_t ra_at_peak,
size_t total, ArenaCountersByTag peak_by_tag,
unsigned live_nodes_at_peak, size_t limit, const char* result) {
assert_lock_strong(NMTCompilationCostHistory_lock);
MemStatTableKey key(fmn, comptype);
@ -360,8 +371,7 @@ public:
e->set_comptype(comptype);
e->inc_recompilation();
e->set_total(total);
e->set_na_at_peak(na_at_peak);
e->set_ra_at_peak(ra_at_peak);
e->set_peak_by_tag(peak_by_tag);
e->set_live_nodes_at_peak(live_nodes_at_peak);
e->set_limit(limit);
e->set_result(result);
@ -427,7 +437,7 @@ void CompilationMemoryStatistic::on_end_compilation() {
const bool print = directive->should_print_memstat();
// Store memory used in task, for later processing by JFR
task->set_arena_bytes(arena_stat->peak_since_start());
task->set_arena_bytes(arena_stat->peak());
// Store result
// For this to work, we must call on_end_compilation() at a point where
@ -447,9 +457,8 @@ void CompilationMemoryStatistic::on_end_compilation() {
assert(_the_table != nullptr, "not initialized");
_the_table->add(fmn, ct,
arena_stat->peak_since_start(), // total
arena_stat->na_at_peak(),
arena_stat->ra_at_peak(),
arena_stat->peak(), // total
arena_stat->peak_by_tag(),
arena_stat->live_nodes_at_peak(),
arena_stat->limit(),
result);
@ -511,7 +520,7 @@ void CompilationMemoryStatistic::on_arena_change(ssize_t diff, const Arena* aren
bool hit_limit_before = arena_stat->hit_limit();
if (arena_stat->account(diff, (int)arena->get_tag())) { // new peak?
if (arena_stat->is_active() && arena_stat->account(diff, (int)arena->get_tag())) { // new peak?
// Limit handling
if (arena_stat->hit_limit()) {
@ -545,7 +554,7 @@ void CompilationMemoryStatistic::on_arena_change(ssize_t diff, const Arena* aren
}
ss.print("Hit MemLimit %s(limit: %zu now: %zu)",
(hit_limit_before ? "again " : ""),
arena_stat->limit(), arena_stat->peak_since_start());
arena_stat->limit(), arena_stat->peak());
}
// log if needed

View File

@ -29,48 +29,70 @@
#include "compiler/compilerDefinitions.hpp"
#include "memory/allocation.hpp"
#include "memory/allStatic.hpp"
#include "memory/arena.hpp"
#include "utilities/globalDefinitions.hpp"
class outputStream;
class Symbol;
class DirectiveSet;
// Counters for allocations from one arena
// Helper class to wrap the array of arena tags for easier processing
class ArenaCountersByTag {
private:
size_t _counter[Arena::tag_count()];
public:
int element_count() const { return Arena::tag_count(); }
const char* tag_name(int tag) const { return Arena::tag_name[tag]; }
size_t counter(int tag) const {
assert(tag < element_count(), "invalid tag %d", tag);
return _counter[tag];
}
void add(int tag, size_t value) {
assert(tag < element_count(), "invalid tag %d", tag);
_counter[tag] += value;
}
void clear() {
memset(_counter, 0, sizeof(size_t) * element_count());
}
};
// Counters for allocations from arenas during compilation
class ArenaStatCounter : public CHeapObj<mtCompiler> {
// Current bytes, total
size_t _current;
// bytes when compilation started
size_t _start;
// bytes at last peak, total
size_t _peak;
// Current bytes used for node arenas, total
size_t _na;
// Current bytes used for resource areas
size_t _ra;
// Current bytes used by arenas per tag
ArenaCountersByTag _current_by_tag;
// Peak composition:
ArenaCountersByTag _peak_by_tag;
// MemLimit handling
size_t _limit;
bool _hit_limit;
bool _limit_in_process;
// Peak composition:
// Size of node arena when total peaked (c2 only)
size_t _na_at_peak;
// Size of resource area when total peaked
size_t _ra_at_peak;
// When to start accounting
bool _active;
// Number of live nodes when total peaked (c2 only)
unsigned _live_nodes_at_peak;
void update_c2_node_count();
void reset();
public:
ArenaStatCounter();
// Size of peak since last compilation
size_t peak_since_start() const;
size_t peak() const { return _peak; }
// Peak details
size_t na_at_peak() const { return _na_at_peak; }
size_t ra_at_peak() const { return _ra_at_peak; }
ArenaCountersByTag peak_by_tag() const { return _peak_by_tag; }
unsigned live_nodes_at_peak() const { return _live_nodes_at_peak; }
// Mark the start and end of a compilation.
@ -89,7 +111,7 @@ public:
bool hit_limit() const { return _hit_limit; }
bool limit_in_process() const { return _limit_in_process; }
void set_limit_in_process(bool v) { _limit_in_process = v; }
bool is_active() const { return _active; }
};
class CompilationMemoryStatistic : public AllStatic {

View File

@ -44,6 +44,19 @@ STATIC_ASSERT(is_aligned((int)Chunk::init_size, ARENA_AMALLOC_ALIGNMENT));
STATIC_ASSERT(is_aligned((int)Chunk::medium_size, ARENA_AMALLOC_ALIGNMENT));
STATIC_ASSERT(is_aligned((int)Chunk::size, ARENA_AMALLOC_ALIGNMENT));
const char* Arena::tag_name[] = {
#define ARENA_TAG_STRING(name, str, desc) XSTR(name),
DO_ARENA_TAG(ARENA_TAG_STRING)
#undef ARENA_TAG_STRING
};
const char* Arena::tag_desc[] = {
#define ARENA_TAG_DESC(name, str, desc) XSTR(desc),
DO_ARENA_TAG(ARENA_TAG_DESC)
#undef ARENA_TAG_DESC
};
// MT-safe pool of same-sized chunks to reduce malloc/free thrashing
// NB: not using Mutex because pools are used before Threads are initialized
class ChunkPool {

View File

@ -83,17 +83,29 @@ public:
bool contains(char* p) const { return bottom() <= p && p <= top(); }
};
#define DO_ARENA_TAG(FN) \
FN(other, Others, Other arenas) \
FN(ra, RA, Resource areas) \
FN(ha, HA, Handle area) \
FN(node, NA, Node arena) \
// Fast allocation of memory
class Arena : public CHeapObjBase {
public:
enum class Tag : uint8_t {
tag_other = 0,
tag_ra, // resource area
tag_ha, // handle area
tag_node // C2 Node arena
enum class Tag: uint8_t {
#define ARENA_TAG_ENUM(name, str, desc) tag_##name,
DO_ARENA_TAG(ARENA_TAG_ENUM)
#undef ARENA_TAG_ENUM
tag_count
};
constexpr static int tag_count() {
return static_cast<int>(Tag::tag_count);
}
static const char* tag_name[static_cast<int>(Arena::Tag::tag_count)];
static const char* tag_desc[static_cast<int>(Arena::Tag::tag_count)];
private:
const MEMFLAGS _flags; // Memory tracking flags
const Tag _tag;

View File

@ -77,16 +77,17 @@ public class CompileCommandPrintMemStat {
// Should see final report
// Looks like this:
// total NA RA result #nodes limit time type #rc thread method
// 2149912 0 1986272 ok - - 0.101 c1 1 0x000000015180a600 jdk/internal/org/objectweb/asm/Frame::execute((IILjdk/internal/org/objectweb/asm/Symbol;Ljdk/internal/org/objectweb/asm/SymbolTable;)V) oa.shouldMatch("total.*method");
// total Others RA HA NA result #nodes limit time type #rc thread method
// 523648 32728 490920 0 0 ok - - 0.250 c1 1 0x00007f4ec00d4ac0 java/lang/Class::descriptorString(()Ljava/lang/String;)
// or
// 537784 98184 208536 ok 267 - 0.096 c2 1 0x0000000153019c00 jdk/internal/classfile/impl/BufWriterImpl::writeU1((I)V) 4521912 0 1986272 ok - - 0.101 c1 1 0x000000015180a600 jdk/internal/org/objectweb/asm/Frame::execute((IILjdk/internal/org/objectweb/asm/Symbol;Ljdk/internal/org/objectweb/asm/SymbolTable;)V) oa.shouldMatch("total.*method");
oa.shouldMatch("\\d+ +\\d+ +\\d+ +ok +(\\d+|-) +.*" + expectedNameIncl + ".*");
// 1898600 853176 750872 0 294552 ok 934 - 1.501 c2 1 0x00007f4ec00d3330 java/lang/String::replace((CC)Ljava/lang/String;)
oa.shouldMatch("total.*method");
oa.shouldMatch("\\d+ +(\\d+ +){4}ok +(\\d+|-) +.*" + expectedNameIncl + ".*");
// In debug builds, we have a default memory limit enabled. That implies MemStat. Therefore we
// expect to see all methods, not just the one we specified on the command line.
if (Platform.isDebugBuild()) {
oa.shouldMatch("\\d+ +\\d+ +\\d+ +ok +(\\d+|-) +.*" + expectedNameExcl + ".*");
oa.shouldMatch("\\d+ +(\\d+ +){4}ok +(\\d+|-) +.*" + expectedNameExcl + ".*");
} else {
oa.shouldNotMatch(".*" + expectedNameExcl + ".*");
}

View File

@ -47,9 +47,9 @@ public class CompilerMemoryStatisticTest {
out.shouldHaveExitValue(0);
// Looks like this:
// total NA RA result #nodes time type #rc thread method
// 211488 66440 77624 ok 13 0.057 c2 2 0x00007fb49428db70 compiler/print/CompileCommandPrintMemStat$TestMain::method1(()V)
// total Others RA HA NA result #nodes limit time type #rc thread method
// 1898600 853176 750872 0 294552 ok 934 - 1.501 c2 1 0x00007f4ec00d3330 java/lang/String::replace((CC)Ljava/lang/String;)
out.shouldMatch("total.*method");
out.shouldMatch("\\d+ +\\d+ +\\d+ +\\S+ +\\d+.*java.*\\(.*\\)");
out.shouldMatch("\\d+ +(\\d+ +){4}\\S+ +\\d+.*java.*\\(.*\\)");
}
}