stan/jdk-24
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

8159974: G1 String deduplication logging not aligned with the rest of G1

Browse Source 
Reviewed-by: stefank, tschatzl
This commit is contained in:
Per Lidén 2016-07-04 11:27:11 +02:00
parent a1dcb34cdc
commit 3ad9aa0f10
6 changed files with 88 additions and 57 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
hotspot/src/share/vm/gc/g1/g1StringDedupQueue.cpp
View File

@ -1,5 +1,5 @@
/* /*
* Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved. * Copyright (c) 2014, 2016, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
* *
* This code is free software; you can redistribute it and/or modify it * This code is free software; you can redistribute it and/or modify it
@ -154,8 +154,8 @@ void G1StringDedupQueue::unlink_or_oops_do(G1StringDedupUnlinkOrOopsDoClosure* c
} }
void G1StringDedupQueue::print_statistics() { void G1StringDedupQueue::print_statistics() {
log_debug(gc, stringdedup)(" [Queue]"); log_debug(gc, stringdedup)(" Queue");
log_debug(gc, stringdedup)(" [Dropped: " UINTX_FORMAT "]", _queue->_dropped); log_debug(gc, stringdedup)(" Dropped: " UINTX_FORMAT, _queue->_dropped);
} }
void G1StringDedupQueue::verify() { void G1StringDedupQueue::verify() {

55
hotspot/src/share/vm/gc/g1/g1StringDedupStat.cpp
View File

@ -1,5 +1,5 @@
/* /*
* Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved. * Copyright (c) 2014, 2016, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
* *
* This code is free software; you can redistribute it and/or modify it * This code is free software; you can redistribute it and/or modify it
@ -42,7 +42,9 @@ G1StringDedupStat::G1StringDedupStat() :
_idle(0), _idle(0),
_exec(0), _exec(0),
_block(0), _block(0),
_start(0.0), _start_concurrent(0.0),
_end_concurrent(0.0),
_start_phase(0.0),
_idle_elapsed(0.0), _idle_elapsed(0.0),
_exec_elapsed(0.0), _exec_elapsed(0.0),
_block_elapsed(0.0) { _block_elapsed(0.0) {
@ -69,7 +71,13 @@ void G1StringDedupStat::add(const G1StringDedupStat& stat) {
_block_elapsed += stat._block_elapsed; _block_elapsed += stat._block_elapsed;
} }
void G1StringDedupStat::print_summary(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat) { void G1StringDedupStat::print_start(const G1StringDedupStat& last_stat) {
log_info(gc, stringdedup)(
"Concurrent String Deduplication (" G1_STRDEDUP_TIME_FORMAT ")",
G1_STRDEDUP_TIME_PARAM(last_stat._start_concurrent));
}
void G1StringDedupStat::print_end(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat) {
double total_deduped_bytes_percent = 0.0; double total_deduped_bytes_percent = 0.0;
if (total_stat._new_bytes > 0) { if (total_stat._new_bytes > 0) {
@ -79,13 +87,16 @@ void G1StringDedupStat::print_summary(const G1StringDedupStat& last_stat, const
log_info(gc, stringdedup)( log_info(gc, stringdedup)(
"Concurrent String Deduplication " "Concurrent String Deduplication "
G1_STRDEDUP_BYTES_FORMAT_NS "->" G1_STRDEDUP_BYTES_FORMAT_NS "(" G1_STRDEDUP_BYTES_FORMAT_NS "), avg " G1_STRDEDUP_BYTES_FORMAT_NS "->" G1_STRDEDUP_BYTES_FORMAT_NS "(" G1_STRDEDUP_BYTES_FORMAT_NS ") "
G1_STRDEDUP_PERCENT_FORMAT_NS ", " G1_STRDEDUP_TIME_FORMAT, "avg " G1_STRDEDUP_PERCENT_FORMAT_NS " "
"(" G1_STRDEDUP_TIME_FORMAT ", " G1_STRDEDUP_TIME_FORMAT ") " G1_STRDEDUP_TIME_FORMAT_MS,
G1_STRDEDUP_BYTES_PARAM(last_stat._new_bytes), G1_STRDEDUP_BYTES_PARAM(last_stat._new_bytes),
G1_STRDEDUP_BYTES_PARAM(last_stat._new_bytes - last_stat._deduped_bytes), G1_STRDEDUP_BYTES_PARAM(last_stat._new_bytes - last_stat._deduped_bytes),
G1_STRDEDUP_BYTES_PARAM(last_stat._deduped_bytes), G1_STRDEDUP_BYTES_PARAM(last_stat._deduped_bytes),
total_deduped_bytes_percent, total_deduped_bytes_percent,
last_stat._exec_elapsed); G1_STRDEDUP_TIME_PARAM(last_stat._start_concurrent),
G1_STRDEDUP_TIME_PARAM(last_stat._end_concurrent),
G1_STRDEDUP_TIME_PARAM_MS(last_stat._exec_elapsed));
} }
void G1StringDedupStat::print_statistics(const G1StringDedupStat& stat, bool total) { void G1StringDedupStat::print_statistics(const G1StringDedupStat& stat, bool total) {
@ -134,23 +145,31 @@ void G1StringDedupStat::print_statistics(const G1StringDedupStat& stat, bool tot
if (total) { if (total) {
log_debug(gc, stringdedup)( log_debug(gc, stringdedup)(
" [Total Exec: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT ", Idle: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT ", Blocked: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT "]", " Total Exec: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT_MS
stat._exec, stat._exec_elapsed, stat._idle, stat._idle_elapsed, stat._block, stat._block_elapsed); ", Idle: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT_MS
", Blocked: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT_MS,
stat._exec, G1_STRDEDUP_TIME_PARAM_MS(stat._exec_elapsed),
stat._idle, G1_STRDEDUP_TIME_PARAM_MS(stat._idle_elapsed),
stat._block, G1_STRDEDUP_TIME_PARAM_MS(stat._block_elapsed));
} else { } else {
log_debug(gc, stringdedup)( log_debug(gc, stringdedup)(
" [Last Exec: " G1_STRDEDUP_TIME_FORMAT ", Idle: " G1_STRDEDUP_TIME_FORMAT ", Blocked: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT "]", " Last Exec: " G1_STRDEDUP_TIME_FORMAT_MS
stat._exec_elapsed, stat._idle_elapsed, stat._block, stat._block_elapsed); ", Idle: " G1_STRDEDUP_TIME_FORMAT_MS
", Blocked: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT_MS,
G1_STRDEDUP_TIME_PARAM_MS(stat._exec_elapsed),
G1_STRDEDUP_TIME_PARAM_MS(stat._idle_elapsed),
stat._block, G1_STRDEDUP_TIME_PARAM_MS(stat._block_elapsed));
} }
log_debug(gc, stringdedup)(" [Inspected: " G1_STRDEDUP_OBJECTS_FORMAT "]", stat._inspected); log_debug(gc, stringdedup)(" Inspected: " G1_STRDEDUP_OBJECTS_FORMAT, stat._inspected);
log_debug(gc, stringdedup)(" [Skipped: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")]", stat._skipped, skipped_percent); log_debug(gc, stringdedup)(" Skipped: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")", stat._skipped, skipped_percent);
log_debug(gc, stringdedup)(" [Hashed: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")]", stat._hashed, hashed_percent); log_debug(gc, stringdedup)(" Hashed: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")", stat._hashed, hashed_percent);
log_debug(gc, stringdedup)(" [Known: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")]", stat._known, known_percent); log_debug(gc, stringdedup)(" Known: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")", stat._known, known_percent);
log_debug(gc, stringdedup)(" [New: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "]", log_debug(gc, stringdedup)(" New: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT,
stat._new, new_percent, G1_STRDEDUP_BYTES_PARAM(stat._new_bytes)); stat._new, new_percent, G1_STRDEDUP_BYTES_PARAM(stat._new_bytes));
log_debug(gc, stringdedup)(" [Deduplicated: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")]", log_debug(gc, stringdedup)(" Deduplicated: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")",
stat._deduped, deduped_percent, G1_STRDEDUP_BYTES_PARAM(stat._deduped_bytes), deduped_bytes_percent); stat._deduped, deduped_percent, G1_STRDEDUP_BYTES_PARAM(stat._deduped_bytes), deduped_bytes_percent);
log_debug(gc, stringdedup)(" [Young: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")]", log_debug(gc, stringdedup)(" Young: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")",
stat._deduped_young, deduped_young_percent, G1_STRDEDUP_BYTES_PARAM(stat._deduped_young_bytes), deduped_young_bytes_percent); stat._deduped_young, deduped_young_percent, G1_STRDEDUP_BYTES_PARAM(stat._deduped_young_bytes), deduped_young_bytes_percent);
log_debug(gc, stringdedup)(" [Old: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")]", log_debug(gc, stringdedup)(" Old: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ")",
stat._deduped_old, deduped_old_percent, G1_STRDEDUP_BYTES_PARAM(stat._deduped_old_bytes), deduped_old_bytes_percent); stat._deduped_old, deduped_old_percent, G1_STRDEDUP_BYTES_PARAM(stat._deduped_old_bytes), deduped_old_bytes_percent);
} }

40
hotspot/src/share/vm/gc/g1/g1StringDedupStat.hpp
View File

@ -1,5 +1,5 @@
/* /*
* Copyright (c) 2014, 2015, Oracle and/or its affiliates. All rights reserved. * Copyright (c) 2014, 2016, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
* *
* This code is free software; you can redistribute it and/or modify it * This code is free software; you can redistribute it and/or modify it
@ -30,11 +30,14 @@
// Macros for GC log output formating // Macros for GC log output formating
#define G1_STRDEDUP_OBJECTS_FORMAT UINTX_FORMAT_W(12) #define G1_STRDEDUP_OBJECTS_FORMAT UINTX_FORMAT_W(12)
#define G1_STRDEDUP_TIME_FORMAT "%1.7lf secs" #define G1_STRDEDUP_TIME_FORMAT "%.3fs"
#define G1_STRDEDUP_PERCENT_FORMAT "%5.1lf%%" #define G1_STRDEDUP_TIME_PARAM(time) (time)
#define G1_STRDEDUP_PERCENT_FORMAT_NS "%.1lf%%" #define G1_STRDEDUP_TIME_FORMAT_MS "%.3fms"
#define G1_STRDEDUP_BYTES_FORMAT "%8.1lf%s" #define G1_STRDEDUP_TIME_PARAM_MS(time) ((time) * MILLIUNITS)
#define G1_STRDEDUP_BYTES_FORMAT_NS "%.1lf%s" #define G1_STRDEDUP_PERCENT_FORMAT "%5.1f%%"
#define G1_STRDEDUP_PERCENT_FORMAT_NS "%.1f%%"
#define G1_STRDEDUP_BYTES_FORMAT "%8.1f%s"
#define G1_STRDEDUP_BYTES_FORMAT_NS "%.1f%s"
#define G1_STRDEDUP_BYTES_PARAM(bytes) byte_size_in_proper_unit((double)(bytes)), proper_unit_for_byte_size((bytes)) #define G1_STRDEDUP_BYTES_PARAM(bytes) byte_size_in_proper_unit((double)(bytes)), proper_unit_for_byte_size((bytes))
// //
@ -60,7 +63,9 @@ private:
uintx _block; uintx _block;
// Time spent by the deduplication thread in different phases // Time spent by the deduplication thread in different phases
double _start; double _start_concurrent;
double _end_concurrent;
double _start_phase;
double _idle_elapsed; double _idle_elapsed;
double _exec_elapsed; double _exec_elapsed;
double _block_elapsed; double _block_elapsed;
@ -104,38 +109,41 @@ public:
} }
void mark_idle() { void mark_idle() {
_start = os::elapsedTime(); _start_phase = os::elapsedTime();
_idle++; _idle++;
} }
void mark_exec() { void mark_exec() {
double now = os::elapsedTime(); double now = os::elapsedTime();
_idle_elapsed = now - _start; _idle_elapsed = now - _start_phase;
_start = now; _start_phase = now;
_start_concurrent = now;
_exec++; _exec++;
} }
void mark_block() { void mark_block() {
double now = os::elapsedTime(); double now = os::elapsedTime();
_exec_elapsed += now - _start; _exec_elapsed += now - _start_phase;
_start = now; _start_phase = now;
_block++; _block++;
} }
void mark_unblock() { void mark_unblock() {
double now = os::elapsedTime(); double now = os::elapsedTime();
_block_elapsed += now - _start; _block_elapsed += now - _start_phase;
_start = now; _start_phase = now;
} }
void mark_done() { void mark_done() {
double now = os::elapsedTime(); double now = os::elapsedTime();
_exec_elapsed += now - _start; _exec_elapsed += now - _start_phase;
_end_concurrent = now;
} }
void add(const G1StringDedupStat& stat); void add(const G1StringDedupStat& stat);
static void print_summary(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat); static void print_start(const G1StringDedupStat& last_stat);
static void print_end(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat);
static void print_statistics(const G1StringDedupStat& stat, bool total); static void print_statistics(const G1StringDedupStat& stat, bool total);
}; };

17
hotspot/src/share/vm/gc/g1/g1StringDedupTable.cpp
View File

@ -196,7 +196,8 @@ void G1StringDedupEntryCache::delete_overflowed() {
} }
double end = os::elapsedTime(); double end = os::elapsedTime();
log_trace(gc, stringdedup)("Deleted " UINTX_FORMAT " entries, " G1_STRDEDUP_TIME_FORMAT, count, end - start); log_trace(gc, stringdedup)("Deleted " UINTX_FORMAT " entries, " G1_STRDEDUP_TIME_FORMAT_MS,
count, G1_STRDEDUP_TIME_PARAM_MS(end - start));
} }
G1StringDedupTable* G1StringDedupTable::_table = NULL; G1StringDedupTable* G1StringDedupTable::_table = NULL;
@ -610,14 +611,14 @@ void G1StringDedupTable::clean_entry_cache() {
void G1StringDedupTable::print_statistics() { void G1StringDedupTable::print_statistics() {
Log(gc, stringdedup) log; Log(gc, stringdedup) log;
log.debug(" [Table]"); log.debug(" Table");
log.debug(" [Memory Usage: " G1_STRDEDUP_BYTES_FORMAT_NS "]", log.debug(" Memory Usage: " G1_STRDEDUP_BYTES_FORMAT_NS,
G1_STRDEDUP_BYTES_PARAM(_table->_size * sizeof(G1StringDedupEntry*) + (_table->_entries + _entry_cache->size()) * sizeof(G1StringDedupEntry))); G1_STRDEDUP_BYTES_PARAM(_table->_size * sizeof(G1StringDedupEntry*) + (_table->_entries + _entry_cache->size()) * sizeof(G1StringDedupEntry)));
log.debug(" [Size: " SIZE_FORMAT ", Min: " SIZE_FORMAT ", Max: " SIZE_FORMAT "]", _table->_size, _min_size, _max_size); log.debug(" Size: " SIZE_FORMAT ", Min: " SIZE_FORMAT ", Max: " SIZE_FORMAT, _table->_size, _min_size, _max_size);
log.debug(" [Entries: " UINTX_FORMAT ", Load: " G1_STRDEDUP_PERCENT_FORMAT_NS ", Cached: " UINTX_FORMAT ", Added: " UINTX_FORMAT ", Removed: " UINTX_FORMAT "]", log.debug(" Entries: " UINTX_FORMAT ", Load: " G1_STRDEDUP_PERCENT_FORMAT_NS ", Cached: " UINTX_FORMAT ", Added: " UINTX_FORMAT ", Removed: " UINTX_FORMAT,
_table->_entries, (double)_table->_entries / (double)_table->_size * 100.0, _entry_cache->size(), _entries_added, _entries_removed); _table->_entries, (double)_table->_entries / (double)_table->_size * 100.0, _entry_cache->size(), _entries_added, _entries_removed);
log.debug(" [Resize Count: " UINTX_FORMAT ", Shrink Threshold: " UINTX_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT_NS "), Grow Threshold: " UINTX_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT_NS ")]", log.debug(" Resize Count: " UINTX_FORMAT ", Shrink Threshold: " UINTX_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT_NS "), Grow Threshold: " UINTX_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT_NS ")",
_resize_count, _table->_shrink_threshold, _shrink_load_factor * 100.0, _table->_grow_threshold, _grow_load_factor * 100.0); _resize_count, _table->_shrink_threshold, _shrink_load_factor * 100.0, _table->_grow_threshold, _grow_load_factor * 100.0);
log.debug(" [Rehash Count: " UINTX_FORMAT ", Rehash Threshold: " UINTX_FORMAT ", Hash Seed: 0x%x]", _rehash_count, _rehash_threshold, _table->_hash_seed); log.debug(" Rehash Count: " UINTX_FORMAT ", Rehash Threshold: " UINTX_FORMAT ", Hash Seed: 0x%x", _rehash_count, _rehash_threshold, _table->_hash_seed);
log.debug(" [Age Threshold: " UINTX_FORMAT "]", StringDeduplicationAgeThreshold); log.debug(" Age Threshold: " UINTX_FORMAT, StringDeduplicationAgeThreshold);
} }

14
hotspot/src/share/vm/gc/g1/g1StringDedupThread.cpp
View File

@ -103,6 +103,7 @@ void G1StringDedupThread::run_service() {
SuspendibleThreadSetJoiner sts_join; SuspendibleThreadSetJoiner sts_join;
stat.mark_exec(); stat.mark_exec();
print_start(stat);
// Process the queue // Process the queue
for (;;) { for (;;) {
@ -123,9 +124,8 @@ void G1StringDedupThread::run_service() {
stat.mark_done(); stat.mark_done();
// Print statistics
total_stat.add(stat); total_stat.add(stat);
print(stat, total_stat); print_end(stat, total_stat);
} }
G1StringDedupTable::clean_entry_cache(); G1StringDedupTable::clean_entry_cache();
@ -136,9 +136,12 @@ void G1StringDedupThread::stop_service() {
G1StringDedupQueue::cancel_wait(); G1StringDedupQueue::cancel_wait();
} }
void G1StringDedupThread::print(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat) { void G1StringDedupThread::print_start(const G1StringDedupStat& last_stat) {
if (log_is_enabled(Info, gc, stringdedup)) { G1StringDedupStat::print_start(last_stat);
G1StringDedupStat::print_summary(last_stat, total_stat); }
void G1StringDedupThread::print_end(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat) {
G1StringDedupStat::print_end(last_stat, total_stat);
if (log_is_enabled(Debug, gc, stringdedup)) { if (log_is_enabled(Debug, gc, stringdedup)) {
G1StringDedupStat::print_statistics(last_stat, false); G1StringDedupStat::print_statistics(last_stat, false);
G1StringDedupStat::print_statistics(total_stat, true); G1StringDedupStat::print_statistics(total_stat, true);
@ -146,4 +149,3 @@ void G1StringDedupThread::print(const G1StringDedupStat& last_stat, const G1Stri
G1StringDedupQueue::print_statistics(); G1StringDedupQueue::print_statistics();
} }
} }
}

3
hotspot/src/share/vm/gc/g1/g1StringDedupThread.hpp
View File

@ -43,7 +43,8 @@ private:
G1StringDedupThread(); G1StringDedupThread();
~G1StringDedupThread(); ~G1StringDedupThread();
void print(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat); void print_start(const G1StringDedupStat& last_stat);
void print_end(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat);
void run_service(); void run_service();
void stop_service(); void stop_service();