changeset 39690:09a3ee292336

8159974: G1 String deduplication logging not aligned with the rest of G1 Reviewed-by: stefank, tschatzl
author pliden
date Mon, 04 Jul 2016 11:27:11 +0200
parents 7181aecf48d5
children 8ebf84c4be69
files hotspot/src/share/vm/gc/g1/g1StringDedupQueue.cpp hotspot/src/share/vm/gc/g1/g1StringDedupStat.cpp hotspot/src/share/vm/gc/g1/g1StringDedupStat.hpp hotspot/src/share/vm/gc/g1/g1StringDedupTable.cpp hotspot/src/share/vm/gc/g1/g1StringDedupThread.cpp hotspot/src/share/vm/gc/g1/g1StringDedupThread.hpp
diffstat 6 files changed, 88 insertions(+), 57 deletions(-) [+]
line wrap: on
line diff
--- 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();