8159974: G1 String deduplication logging not aligned with the rest of G1
Reviewed-by: stefank, tschatzl
--- a/hotspot/src/share/vm/gc/g1/g1StringDedupQueue.cpp Sat Jul 02 00:26:51 2016 +0000
+++ b/hotspot/src/share/vm/gc/g1/g1StringDedupQueue.cpp Mon Jul 04 11:27:11 2016 +0200
@@ -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.
*
* This code is free software; you can redistribute it and/or modify it
@@ -154,8 +154,8 @@
}
void G1StringDedupQueue::print_statistics() {
- log_debug(gc, stringdedup)(" [Queue]");
- log_debug(gc, stringdedup)(" [Dropped: " UINTX_FORMAT "]", _queue->_dropped);
+ log_debug(gc, stringdedup)(" Queue");
+ log_debug(gc, stringdedup)(" Dropped: " UINTX_FORMAT, _queue->_dropped);
}
void G1StringDedupQueue::verify() {
--- a/hotspot/src/share/vm/gc/g1/g1StringDedupStat.cpp Sat Jul 02 00:26:51 2016 +0000
+++ b/hotspot/src/share/vm/gc/g1/g1StringDedupStat.cpp Mon Jul 04 11:27:11 2016 +0200
@@ -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.
*
* This code is free software; you can redistribute it and/or modify it
@@ -42,7 +42,9 @@
_idle(0),
_exec(0),
_block(0),
- _start(0.0),
+ _start_concurrent(0.0),
+ _end_concurrent(0.0),
+ _start_phase(0.0),
_idle_elapsed(0.0),
_exec_elapsed(0.0),
_block_elapsed(0.0) {
@@ -69,7 +71,13 @@
_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;
if (total_stat._new_bytes > 0) {
@@ -79,13 +87,16 @@
log_info(gc, stringdedup)(
"Concurrent String Deduplication "
- G1_STRDEDUP_BYTES_FORMAT_NS "->" G1_STRDEDUP_BYTES_FORMAT_NS "(" G1_STRDEDUP_BYTES_FORMAT_NS "), avg "
- G1_STRDEDUP_PERCENT_FORMAT_NS ", " G1_STRDEDUP_TIME_FORMAT,
+ G1_STRDEDUP_BYTES_FORMAT_NS "->" G1_STRDEDUP_BYTES_FORMAT_NS "(" G1_STRDEDUP_BYTES_FORMAT_NS ") "
+ "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 - last_stat._deduped_bytes),
G1_STRDEDUP_BYTES_PARAM(last_stat._deduped_bytes),
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) {
@@ -134,23 +145,31 @@
if (total) {
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 "]",
- stat._exec, stat._exec_elapsed, stat._idle, stat._idle_elapsed, stat._block, stat._block_elapsed);
+ " Total Exec: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT_MS
+ ", 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 {
log_debug(gc, stringdedup)(
- " [Last Exec: " G1_STRDEDUP_TIME_FORMAT ", Idle: " G1_STRDEDUP_TIME_FORMAT ", Blocked: " UINTX_FORMAT "/" G1_STRDEDUP_TIME_FORMAT "]",
- stat._exec_elapsed, stat._idle_elapsed, stat._block, stat._block_elapsed);
+ " Last Exec: " G1_STRDEDUP_TIME_FORMAT_MS
+ ", 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)(" [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)(" [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)(" 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)(" 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)(" New: " G1_STRDEDUP_OBJECTS_FORMAT "(" G1_STRDEDUP_PERCENT_FORMAT ") " G1_STRDEDUP_BYTES_FORMAT,
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);
- 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);
- 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);
}
--- a/hotspot/src/share/vm/gc/g1/g1StringDedupStat.hpp Sat Jul 02 00:26:51 2016 +0000
+++ b/hotspot/src/share/vm/gc/g1/g1StringDedupStat.hpp Mon Jul 04 11:27:11 2016 +0200
@@ -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.
*
* This code is free software; you can redistribute it and/or modify it
@@ -30,11 +30,14 @@
// Macros for GC log output formating
#define G1_STRDEDUP_OBJECTS_FORMAT UINTX_FORMAT_W(12)
-#define G1_STRDEDUP_TIME_FORMAT "%1.7lf secs"
-#define G1_STRDEDUP_PERCENT_FORMAT "%5.1lf%%"
-#define G1_STRDEDUP_PERCENT_FORMAT_NS "%.1lf%%"
-#define G1_STRDEDUP_BYTES_FORMAT "%8.1lf%s"
-#define G1_STRDEDUP_BYTES_FORMAT_NS "%.1lf%s"
+#define G1_STRDEDUP_TIME_FORMAT "%.3fs"
+#define G1_STRDEDUP_TIME_PARAM(time) (time)
+#define G1_STRDEDUP_TIME_FORMAT_MS "%.3fms"
+#define G1_STRDEDUP_TIME_PARAM_MS(time) ((time) * MILLIUNITS)
+#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))
//
@@ -60,7 +63,9 @@
uintx _block;
// Time spent by the deduplication thread in different phases
- double _start;
+ double _start_concurrent;
+ double _end_concurrent;
+ double _start_phase;
double _idle_elapsed;
double _exec_elapsed;
double _block_elapsed;
@@ -104,38 +109,41 @@
}
void mark_idle() {
- _start = os::elapsedTime();
+ _start_phase = os::elapsedTime();
_idle++;
}
void mark_exec() {
double now = os::elapsedTime();
- _idle_elapsed = now - _start;
- _start = now;
+ _idle_elapsed = now - _start_phase;
+ _start_phase = now;
+ _start_concurrent = now;
_exec++;
}
void mark_block() {
double now = os::elapsedTime();
- _exec_elapsed += now - _start;
- _start = now;
+ _exec_elapsed += now - _start_phase;
+ _start_phase = now;
_block++;
}
void mark_unblock() {
double now = os::elapsedTime();
- _block_elapsed += now - _start;
- _start = now;
+ _block_elapsed += now - _start_phase;
+ _start_phase = now;
}
void mark_done() {
double now = os::elapsedTime();
- _exec_elapsed += now - _start;
+ _exec_elapsed += now - _start_phase;
+ _end_concurrent = now;
}
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);
};
--- a/hotspot/src/share/vm/gc/g1/g1StringDedupTable.cpp Sat Jul 02 00:26:51 2016 +0000
+++ b/hotspot/src/share/vm/gc/g1/g1StringDedupTable.cpp Mon Jul 04 11:27:11 2016 +0200
@@ -196,7 +196,8 @@
}
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;
@@ -610,14 +611,14 @@
void G1StringDedupTable::print_statistics() {
Log(gc, stringdedup) log;
- log.debug(" [Table]");
- log.debug(" [Memory Usage: " G1_STRDEDUP_BYTES_FORMAT_NS "]",
+ log.debug(" Table");
+ log.debug(" Memory Usage: " G1_STRDEDUP_BYTES_FORMAT_NS,
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(" [Entries: " UINTX_FORMAT ", Load: " G1_STRDEDUP_PERCENT_FORMAT_NS ", Cached: " UINTX_FORMAT ", Added: " UINTX_FORMAT ", Removed: " UINTX_FORMAT "]",
+ 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,
_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);
- 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(" 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);
}
--- a/hotspot/src/share/vm/gc/g1/g1StringDedupThread.cpp Sat Jul 02 00:26:51 2016 +0000
+++ b/hotspot/src/share/vm/gc/g1/g1StringDedupThread.cpp Mon Jul 04 11:27:11 2016 +0200
@@ -103,6 +103,7 @@
SuspendibleThreadSetJoiner sts_join;
stat.mark_exec();
+ print_start(stat);
// Process the queue
for (;;) {
@@ -123,9 +124,8 @@
stat.mark_done();
- // Print statistics
total_stat.add(stat);
- print(stat, total_stat);
+ print_end(stat, total_stat);
}
G1StringDedupTable::clean_entry_cache();
@@ -136,14 +136,16 @@
G1StringDedupQueue::cancel_wait();
}
-void G1StringDedupThread::print(const G1StringDedupStat& last_stat, const G1StringDedupStat& total_stat) {
- if (log_is_enabled(Info, gc, stringdedup)) {
- G1StringDedupStat::print_summary(last_stat, total_stat);
- if (log_is_enabled(Debug, gc, stringdedup)) {
- G1StringDedupStat::print_statistics(last_stat, false);
- G1StringDedupStat::print_statistics(total_stat, true);
- G1StringDedupTable::print_statistics();
- G1StringDedupQueue::print_statistics();
- }
+void G1StringDedupThread::print_start(const G1StringDedupStat& last_stat) {
+ G1StringDedupStat::print_start(last_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)) {
+ G1StringDedupStat::print_statistics(last_stat, false);
+ G1StringDedupStat::print_statistics(total_stat, true);
+ G1StringDedupTable::print_statistics();
+ G1StringDedupQueue::print_statistics();
}
}
--- a/hotspot/src/share/vm/gc/g1/g1StringDedupThread.hpp Sat Jul 02 00:26:51 2016 +0000
+++ b/hotspot/src/share/vm/gc/g1/g1StringDedupThread.hpp Mon Jul 04 11:27:11 2016 +0200
@@ -43,7 +43,8 @@
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 stop_service();