< prev index next >

src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp

Print this page




   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.
   8  *
   9  * This code is distributed in the hope that it will be useful, but WITHOUT
  10  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  11  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  12  * version 2 for more details (a copy is included in the LICENSE file that
  13  * accompanied this code).
  14  *
  15  * You should have received a copy of the GNU General Public License version
  16  * 2 along with this work; if not, write to the Free Software Foundation,
  17  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  18  *
  19  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  20  * or visit www.oracle.com if you need additional information or have any
  21  * questions.
  22  *
  23  */
  24 
  25 
  26 #include "precompiled.hpp"
  27 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
  28 #include "gc_implementation/g1/g1GCPhaseTimes.hpp"
  29 #include "gc_implementation/g1/g1Log.hpp"
  30 #include "gc_implementation/g1/g1StringDedup.hpp"
  31 #include "runtime/atomic.inline.hpp"

  32 
  33 // Helper class for avoiding interleaved logging
  34 class LineBuffer: public StackObj {
  35 
  36 private:
  37   static const int BUFFER_LEN = 1024;
  38   static const int INDENT_CHARS = 3;
  39   char _buffer[BUFFER_LEN];
  40   int _indent_level;
  41   int _cur;
  42 
  43   void vappend(const char* format, va_list ap)  ATTRIBUTE_PRINTF(2, 0) {
  44     int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
  45     if (res != -1) {
  46       _cur += res;
  47     } else {
  48       DEBUG_ONLY(warning("buffer too small in LineBuffer");)
  49       _buffer[BUFFER_LEN -1] = 0;
  50       _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
  51     }


  54 public:
  55   explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
  56     for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
  57       _buffer[_cur] = ' ';
  58     }
  59   }
  60 
  61 #ifndef PRODUCT
  62   ~LineBuffer() {
  63     assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
  64   }
  65 #endif
  66 
  67   void append(const char* format, ...)  ATTRIBUTE_PRINTF(2, 3) {
  68     va_list ap;
  69     va_start(ap, format);
  70     vappend(format, ap);
  71     va_end(ap);
  72   }
  73 





  74   void append_and_print_cr(const char* format, ...)  ATTRIBUTE_PRINTF(2, 3) {
  75     va_list ap;
  76     va_start(ap, format);
  77     vappend(format, ap);
  78     va_end(ap);
  79     gclog_or_tty->print_cr("%s", _buffer);
  80     _cur = _indent_level * INDENT_CHARS;
  81   }
  82 };
  83 
  84 PRAGMA_DIAG_PUSH
  85 PRAGMA_FORMAT_NONLITERAL_IGNORED
  86 template <class T>
  87 void WorkerDataArray<T>::print(int level, const char* title) {
  88   if (_length == 1) {
  89     // No need for min, max, average and sum for only one worker
  90     LineBuffer buf(level);
  91     buf.append("[%s:  ", title);
  92     buf.append(_print_format, _data[0]);
  93     buf.append_and_print_cr("]");
  94     return;























  95   }
  96 
  97   T min = _data[0];
  98   T max = _data[0];
  99   T sum = 0;
 100 
 101   LineBuffer buf(level);
 102   buf.append("[%s:", title);
 103   for (uint i = 0; i < _length; ++i) {
 104     T val = _data[i];
 105     min = MIN2(val, min);
 106     max = MAX2(val, max);
 107     sum += val;
 108     if (G1Log::finest()) {
 109       buf.append("  ");
 110       buf.append(_print_format, val);

 111     }




 112   }
 113 
 114   if (G1Log::finest()) {
 115     buf.append_and_print_cr("%s", "");


 116   }
 117 
 118   double avg = (double)sum / (double)_length;
 119   buf.append(" Min: ");
 120   buf.append(_print_format, min);
 121   buf.append(", Avg: ");
 122   buf.append("%.1lf", avg); // Always print average as a double
 123   buf.append(", Max: ");
 124   buf.append(_print_format, max);
 125   buf.append(", Diff: ");
 126   buf.append(_print_format, max - min);
 127   if (_print_sum) {
 128     // for things like the start and end times the sum is not
 129     // that relevant
 130     buf.append(", Sum: ");
 131     buf.append(_print_format, sum);
 132   }
 133   buf.append_and_print_cr("]");
 134 }
 135 PRAGMA_DIAG_POP














































 136 
 137 #ifndef PRODUCT
 138 
 139 template <> const int WorkerDataArray<int>::_uninitialized = -1;
 140 template <> const double WorkerDataArray<double>::_uninitialized = -1.0;
 141 template <> const size_t WorkerDataArray<size_t>::_uninitialized = (size_t)-1;






 142 
 143 template <class T>
 144 void WorkerDataArray<T>::reset() {
 145   for (uint i = 0; i < _length; i++) {
 146     _data[i] = (T)_uninitialized;



 147   }
 148 }
 149 
 150 template <class T>
 151 void WorkerDataArray<T>::verify() {




 152   for (uint i = 0; i < _length; i++) {
 153     assert(_data[i] != _uninitialized,
 154         err_msg("Invalid data for worker %u, data: %lf, uninitialized: %lf",
 155             i, (double)_data[i], (double)_uninitialized));


 156   }
 157 }
 158 
 159 #endif
 160 
 161 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
 162   _max_gc_threads(max_gc_threads),
 163   _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
 164   _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
 165   _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
 166   _last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
 167   _last_update_rs_processed_buffers(_max_gc_threads, "%d"),
 168   _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
 169   _last_strong_code_root_scan_times_ms(_max_gc_threads, "%.1lf"),
 170   _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
 171   _last_termination_times_ms(_max_gc_threads, "%.1lf"),
 172   _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
 173   _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
 174   _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
 175   _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"),
 176   _last_redirty_logged_cards_time_ms(_max_gc_threads, "%.1lf"),
 177   _last_redirty_logged_cards_processed_cards(_max_gc_threads, SIZE_FORMAT),
 178   _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"),
 179   _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf")
 180 {
 181   assert(max_gc_threads > 0, "Must have some GC threads");

























 182 }
 183 
 184 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
 185   assert(active_gc_threads > 0, "The number of threads must be > 0");
 186   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
 187   _active_gc_threads = active_gc_threads;
 188 
 189   _last_gc_worker_start_times_ms.reset();
 190   _last_ext_root_scan_times_ms.reset();
 191   _last_satb_filtering_times_ms.reset();
 192   _last_update_rs_times_ms.reset();
 193   _last_update_rs_processed_buffers.reset();
 194   _last_scan_rs_times_ms.reset();
 195   _last_strong_code_root_scan_times_ms.reset();
 196   _last_obj_copy_times_ms.reset();
 197   _last_termination_times_ms.reset();
 198   _last_termination_attempts.reset();
 199   _last_gc_worker_end_times_ms.reset();
 200   _last_gc_worker_times_ms.reset();
 201   _last_gc_worker_other_times_ms.reset();
 202 
 203   _last_redirty_logged_cards_time_ms.reset();
 204   _last_redirty_logged_cards_processed_cards.reset();
 205 


 206 }
 207 
 208 void G1GCPhaseTimes::note_gc_end() {
 209   _last_gc_worker_start_times_ms.verify();
 210   _last_ext_root_scan_times_ms.verify();
 211   _last_satb_filtering_times_ms.verify();
 212   _last_update_rs_times_ms.verify();
 213   _last_update_rs_processed_buffers.verify();
 214   _last_scan_rs_times_ms.verify();
 215   _last_strong_code_root_scan_times_ms.verify();
 216   _last_obj_copy_times_ms.verify();
 217   _last_termination_times_ms.verify();
 218   _last_termination_attempts.verify();
 219   _last_gc_worker_end_times_ms.verify();
 220 
 221   for (uint i = 0; i < _active_gc_threads; i++) {
 222     double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i);
 223     _last_gc_worker_times_ms.set(i, worker_time);
 224 
 225     double worker_known_time = _last_ext_root_scan_times_ms.get(i) +
 226                                _last_satb_filtering_times_ms.get(i) +
 227                                _last_update_rs_times_ms.get(i) +
 228                                _last_scan_rs_times_ms.get(i) +
 229                                _last_strong_code_root_scan_times_ms.get(i) +
 230                                _last_obj_copy_times_ms.get(i) +
 231                                _last_termination_times_ms.get(i);

 232 
 233     double worker_other_time = worker_time - worker_known_time;
 234     _last_gc_worker_other_times_ms.set(i, worker_other_time);
 235   }
 236 
 237   _last_gc_worker_times_ms.verify();
 238   _last_gc_worker_other_times_ms.verify();
 239 
 240   _last_redirty_logged_cards_time_ms.verify();
 241   _last_redirty_logged_cards_processed_cards.verify();
 242 }
 243 
 244 void G1GCPhaseTimes::note_string_dedup_fixup_start() {
 245   _cur_string_dedup_queue_fixup_worker_times_ms.reset();
 246   _cur_string_dedup_table_fixup_worker_times_ms.reset();
 247 }
 248 
 249 void G1GCPhaseTimes::note_string_dedup_fixup_end() {
 250   _cur_string_dedup_queue_fixup_worker_times_ms.verify();
 251   _cur_string_dedup_table_fixup_worker_times_ms.verify();
 252 }
 253 
 254 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
 255   LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
 256 }
 257 
 258 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
 259   LineBuffer(level).append_and_print_cr("[%s: "SIZE_FORMAT"]", str, value);
 260 }
 261 
 262 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
 263   LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
 264 }
 265 
 266 double G1GCPhaseTimes::accounted_time_ms() {
 267     // Subtract the root region scanning wait time. It's initialized to
 268     // zero at the start of the pause.
 269     double misc_time_ms = _root_region_scan_wait_time_ms;
 270 
 271     misc_time_ms += _cur_collection_par_time_ms;
 272 
 273     // Now subtract the time taken to fix up roots in generated code
 274     misc_time_ms += _cur_collection_code_root_fixup_time_ms;
 275 
 276     // Strong code root purge time
 277     misc_time_ms += _cur_strong_code_root_purge_time_ms;
 278 
 279     if (G1StringDedup::is_enabled()) {
 280       // String dedup fixup time
 281       misc_time_ms += _cur_string_dedup_fixup_time_ms;
 282     }
 283 
 284     // Subtract the time taken to clean the card table from the
 285     // current value of "other time"
 286     misc_time_ms += _cur_clear_ct_time_ms;
 287 
 288     return misc_time_ms;
 289 }
 290 
























































































































































 291 void G1GCPhaseTimes::print(double pause_time_sec) {


 292   if (_root_region_scan_wait_time_ms > 0.0) {
 293     print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 294   }

 295   print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
 296   _last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)");
 297   _last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)");
 298   if (_last_satb_filtering_times_ms.sum() > 0.0) {
 299     _last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)");
 300   }
 301   _last_update_rs_times_ms.print(2, "Update RS (ms)");
 302     _last_update_rs_processed_buffers.print(3, "Processed Buffers");
 303   _last_scan_rs_times_ms.print(2, "Scan RS (ms)");
 304   _last_strong_code_root_scan_times_ms.print(2, "Code Root Scanning (ms)");
 305   _last_obj_copy_times_ms.print(2, "Object Copy (ms)");
 306   _last_termination_times_ms.print(2, "Termination (ms)");
 307   if (G1Log::finest()) {
 308     _last_termination_attempts.print(3, "Termination Attempts");
 309   }
 310   _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)");
 311   _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)");
 312   _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)");
 313 
 314   print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
 315   print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
 316   if (G1StringDedup::is_enabled()) {
 317     print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
 318     _cur_string_dedup_queue_fixup_worker_times_ms.print(2, "Queue Fixup (ms)");
 319     _cur_string_dedup_table_fixup_worker_times_ms.print(2, "Table Fixup (ms)");

 320   }
 321   print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
 322   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
 323   print_stats(1, "Other", misc_time_ms);
 324   if (_cur_verify_before_time_ms > 0.0) {
 325     print_stats(2, "Verify Before", _cur_verify_before_time_ms);
 326   }
 327   if (G1CollectedHeap::heap()->evacuation_failed()) {
 328     double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
 329       _cur_evac_fail_restore_remsets;
 330     print_stats(2, "Evacuation Failure", evac_fail_handling);
 331     if (G1Log::finest()) {
 332       print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
 333       print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
 334       print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
 335     }
 336   }
 337   print_stats(2, "Choose CSet",
 338     (_recorded_young_cset_choice_time_ms +
 339     _recorded_non_young_cset_choice_time_ms));
 340   print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
 341   print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
 342   print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 343   if (G1Log::finest()) {
 344     _last_redirty_logged_cards_time_ms.print(3, "Parallel Redirty");
 345     _last_redirty_logged_cards_processed_cards.print(3, "Redirtied Cards");
 346   }
 347   if (G1EagerReclaimHumongousObjects) {
 348     print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 349     if (G1Log::finest()) {
 350       print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
 351       print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 352     }
 353     print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 354     if (G1Log::finest()) {
 355       print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 356     }
 357   }
 358   print_stats(2, "Free CSet",
 359     (_recorded_young_free_cset_time_ms +
 360     _recorded_non_young_free_cset_time_ms));
 361   if (G1Log::finest()) {
 362     print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
 363     print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
 364   }
 365   if (_cur_verify_after_time_ms > 0.0) {
 366     print_stats(2, "Verify After", _cur_verify_after_time_ms);
 367   }
 368 }
















   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.
   8  *
   9  * This code is distributed in the hope that it will be useful, but WITHOUT
  10  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  11  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  12  * version 2 for more details (a copy is included in the LICENSE file that
  13  * accompanied this code).
  14  *
  15  * You should have received a copy of the GNU General Public License version
  16  * 2 along with this work; if not, write to the Free Software Foundation,
  17  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  18  *
  19  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  20  * or visit www.oracle.com if you need additional information or have any
  21  * questions.
  22  *
  23  */
  24 

  25 #include "precompiled.hpp"
  26 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
  27 #include "gc_implementation/g1/g1GCPhaseTimes.hpp"
  28 #include "gc_implementation/g1/g1Log.hpp"
  29 #include "gc_implementation/g1/g1StringDedup.hpp"
  30 #include "memory/allocation.hpp"
  31 #include "runtime/os.hpp"
  32 
  33 // Helper class for avoiding interleaved logging
  34 class LineBuffer: public StackObj {
  35 
  36 private:
  37   static const int BUFFER_LEN = 1024;
  38   static const int INDENT_CHARS = 3;
  39   char _buffer[BUFFER_LEN];
  40   int _indent_level;
  41   int _cur;
  42 
  43   void vappend(const char* format, va_list ap)  ATTRIBUTE_PRINTF(2, 0) {
  44     int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
  45     if (res != -1) {
  46       _cur += res;
  47     } else {
  48       DEBUG_ONLY(warning("buffer too small in LineBuffer");)
  49       _buffer[BUFFER_LEN -1] = 0;
  50       _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
  51     }


  54 public:
  55   explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
  56     for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
  57       _buffer[_cur] = ' ';
  58     }
  59   }
  60 
  61 #ifndef PRODUCT
  62   ~LineBuffer() {
  63     assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
  64   }
  65 #endif
  66 
  67   void append(const char* format, ...)  ATTRIBUTE_PRINTF(2, 3) {
  68     va_list ap;
  69     va_start(ap, format);
  70     vappend(format, ap);
  71     va_end(ap);
  72   }
  73 
  74   void print_cr() {
  75     gclog_or_tty->print_cr("%s", _buffer);
  76     _cur = _indent_level * INDENT_CHARS;
  77   }
  78 
  79   void append_and_print_cr(const char* format, ...)  ATTRIBUTE_PRINTF(2, 3) {
  80     va_list ap;
  81     va_start(ap, format);
  82     vappend(format, ap);
  83     va_end(ap);
  84     print_cr();

  85   }
  86 };
  87 


  88 template <class T>
  89 class WorkerDataArray  : public CHeapObj<mtGC> {
  90   friend class G1GCParPhasePrinter;
  91   T*          _data;
  92   uint        _length;
  93   const char* _title;
  94   bool        _print_sum;
  95   int         _log_level;
  96   uint        _indent_level;
  97   bool        _enabled;
  98 
  99   WorkerDataArray<size_t>* _sub_count;
 100 
 101   NOT_PRODUCT(T uninitialized();)
 102 
 103   // We are caching the sum and average to only have to calculate them once.
 104   // This is not done in an MT-safe way. It is intended to allow single
 105   // threaded code to call sum() and average() multiple times in any order
 106   // without having to worry about the cost.
 107   bool   _has_new_data;
 108   T      _sum;
 109   T      _min;
 110   T      _max;
 111   double _average;
 112 
 113  public:
 114   WorkerDataArray(uint length, const char* title, bool print_sum, int log_level, uint indent_level) :
 115     _title(title), _length(0), _print_sum(print_sum), _log_level(log_level), _indent_level(indent_level),
 116     _has_new_data(true), _sub_count(NULL), _enabled(true) {
 117     assert(length > 0, "Must have some workers to store data for");
 118     _length = length;
 119     _data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
 120   }
 121 
 122   ~WorkerDataArray() {
 123     FREE_C_HEAP_ARRAY(T, _data);
 124   }
 125 
 126   void link_sub_count_array(WorkerDataArray<size_t>* sub_count) {
 127     _sub_count = sub_count;
 128   }
 129 
 130   WorkerDataArray<size_t>* sub_count() { return _sub_count; }
 131 
 132   void set(uint worker_i, T value) {
 133     assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
 134     assert(_data[worker_i] == WorkerDataArray<T>::uninitialized(), err_msg("Overwriting data for worker %d in %s", worker_i, _title));
 135     _data[worker_i] = value;
 136     _has_new_data = true;
 137   }
 138 
 139   void set_sub_count(uint worker_i, size_t value) {
 140     assert(_sub_count != NULL, "No sub count");
 141     _sub_count->set(worker_i, value);
 142   }
 143 
 144   T get(uint worker_i) {
 145     assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
 146     assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), err_msg("No data to add to for worker %d", worker_i));
 147     return _data[worker_i];
 148   }
 149 
 150   void add(uint worker_i, T value) {
 151     assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
 152     assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), err_msg("No data to add to for worker %d", worker_i));
 153     _data[worker_i] += value;
 154     _has_new_data = true;









 155   }
 156 
 157   double average(){
 158     calculate_totals();
 159     return _average;
 160   }
 161 
 162   T sum() {
 163     calculate_totals();
 164     return _sum;
 165   }
 166 
 167   T minimum() {
 168     calculate_totals();
 169     return _min;
 170   }
 171 
 172   T maximum() {
 173     calculate_totals();
 174     return _max;
 175   }
 176 
 177   void reset() PRODUCT_RETURN;
 178   void verify() PRODUCT_RETURN;
 179 
 180   void set_enabled(bool enabled) { _enabled = enabled; }
 181 
 182   int log_level() { return _log_level;  }
 183 
 184  private:
 185 
 186   void calculate_totals(){
 187     if (!_has_new_data) {
 188       return;
 189     }
 190 
 191     _sum = (T)0;
 192     _min = _data[0];
 193     _max = _min;
 194     for (uint i = 0; i < _length; ++i) {
 195       T val = _data[i];
 196       _sum += val;
 197       _min = MIN2(_min, val);
 198       _max = MAX2(_max, val);
 199     }
 200     _average = (double)_sum / (double)_length;
 201     _has_new_data = false;
 202   }
 203 };
 204 
 205 
 206 #ifndef PRODUCT
 207 
 208 template <>
 209 size_t WorkerDataArray<size_t>::uninitialized() {
 210   return (size_t)-1;
 211 }
 212 
 213 template <>
 214 double WorkerDataArray<double>::uninitialized() {
 215   return -1.0;
 216 }
 217 
 218 template <class T>
 219 void WorkerDataArray<T>::reset() {
 220   for (uint i = 0; i < _length; i++) {
 221     _data[i] = WorkerDataArray<T>::uninitialized();
 222   }
 223   if (_sub_count != NULL) {
 224     _sub_count->reset();
 225   }
 226 }
 227 
 228 template <class T>
 229 void WorkerDataArray<T>::verify() {
 230   if (!_enabled) {
 231     return;
 232   }
 233 
 234   for (uint i = 0; i < _length; i++) {
 235     assert(_data[i] != WorkerDataArray<T>::uninitialized(),
 236         err_msg("Invalid data for worker %u in '%s'", i, _title));
 237   }
 238   if (_sub_count != NULL) {
 239     _sub_count->verify();
 240   }
 241 }
 242 
 243 #endif
 244 
 245 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
 246   _max_gc_threads(max_gc_threads)

















 247 {
 248   assert(max_gc_threads > 0, "Must have some GC threads");
 249 
 250   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2);
 251   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2);
 252   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFiner, 2);
 253   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);
 254   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);
 255   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);
 256   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms)", true, G1Log::LevelFiner, 2);
 257   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms)", true, G1Log::LevelFiner, 2);
 258   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms)", true, G1Log::LevelFiner, 2);
 259   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms)", false, G1Log::LevelFiner, 2);
 260   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms)", true, G1Log::LevelFiner, 2);
 261 
 262   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers", true, G1Log::LevelFiner, 3);
 263   _gc_par_phases[UpdateRS]->link_sub_count_array(_update_rs_processed_buffers);
 264 
 265   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts", true, G1Log::LevelFinest, 3);
 266   _gc_par_phases[Termination]->link_sub_count_array(_termination_attempts);
 267 
 268   _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2);
 269   _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2);
 270 
 271   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3);
 272   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3);
 273   _gc_par_phases[RedirtyCards]->link_sub_count_array(_redirtied_cards);
 274 }
 275 
 276 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress) {
 277   assert(active_gc_threads > 0, "The number of threads must be > 0");
 278   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
 279   _active_gc_threads = active_gc_threads;
 280 
 281   for (int i = 0; i < GCParPhasesSentinel; i++) {
 282     _gc_par_phases[i]->reset();
 283   }










 284 
 285   _gc_par_phases[SATBFiltering]->set_enabled(mark_in_progress);

 286 
 287   _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
 288   _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
 289 }
 290 
 291 void G1GCPhaseTimes::note_gc_end() {












 292   for (uint i = 0; i < _active_gc_threads; i++) {
 293     double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 294     record_time_secs(GCWorkerTotal, i , worker_time);
 295 
 296     double worker_known_time =
 297         _gc_par_phases[ExtRootScan]->get(i) +
 298         _gc_par_phases[SATBFiltering]->get(i) +
 299         _gc_par_phases[UpdateRS]->get(i) +
 300         _gc_par_phases[ScanRS]->get(i) +
 301         _gc_par_phases[CodeRoots]->get(i) +
 302         _gc_par_phases[ObjCopy]->get(i) +
 303         _gc_par_phases[Termination]->get(i);
 304 
 305     record_time_secs(Other, i, worker_time - worker_known_time);

 306   }
 307 
 308   for (int i = 0; i < GCParPhasesSentinel; i++) {
 309     _gc_par_phases[i]->verify();
 310   }












 311 }
 312 
 313 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
 314   LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
 315 }
 316 
 317 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
 318   LineBuffer(level).append_and_print_cr("[%s: "SIZE_FORMAT"]", str, value);
 319 }
 320 
 321 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
 322   LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
 323 }
 324 
 325 double G1GCPhaseTimes::accounted_time_ms() {
 326     // Subtract the root region scanning wait time. It's initialized to
 327     // zero at the start of the pause.
 328     double misc_time_ms = _root_region_scan_wait_time_ms;
 329 
 330     misc_time_ms += _cur_collection_par_time_ms;
 331 
 332     // Now subtract the time taken to fix up roots in generated code
 333     misc_time_ms += _cur_collection_code_root_fixup_time_ms;
 334 
 335     // Strong code root purge time
 336     misc_time_ms += _cur_strong_code_root_purge_time_ms;
 337 
 338     if (G1StringDedup::is_enabled()) {
 339       // String dedup fixup time
 340       misc_time_ms += _cur_string_dedup_fixup_time_ms;
 341     }
 342 
 343     // Subtract the time taken to clean the card table from the
 344     // current value of "other time"
 345     misc_time_ms += _cur_clear_ct_time_ms;
 346 
 347     return misc_time_ms;
 348 }
 349 
 350 // record the time a phase took in seconds
 351 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 352   _gc_par_phases[phase]->set(worker_i, secs);
 353 }
 354 
 355 // add a number of seconds to a phase
 356 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 357   _gc_par_phases[phase]->add(worker_i, secs);
 358 }
 359 
 360 void G1GCPhaseTimes::record_sub_count(GCParPhases phase, uint worker_i, size_t count) {
 361   _gc_par_phases[phase]->set_sub_count(worker_i, count);
 362 }
 363 
 364 // return the average time for a phase in milliseconds
 365 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 366   return _gc_par_phases[phase]->average() * 1000.0;
 367 }
 368 
 369 size_t G1GCPhaseTimes::sub_count_sum(GCParPhases phase) {
 370   assert(_gc_par_phases[phase]->sub_count() != NULL, "No sub count");
 371   return _gc_par_phases[phase]->sub_count()->sum();
 372 }
 373 
 374 double G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) {
 375   return _gc_par_phases[phase]->get(worker_i) * 1000.0;
 376 }
 377 
 378 double G1GCPhaseTimes::sum_time_ms(GCParPhases phase) {
 379   return _gc_par_phases[phase]->sum() * 1000.0;
 380 }
 381 
 382 double G1GCPhaseTimes::min_time_ms(GCParPhases phase) {
 383   return _gc_par_phases[phase]->minimum() * 1000.0;
 384 }
 385 
 386 double G1GCPhaseTimes::max_time_ms(GCParPhases phase) {
 387   return _gc_par_phases[phase]->maximum() * 1000.0;
 388 }
 389 
 390 size_t G1GCPhaseTimes::get_sub_count(GCParPhases phase, uint worker_i) {
 391   assert(_gc_par_phases[phase]->sub_count() != NULL, "No sub count");
 392   return _gc_par_phases[phase]->sub_count()->get(worker_i);
 393 }
 394 
 395 size_t G1GCPhaseTimes::sum_sub_count(GCParPhases phase) {
 396   assert(_gc_par_phases[phase]->sub_count() != NULL, "No sub count");
 397   return _gc_par_phases[phase]->sub_count()->sum();
 398 }
 399 
 400 double G1GCPhaseTimes::average_sub_count(GCParPhases phase) {
 401   assert(_gc_par_phases[phase]->sub_count() != NULL, "No sub count");
 402   return _gc_par_phases[phase]->sub_count()->average();
 403 }
 404 
 405 size_t G1GCPhaseTimes::min_sub_count(GCParPhases phase) {
 406   assert(_gc_par_phases[phase]->sub_count() != NULL, "No sub count");
 407   return _gc_par_phases[phase]->sub_count()->minimum();
 408 }
 409 
 410 size_t G1GCPhaseTimes::max_sub_count(GCParPhases phase) {
 411   assert(_gc_par_phases[phase]->sub_count() != NULL, "No sub count");
 412   return _gc_par_phases[phase]->sub_count()->maximum();
 413 }
 414 
 415 class G1GCParPhasePrinter : public StackObj {
 416   G1GCPhaseTimes* _phase_times;
 417  public:
 418   G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {}
 419 
 420   void print(G1GCPhaseTimes::GCParPhases phase_id) {
 421     WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id];
 422 
 423     if (phase->_log_level > G1Log::level() || !phase->_enabled) {
 424       return;
 425     }
 426 
 427     if (phase->_length == 1) {
 428       print_single_length(phase_id, phase);
 429     } else {
 430       print_multi_length(phase_id, phase);
 431     }
 432   }
 433 
 434  private:
 435 
 436   void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 437     // No need for min, max, average and sum for only one worker
 438     LineBuffer buf(phase->_indent_level);
 439     buf.append_and_print_cr("[%s:  %.1lf]", phase->_title, _phase_times->get_time_ms(phase_id, 0));
 440 
 441     if (phase->_sub_count != NULL) {
 442       LineBuffer buf2(phase->_sub_count->_indent_level);
 443       buf2.append_and_print_cr("[%s:  "SIZE_FORMAT"]", phase->_sub_count->_title, _phase_times->sub_count_sum(phase_id));
 444     }
 445   }
 446 
 447   void print_time_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 448     for (uint i = 0; i < phase->_length; ++i) {
 449       buf.append("  %.1lf", _phase_times->get_time_ms(phase_id, i));
 450     }
 451     buf.print_cr();
 452   }
 453 
 454   void print_count_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* sub_count) {
 455     for (uint i = 0; i < sub_count->_length; ++i) {
 456       buf.append("  " SIZE_FORMAT, _phase_times->get_sub_count(phase_id, i));
 457     }
 458     buf.print_cr();
 459   }
 460 
 461   void print_sub_count(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* sub_count) {
 462     LineBuffer buf(sub_count->_indent_level);
 463     buf.append("[%s:", sub_count->_title);
 464 
 465     if (G1Log::finest()) {
 466       print_count_values(buf, phase_id, sub_count);
 467     }
 468 
 469     assert(sub_count->_print_sum, err_msg("%s does not have print sum true even though it is a count", sub_count->_title));
 470 
 471     buf.append_and_print_cr(" Min: " SIZE_FORMAT ", Avg: %.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT "]",
 472         _phase_times->min_sub_count(phase_id), _phase_times->average_sub_count(phase_id), _phase_times->max_sub_count(phase_id),
 473         _phase_times->max_sub_count(phase_id) - _phase_times->min_sub_count(phase_id), _phase_times->sum_sub_count(phase_id));
 474   }
 475 
 476   void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 477     LineBuffer buf(phase->_indent_level);
 478     buf.append("[%s:", phase->_title);
 479 
 480     if (G1Log::finest()) {
 481       print_time_values(buf, phase_id, phase);
 482     }
 483 
 484     buf.append(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf",
 485         _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
 486         _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
 487 
 488     if (phase->_print_sum) {
 489       // for things like the start and end times the sum is not
 490       // that relevant
 491       buf.append(", Sum: %.1lf", _phase_times->sum_time_ms(phase_id));
 492     }
 493 
 494     buf.append_and_print_cr("]");
 495 
 496     if (phase->_sub_count != NULL) {
 497       print_sub_count(phase_id, phase->_sub_count);
 498     }
 499   }
 500 };
 501 
 502 void G1GCPhaseTimes::print(double pause_time_sec) {
 503   G1GCParPhasePrinter par_phase_printer(this);
 504 
 505   if (_root_region_scan_wait_time_ms > 0.0) {
 506     print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 507   }
 508 
 509   print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
 510   for (int i = 0; i <= GCMainParPhasesLast; i++) {
 511     par_phase_printer.print((GCParPhases) i);











 512   }



 513 
 514   print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
 515   print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
 516   if (G1StringDedup::is_enabled()) {
 517     print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
 518     for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
 519       par_phase_printer.print((GCParPhases) i);
 520     }
 521   }
 522   print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
 523   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
 524   print_stats(1, "Other", misc_time_ms);
 525   if (_cur_verify_before_time_ms > 0.0) {
 526     print_stats(2, "Verify Before", _cur_verify_before_time_ms);
 527   }
 528   if (G1CollectedHeap::heap()->evacuation_failed()) {
 529     double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
 530       _cur_evac_fail_restore_remsets;
 531     print_stats(2, "Evacuation Failure", evac_fail_handling);
 532     if (G1Log::finest()) {
 533       print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
 534       print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
 535       print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
 536     }
 537   }
 538   print_stats(2, "Choose CSet",
 539     (_recorded_young_cset_choice_time_ms +
 540     _recorded_non_young_cset_choice_time_ms));
 541   print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
 542   print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
 543   print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 544   par_phase_printer.print(RedirtyCards);



 545   if (G1EagerReclaimHumongousObjects) {
 546     print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 547     if (G1Log::finest()) {
 548       print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
 549       print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 550     }
 551     print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 552     if (G1Log::finest()) {
 553       print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 554     }
 555   }
 556   print_stats(2, "Free CSet",
 557     (_recorded_young_free_cset_time_ms +
 558     _recorded_non_young_free_cset_time_ms));
 559   if (G1Log::finest()) {
 560     print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
 561     print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
 562   }
 563   if (_cur_verify_after_time_ms > 0.0) {
 564     print_stats(2, "Verify After", _cur_verify_after_time_ms);
 565   }
 566 }
 567 
 568 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 569     _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
 570   if (_phase_times != NULL) {
 571     _start_time = os::elapsedTime();
 572   }
 573 }
 574 
 575 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 576   if (_phase_times != NULL) {
 577     _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
 578   }
 579 }
 580 
< prev index next >