< prev index next >

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

Print this page




   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/g1/concurrentG1Refine.hpp"
  27 #include "gc/g1/g1CollectedHeap.inline.hpp"
  28 #include "gc/g1/g1GCPhaseTimes.hpp"
  29 #include "gc/g1/g1Log.hpp"
  30 #include "gc/g1/g1StringDedup.hpp"
  31 #include "gc/g1/workerDataArray.inline.hpp"
  32 #include "memory/allocation.hpp"

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


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


  90 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
  91   _max_gc_threads(max_gc_threads)
  92 {
  93   assert(max_gc_threads > 0, "Must have some GC threads");
  94 
  95   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2);
  96   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2);
  97 
  98   // Root scanning phases
  99   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3);
 100   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3);
 101   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3);
 102   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3);
 103   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3);
 104   _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3);
 105   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3);
 106   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3);
 107   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3);
 108   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3);
 109   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3);
 110   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3);
 111   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3);
 112   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3);
 113 
 114   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);
 115   _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms)", true, G1Log::LevelFiner, 3);
 116   _gc_par_phases[ScanHCC]->set_enabled(ConcurrentG1Refine::hot_card_cache_enabled());
 117   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);
 118   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);
 119   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms)", true, G1Log::LevelFiner, 2);
 120   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms)", true, G1Log::LevelFiner, 2);
 121   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms)", true, G1Log::LevelFiner, 2);
 122   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms)", false, G1Log::LevelFiner, 2);
 123   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms)", true, G1Log::LevelFiner, 2);
 124 
 125   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers", true, G1Log::LevelFiner, 3);
 126   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
 127 
 128   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts", true, G1Log::LevelFinest, 3);
 129   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 130 
 131   _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2);
 132   _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2);
 133 
 134   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3);
 135   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3);
 136   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 137 }
 138 
 139 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
 140   assert(active_gc_threads > 0, "The number of threads must be > 0");
 141   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
 142   _active_gc_threads = active_gc_threads;
 143   _cur_expand_heap_time_ms = 0.0;
 144   _external_accounted_time_ms = 0.0;
 145 
 146   for (int i = 0; i < GCParPhasesSentinel; i++) {
 147     _gc_par_phases[i]->reset();
 148   }
 149 
 150   _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
 151   _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
 152 }
 153 
 154 void G1GCPhaseTimes::note_gc_end() {
 155   for (uint i = 0; i < _active_gc_threads; i++) {
 156     double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 157     record_time_secs(GCWorkerTotal, i , worker_time);
 158 
 159     double worker_known_time =
 160         _gc_par_phases[ExtRootScan]->get(i) +
 161         _gc_par_phases[SATBFiltering]->get(i) +
 162         _gc_par_phases[UpdateRS]->get(i) +
 163         _gc_par_phases[ScanRS]->get(i) +
 164         _gc_par_phases[CodeRoots]->get(i) +
 165         _gc_par_phases[ObjCopy]->get(i) +
 166         _gc_par_phases[Termination]->get(i);
 167 
 168     record_time_secs(Other, i, worker_time - worker_known_time);
 169   }
 170 
 171   for (int i = 0; i < GCParPhasesSentinel; i++) {
 172     _gc_par_phases[i]->verify(_active_gc_threads);
 173   }
 174 }
 175 
 176 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
 177   LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
 178 }
 179 
 180 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
 181   LineBuffer(level).append_and_print_cr("[%s: " SIZE_FORMAT "]", str, value);
 182 }
 183 
 184 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
 185   LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
 186 }
 187 
 188 double G1GCPhaseTimes::accounted_time_ms() {
 189     // First subtract any externally accounted time
 190     double misc_time_ms = _external_accounted_time_ms;
 191 
 192     // Subtract the root region scanning wait time. It's initialized to
 193     // zero at the start of the pause.
 194     misc_time_ms += _root_region_scan_wait_time_ms;
 195 
 196     misc_time_ms += _cur_collection_par_time_ms;
 197 
 198     // Now subtract the time taken to fix up roots in generated code
 199     misc_time_ms += _cur_collection_code_root_fixup_time_ms;
 200 
 201     // Strong code root purge time
 202     misc_time_ms += _cur_strong_code_root_purge_time_ms;
 203 
 204     if (G1StringDedup::is_enabled()) {
 205       // String dedup fixup time


 267 }
 268 
 269 size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {
 270   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
 271   return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads);
 272 }
 273 
 274 size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {
 275   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
 276   return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads);
 277 }
 278 
 279 class G1GCParPhasePrinter : public StackObj {
 280   G1GCPhaseTimes* _phase_times;
 281  public:
 282   G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {}
 283 
 284   void print(G1GCPhaseTimes::GCParPhases phase_id) {
 285     WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id];
 286 
 287     if (phase->_log_level > G1Log::level() || !phase->_enabled) {
 288       return;
 289     }
 290 
 291     if (phase->_length == 1) {
 292       print_single_length(phase_id, phase);
 293     } else {
 294       print_multi_length(phase_id, phase);
 295     }
 296   }
 297 
 298  private:
 299 

 300   void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 301     // No need for min, max, average and sum for only one worker
 302     LineBuffer buf(phase->_indent_level);
 303     buf.append_and_print_cr("[%s:  %.1lf]", phase->_title, _phase_times->get_time_ms(phase_id, 0));
 304 
 305     if (phase->_thread_work_items != NULL) {
 306       LineBuffer buf2(phase->_thread_work_items->_indent_level);
 307       buf2.append_and_print_cr("[%s:  " SIZE_FORMAT "]", phase->_thread_work_items->_title, _phase_times->sum_thread_work_items(phase_id));
 308     }
 309   }
 310 
 311   void print_time_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {


 312     uint active_length = _phase_times->_active_gc_threads;
 313     for (uint i = 0; i < active_length; ++i) {
 314       buf.append("  %.1lf", _phase_times->get_time_ms(phase_id, i));



 315     }
 316     buf.print_cr();
 317   }
 318 
 319   void print_count_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {


 320     uint active_length = _phase_times->_active_gc_threads;
 321     for (uint i = 0; i < active_length; ++i) {
 322       buf.append("  " SIZE_FORMAT, _phase_times->get_thread_work_item(phase_id, i));
 323     }
 324     buf.print_cr();


 325   }
 326 
 327   void print_thread_work_items(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
 328     LineBuffer buf(thread_work_items->_indent_level);
 329     buf.append("[%s:", thread_work_items->_title);
 330 
 331     if (G1Log::finest()) {
 332       print_count_values(buf, phase_id, thread_work_items);
 333     }
 334 
 335     assert(thread_work_items->_print_sum, "%s does not have print sum true even though it is a count", thread_work_items->_title);
 336 
 337     buf.append_and_print_cr(" Min: " SIZE_FORMAT ", Avg: %.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT "]",

 338         _phase_times->min_thread_work_items(phase_id), _phase_times->average_thread_work_items(phase_id), _phase_times->max_thread_work_items(phase_id),
 339         _phase_times->max_thread_work_items(phase_id) - _phase_times->min_thread_work_items(phase_id), _phase_times->sum_thread_work_items(phase_id));


 340   }
 341 
 342   void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 343     LineBuffer buf(phase->_indent_level);
 344     buf.append("[%s:", phase->_title);
 345 
 346     if (G1Log::finest()) {
 347       print_time_values(buf, phase_id, phase);
 348     }
 349 
 350     buf.append(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf",



 351         _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
 352         _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
 353 
 354     if (phase->_print_sum) {
 355       // for things like the start and end times the sum is not
 356       // that relevant
 357       buf.append(", Sum: %.1lf", _phase_times->sum_time_ms(phase_id));
 358     }
 359 
 360     buf.append_and_print_cr("]");
 361 
 362     if (phase->_thread_work_items != NULL) {
 363       print_thread_work_items(phase_id, phase->_thread_work_items);
 364     }
 365   }
 366 };
 367 
 368 void G1GCPhaseTimes::print(double pause_time_sec) {
 369   note_gc_end();
 370 
 371   G1GCParPhasePrinter par_phase_printer(this);
 372 
 373   if (_root_region_scan_wait_time_ms > 0.0) {
 374     print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 375   }
 376 
 377   print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
 378   for (int i = 0; i <= GCMainParPhasesLast; i++) {
 379     par_phase_printer.print((GCParPhases) i);
 380   }
 381 
 382   print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
 383   print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
 384   if (G1StringDedup::is_enabled()) {
 385     print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
 386     for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
 387       par_phase_printer.print((GCParPhases) i);
 388     }
 389   }
 390   print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
 391   print_stats(1, "Expand Heap After Collection", _cur_expand_heap_time_ms);
 392 
 393   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
 394   print_stats(1, "Other", misc_time_ms);
 395   if (_cur_verify_before_time_ms > 0.0) {
 396     print_stats(2, "Verify Before", _cur_verify_before_time_ms);
 397   }
 398   if (G1CollectedHeap::heap()->evacuation_failed()) {
 399     double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
 400       _cur_evac_fail_restore_remsets;
 401     print_stats(2, "Evacuation Failure", evac_fail_handling);
 402     if (G1Log::finest()) {
 403       print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
 404       print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
 405       print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
 406     }
 407   }
 408   print_stats(2, "Choose CSet",
 409     (_recorded_young_cset_choice_time_ms +
 410     _recorded_non_young_cset_choice_time_ms));
 411   print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
 412   print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
 413   print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 414   par_phase_printer.print(RedirtyCards);
 415   if (G1EagerReclaimHumongousObjects) {
 416     print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 417     if (G1Log::finest()) {
 418       print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
 419       print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 420     }
 421     print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 422     if (G1Log::finest()) {
 423       print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 424     }
 425   }
 426   print_stats(2, "Free CSet",
 427     (_recorded_young_free_cset_time_ms +
 428     _recorded_non_young_free_cset_time_ms));
 429   if (G1Log::finest()) {
 430     print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
 431     print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
 432   }
 433   if (_cur_verify_after_time_ms > 0.0) {
 434     print_stats(2, "Verify After", _cur_verify_after_time_ms);
 435   }
 436 }
 437 
 438 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 439     _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
 440   if (_phase_times != NULL) {
 441     _start_time = os::elapsedTime();
 442   }
 443 }
 444 
 445 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 446   if (_phase_times != NULL) {
 447     _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
 448   }
 449 }
 450 


   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/g1/concurrentG1Refine.hpp"
  27 #include "gc/g1/g1CollectedHeap.inline.hpp"
  28 #include "gc/g1/g1GCPhaseTimes.hpp"

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


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

  77     _cur = _indent_level * INDENT_CHARS;
  78     return _buffer;







  79   }
  80 };
  81 
  82 static const char* Indents[4] = {"", "   ", "      ", "         "};
  83 
  84 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
  85   _max_gc_threads(max_gc_threads)
  86 {
  87   assert(max_gc_threads > 0, "Must have some GC threads");
  88 
  89   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start:", false, 2);
  90   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning:", true, 2);
  91 
  92   // Root scanning phases
  93   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots:", true, 3);
  94   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots:", true, 3);
  95   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots:", true, 3);
  96   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots:", true, 3);
  97   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots:", true, 3);
  98   _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots:", true, 3);
  99   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots:", true, 3);
 100   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots:", true, 3);
 101   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots:", true, 3);
 102   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots:", true, 3);
 103   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots:", true, 3);
 104   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD:", true, 3);
 105   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots:", true, 3);
 106   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering:", true, 3);
 107 
 108   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS:", true, 2);
 109   _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC:", true, 3);
 110   _gc_par_phases[ScanHCC]->set_enabled(ConcurrentG1Refine::hot_card_cache_enabled());
 111   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS:", true, 2);
 112   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning:", true, 2);
 113   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy:", true, 2);
 114   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination:", true, 2);
 115   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total:", true, 2);
 116   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End:", false, 2);
 117   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other:", true, 2);
 118 
 119   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:", true, 3);
 120   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
 121 
 122   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:", true, 3);
 123   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 124 
 125   _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup:", true, 2);
 126   _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup:", true, 2);
 127 
 128   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, 3);
 129   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:", true, 3);
 130   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 131 }
 132 
 133 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
 134   assert(active_gc_threads > 0, "The number of threads must be > 0");
 135   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
 136   _active_gc_threads = active_gc_threads;
 137   _cur_expand_heap_time_ms = 0.0;
 138   _external_accounted_time_ms = 0.0;
 139 
 140   for (int i = 0; i < GCParPhasesSentinel; i++) {
 141     _gc_par_phases[i]->reset();
 142   }
 143 
 144   _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
 145   _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
 146 }
 147 
 148 void G1GCPhaseTimes::note_gc_end() {
 149   for (uint i = 0; i < _active_gc_threads; i++) {
 150     double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 151     record_time_secs(GCWorkerTotal, i , worker_time);
 152 
 153     double worker_known_time =
 154         _gc_par_phases[ExtRootScan]->get(i) +
 155         _gc_par_phases[SATBFiltering]->get(i) +
 156         _gc_par_phases[UpdateRS]->get(i) +
 157         _gc_par_phases[ScanRS]->get(i) +
 158         _gc_par_phases[CodeRoots]->get(i) +
 159         _gc_par_phases[ObjCopy]->get(i) +
 160         _gc_par_phases[Termination]->get(i);
 161 
 162     record_time_secs(Other, i, worker_time - worker_known_time);
 163   }
 164 
 165   for (int i = 0; i < GCParPhasesSentinel; i++) {
 166     _gc_par_phases[i]->verify(_active_gc_threads);
 167   }
 168 }
 169 
 170 void G1GCPhaseTimes::print_stats(const char* indent, const char* str, double value) {
 171   log_debug(gc, phases)("%s%s: %.1lf ms", indent, str, value);








 172 }
 173 
 174 double G1GCPhaseTimes::accounted_time_ms() {
 175     // First subtract any externally accounted time
 176     double misc_time_ms = _external_accounted_time_ms;
 177 
 178     // Subtract the root region scanning wait time. It's initialized to
 179     // zero at the start of the pause.
 180     misc_time_ms += _root_region_scan_wait_time_ms;
 181 
 182     misc_time_ms += _cur_collection_par_time_ms;
 183 
 184     // Now subtract the time taken to fix up roots in generated code
 185     misc_time_ms += _cur_collection_code_root_fixup_time_ms;
 186 
 187     // Strong code root purge time
 188     misc_time_ms += _cur_strong_code_root_purge_time_ms;
 189 
 190     if (G1StringDedup::is_enabled()) {
 191       // String dedup fixup time


 253 }
 254 
 255 size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {
 256   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
 257   return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads);
 258 }
 259 
 260 size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {
 261   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
 262   return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads);
 263 }
 264 
 265 class G1GCParPhasePrinter : public StackObj {
 266   G1GCPhaseTimes* _phase_times;
 267  public:
 268   G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {}
 269 
 270   void print(G1GCPhaseTimes::GCParPhases phase_id) {
 271     WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id];
 272 




 273     if (phase->_length == 1) {
 274       print_single_length(phase_id, phase);
 275     } else {
 276       print_multi_length(phase_id, phase);
 277     }
 278   }
 279 

 280 
 281  private:
 282   void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 283     // No need for min, max, average and sum for only one worker
 284     log_debug(gc, phases)("%s%s:  %.1lf", Indents[phase->_indent_level], phase->_title, _phase_times->get_time_ms(phase_id, 0));

 285 
 286     WorkerDataArray<size_t>* work_items = phase->_thread_work_items;
 287     if (work_items != NULL) {
 288       log_debug(gc, phases)("%s%s:  " SIZE_FORMAT, Indents[work_items->_indent_level], work_items->_title, _phase_times->sum_thread_work_items(phase_id));
 289     }
 290   }
 291 
 292   void print_time_values(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) {
 293     if (log_is_enabled(Trace, gc)) {
 294       LineBuffer buf(0);
 295       uint active_length = _phase_times->_active_gc_threads;
 296       for (uint i = 0; i < active_length; ++i) {
 297         buf.append(" %4.1lf", _phase_times->get_time_ms(phase_id, i));
 298       }
 299       const char* line = buf.to_string();
 300       log_trace(gc, phases)("%s%-25s%s", indent, "", line);
 301     }

 302   }
 303 
 304   void print_count_values(const char* indent, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
 305     if (log_is_enabled(Trace, gc)) {
 306       LineBuffer buf(0);
 307       uint active_length = _phase_times->_active_gc_threads;
 308       for (uint i = 0; i < active_length; ++i) {
 309         buf.append("  " SIZE_FORMAT, _phase_times->get_thread_work_item(phase_id, i));
 310       }
 311       const char* line = buf.to_string();
 312       log_trace(gc, phases)("%s%-25s%s", indent, "", line);
 313     }
 314   }
 315 
 316   void print_thread_work_items(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
 317     const char* indent = Indents[thread_work_items->_indent_level];





 318 
 319     assert(thread_work_items->_print_sum, "%s does not have print sum true even though it is a count", thread_work_items->_title);
 320 
 321     log_debug(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT,
 322         indent, thread_work_items->_title,
 323         _phase_times->min_thread_work_items(phase_id), _phase_times->average_thread_work_items(phase_id), _phase_times->max_thread_work_items(phase_id),
 324         _phase_times->max_thread_work_items(phase_id) - _phase_times->min_thread_work_items(phase_id), _phase_times->sum_thread_work_items(phase_id));
 325 
 326     print_count_values(indent, phase_id, thread_work_items);
 327   }
 328 
 329   void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
 330     const char* indent = Indents[phase->_indent_level];

 331 
 332     if (phase->_print_sum) {
 333       log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf",
 334           indent, phase->_title,
 335           _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
 336           _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id), _phase_times->sum_time_ms(phase_id));
 337     } else {
 338       log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf",
 339           indent, phase->_title,
 340           _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
 341           _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));





 342     }
 343 
 344     print_time_values(indent, phase_id);
 345 
 346     if (phase->_thread_work_items != NULL) {
 347       print_thread_work_items(phase_id, phase->_thread_work_items);
 348     }
 349   }
 350 };
 351 
 352 void G1GCPhaseTimes::print(double pause_time_sec) {
 353   note_gc_end();
 354 
 355   G1GCParPhasePrinter par_phase_printer(this);
 356 
 357   if (_root_region_scan_wait_time_ms > 0.0) {
 358     print_stats(Indents[1], "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 359   }
 360 
 361   print_stats(Indents[1], "Parallel Time", _cur_collection_par_time_ms);
 362   for (int i = 0; i <= GCMainParPhasesLast; i++) {
 363     par_phase_printer.print((GCParPhases) i);
 364   }
 365 
 366   print_stats(Indents[1], "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
 367   print_stats(Indents[1], "Code Root Purge", _cur_strong_code_root_purge_time_ms);
 368   if (G1StringDedup::is_enabled()) {
 369     print_stats(Indents[1], "String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
 370     for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
 371       par_phase_printer.print((GCParPhases) i);
 372     }
 373   }
 374   print_stats(Indents[1], "Clear CT", _cur_clear_ct_time_ms);
 375   print_stats(Indents[1], "Expand Heap After Collection", _cur_expand_heap_time_ms);

 376   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
 377   print_stats(Indents[1], "Other", misc_time_ms);
 378   if (_cur_verify_before_time_ms > 0.0) {
 379     print_stats(Indents[2], "Verify Before", _cur_verify_before_time_ms);
 380   }
 381   if (G1CollectedHeap::heap()->evacuation_failed()) {
 382     double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
 383       _cur_evac_fail_restore_remsets;
 384     print_stats(Indents[2], "Evacuation Failure", evac_fail_handling);
 385     log_trace(gc, phases)("%sRecalculate Used: %.1lf ms", Indents[3], _cur_evac_fail_recalc_used);
 386     log_trace(gc, phases)("%sRemove Self Forwards: %.1lf ms", Indents[3], _cur_evac_fail_remove_self_forwards);
 387     log_trace(gc, phases)("%sRestore RemSet: %.1lf ms", Indents[3], _cur_evac_fail_restore_remsets);


 388   }
 389   print_stats(Indents[2], "Choose CSet",
 390     (_recorded_young_cset_choice_time_ms +
 391     _recorded_non_young_cset_choice_time_ms));
 392   print_stats(Indents[2], "Ref Proc", _cur_ref_proc_time_ms);
 393   print_stats(Indents[2], "Ref Enq", _cur_ref_enq_time_ms);
 394   print_stats(Indents[2], "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 395   par_phase_printer.print(RedirtyCards);
 396   if (G1EagerReclaimHumongousObjects) {
 397     print_stats(Indents[2], "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 398 
 399     log_trace(gc, phases)("%sHumongous Total: " SIZE_FORMAT, Indents[3], _cur_fast_reclaim_humongous_total);
 400     log_trace(gc, phases)("%sHumongous Candidate: " SIZE_FORMAT, Indents[3], _cur_fast_reclaim_humongous_candidates);
 401     print_stats(Indents[2], "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 402     log_trace(gc, phases)("%sHumongous Reclaimed: " SIZE_FORMAT, Indents[3], _cur_fast_reclaim_humongous_reclaimed);



 403   }
 404   print_stats(Indents[2], "Free CSet",
 405     (_recorded_young_free_cset_time_ms +
 406     _recorded_non_young_free_cset_time_ms));
 407   log_trace(gc, phases)("%sYoung Free CSet: %.1lf ms", Indents[3], _recorded_young_free_cset_time_ms);
 408   log_trace(gc, phases)("%sNon-Young Free CSet: %.1lf ms", Indents[3], _recorded_non_young_free_cset_time_ms);


 409   if (_cur_verify_after_time_ms > 0.0) {
 410     print_stats(Indents[2], "Verify After", _cur_verify_after_time_ms);
 411   }
 412 }
 413 
 414 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 415     _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
 416   if (_phase_times != NULL) {
 417     _start_time = os::elapsedTime();
 418   }
 419 }
 420 
 421 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 422   if (_phase_times != NULL) {
 423     _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
 424   }
 425 }
 426 
< prev index next >