31 #include "memory/allocation.hpp"

    31 #include "memory/resourceArea.hpp"

    36 // Helper class for avoiding interleaved logging

    36 static const char* Indents[5] = {"", "  ", "    ", "     ", "       "};

    37 class LineBuffer: public StackObj {

    38 

    39 private:

    40   static const int BUFFER_LEN = 1024;

    41   static const int INDENT_CHARS = 3;

    42   char _buffer[BUFFER_LEN];

    43   int _indent_level;

    44   int _cur;

    45 

    46   void vappend(const char* format, va_list ap)  ATTRIBUTE_PRINTF(2, 0) {

    47     int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);

    48     if (res != -1) {

    49       _cur += res;

    50     } else {

    51       DEBUG_ONLY(warning("buffer too small in LineBuffer");)

    52       _buffer[BUFFER_LEN -1] = 0;

    53       _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again

    54     }

    55   }

    56 

    57 public:

    58   explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {

    59     for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {

    60       _buffer[_cur] = ' ';

    61     }

    62   }

    63 

    64 #ifndef PRODUCT

    65   ~LineBuffer() {

    66     assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");

    67   }

    68 #endif

    69 

    70   void append(const char* format, ...)  ATTRIBUTE_PRINTF(2, 3) {

    71     va_list ap;

    72     va_start(ap, format);

    73     vappend(format, ap);

    74     va_end(ap);

    75   }

    76 

    77   const char* to_string() {

    78     _cur = _indent_level * INDENT_CHARS;

    79     return _buffer;

    80   }

    81 };

    82 

    83 static const char* Indents[4] = {"", "   ", "      ", "         "};

    90   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start:", false, 2);

    43   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");

    91   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning:", true, 2);

    44   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");

    94   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots:", true, 3);

    47   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");

    95   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots:", true, 3);

    48   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");

    96   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots:", true, 3);

    49   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");

    97   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots:", true, 3);

    50   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");

    98   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots:", true, 3);

    51   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");

    99   _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots:", true, 3);

    52   _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):");

   100   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots:", true, 3);

    53   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");

   101   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots:", true, 3);

    54   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");

   102   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots:", true, 3);

    55   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");

   103   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots:", true, 3);

    56   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");

   104   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots:", true, 3);

    57   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");

   105   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD:", true, 3);

    58   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");

   106   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots:", true, 3);

    59   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");

   107   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering:", true, 3);

    60   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");

   108 

    61 

   109   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS:", true, 2);

    62   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");

   110   _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC:", true, 3);

    63   if (ConcurrentG1Refine::hot_card_cache_enabled()) {

   111   _gc_par_phases[ScanHCC]->set_enabled(ConcurrentG1Refine::hot_card_cache_enabled());

    64     _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");

   112   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS:", true, 2);

    65   } else {

   113   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning:", true, 2);

    66     _gc_par_phases[ScanHCC] = NULL;

   114   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy:", true, 2);

    67   }

   115   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination:", true, 2);

    68   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");

   116   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total:", true, 2);

    69   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");

   117   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End:", false, 2);

    70   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");

   118   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other:", true, 2);

    71   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");

   119 

    72   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");

   120   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:", true, 3);

    73   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");

    74   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");

    75 

    76   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");

   123   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:", true, 3);

    79   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");

   126   _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup:", true, 2);

    82   if (UseStringDeduplication) {

   127   _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup:", true, 2);

    83     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");

   128 

    84     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");

   129   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty:", true, 3);

    85   } else {

   130   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:", true, 3);

    86     _gc_par_phases[StringDedupQueueFixup] = NULL;

    87     _gc_par_phases[StringDedupTableFixup] = NULL;

    88   }

    89 

    90   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");

    91   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");

   133   _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs:", true, 3);

    94   _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");

   145     _gc_par_phases[i]->reset();

   106     if (_gc_par_phases[i] != NULL) {

   146   }

   107       _gc_par_phases[i]->reset();

   147 

   108     }

   148   _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());

   109   }

   149   _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());

   171     _gc_par_phases[i]->verify(_active_gc_threads);

   131     if (_gc_par_phases[i] != NULL) {

   172   }

   132       _gc_par_phases[i]->verify(_active_gc_threads);

   173 }

   174 

   175 void G1GCPhaseTimes::print_stats(const char* indent, const char* str, double value) {

   176   log_debug(gc, phases)("%s%s: %.1lf ms", indent, str, value);

   177 }

   178 

   179 double G1GCPhaseTimes::accounted_time_ms() {

   180     // First subtract any externally accounted time

   181     double misc_time_ms = _external_accounted_time_ms;

   182 

   183     // Subtract the root region scanning wait time. It's initialized to

   184     // zero at the start of the pause.

   185     misc_time_ms += _root_region_scan_wait_time_ms;

   186 

   187     misc_time_ms += _cur_collection_par_time_ms;

   188 

   189     // Now subtract the time taken to fix up roots in generated code

   190     misc_time_ms += _cur_collection_code_root_fixup_time_ms;

   191 

   192     // Strong code root purge time

   193     misc_time_ms += _cur_strong_code_root_purge_time_ms;

   194 

   195     if (G1StringDedup::is_enabled()) {

   196       // String dedup fixup time

   197       misc_time_ms += _cur_string_dedup_fixup_time_ms;

   199 

   134   }

   200     // Subtract the time taken to clean the card table from the

   201     // current value of "other time"

   202     misc_time_ms += _cur_clear_ct_time_ms;

   203 

   204     // Remove expand heap time from "other time"

   205     misc_time_ms += _cur_expand_heap_time_ms;

   206 

   207     return misc_time_ms;

   255 double G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) {

   161 template <class T>

   256   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");

   162 void G1GCPhaseTimes::details(T* phase, const char* indent) {

   257   return _gc_par_phases[phase]->thread_work_items()->average(_active_gc_threads);

   163   LogHandle(gc, phases, task) log;

   258 }

   164   if (log.is_level(LogLevel::Trace)) {

   259 

   165     outputStream* trace_out = log.trace_stream();

   260 size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {

   166     trace_out->print("%s", indent);

   261   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");

   167     phase->print_details_on(trace_out, _active_gc_threads);

   262   return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads);

   168   }

   263 }

   169 }

   264 

   170 

   265 size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {

   171 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {

   266   assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");

   172   out->print("%s", Indents[indent]);

   267   return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads);

   173   phase->print_summary_on(out, _active_gc_threads, print_sum);

   268 }

   174   details(phase, Indents[indent]);

   269 

   175 

   270 class G1GCParPhasePrinter : public StackObj {

   176   WorkerDataArray<size_t>* work_items = phase->thread_work_items();

   271   G1GCPhaseTimes* _phase_times;

   177   if (work_items != NULL) {

   272  public:

   178     out->print("%s", Indents[indent + 1]);

   273   G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {}

   179     work_items->print_summary_on(out, _active_gc_threads, true);

   274 

   180     details(work_items, Indents[indent + 1]);

   275   void print(G1GCPhaseTimes::GCParPhases phase_id) {

   181   }

   276     WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id];

   182 }

   277 

   183 

   278     if (phase->_length == 1) {

   184 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {

   279       print_single_length(phase_id, phase);

   185   LogHandle(gc, phases) log;

   280     } else {

   186   if (log.is_level(LogLevel::Debug)) {

   281       print_multi_length(phase_id, phase);

   187     ResourceMark rm;

   282     }

   188     log_phase(phase, 2, log.debug_stream(), true);

   283   }

   189   }

   284 

   190 }

   285 

   191 

   286  private:

   192 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) {

   287   void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {

   193   LogHandle(gc, phases) log;

   288     // No need for min, max, average and sum for only one worker

   194   if (log.is_level(LogLevel::Trace)) {

   289     log_debug(gc, phases)("%s%s:  %.1lf", Indents[phase->_indent_level], phase->_title, _phase_times->get_time_ms(phase_id, 0));

   195     ResourceMark rm;

   290 

   196     log_phase(phase, 3, log.trace_stream(), print_sum);

   291     WorkerDataArray<size_t>* work_items = phase->_thread_work_items;

   197   }

   292     if (work_items != NULL) {

   198 }

   293       log_debug(gc, phases)("%s%s:  " SIZE_FORMAT, Indents[work_items->_indent_level], work_items->_title, _phase_times->sum_thread_work_items(phase_id));

   199 

   294     }

   200 #define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms"

   295   }

   201 #define PHASE_SIZE_FORMAT "%s%s: " SIZE_FORMAT

   296 

   202 

   297   void print_time_values(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) {

   203 #define info_line(str, value) \

   298     if (log_is_enabled(Trace, gc)) {

   204   log_info(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[1], str, value);

   299       LineBuffer buf(0);

   205 

   300       uint active_length = _phase_times->_active_gc_threads;

   206 #define debug_line(str, value) \

   301       for (uint i = 0; i < active_length; ++i) {

   207   log_debug(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[2], str, value);

   302         buf.append(" %4.1lf", _phase_times->get_time_ms(phase_id, i));

   208 

   303       }

   209 #define trace_line(str, value) \

   304       const char* line = buf.to_string();

   210   log_trace(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[3], str, value);

   305       log_trace(gc, phases)("%s%-25s%s", indent, "", line);

   211 

   306     }

   212 #define trace_line_sz(str, value) \

   307   }

   213   log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);

   308 

   214 

   309   void print_count_values(const char* indent, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {

   215 #define trace_line_ms(str, value) \

   310     if (log_is_enabled(Trace, gc)) {

   216   log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value);

   311       LineBuffer buf(0);

   217 

   312       uint active_length = _phase_times->_active_gc_threads;

   218 #define info_line_and_account(str, value) \

   313       for (uint i = 0; i < active_length; ++i) {

   219   info_line(str, value);                  \

   314         buf.append("  " SIZE_FORMAT, _phase_times->get_thread_work_item(phase_id, i));

   220   accounted_time_ms += value;

   315       }

   316       const char* line = buf.to_string();

   317       log_trace(gc, phases)("%s%-25s%s", indent, "", line);

   318     }

   319   }

   320 

   321   void print_thread_work_items(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {

   322     const char* indent = Indents[thread_work_items->_indent_level];

   323 

   324     assert(thread_work_items->_print_sum, "%s does not have print sum true even though it is a count", thread_work_items->_title);

   325 

   326     log_debug(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT,

   327         indent, thread_work_items->_title,

   328         _phase_times->min_thread_work_items(phase_id), _phase_times->average_thread_work_items(phase_id), _phase_times->max_thread_work_items(phase_id),

   329         _phase_times->max_thread_work_items(phase_id) - _phase_times->min_thread_work_items(phase_id), _phase_times->sum_thread_work_items(phase_id));

   330 

   331     print_count_values(indent, phase_id, thread_work_items);

   332   }

   333 

   334   void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {

   335     const char* indent = Indents[phase->_indent_level];

   336 

   337     if (phase->_print_sum) {

   338       log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %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), _phase_times->sum_time_ms(phase_id));

   342     } else {

   343       log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf",

   344           indent, phase->_title,

   345           _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),

   346           _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));

   347     }

   348 

   349     print_time_values(indent, phase_id);

   350 

   351     if (phase->_thread_work_items != NULL) {

   352       print_thread_work_items(phase_id, phase->_thread_work_items);

   353     }

   354   }

   355 };

   360   G1GCParPhasePrinter par_phase_printer(this);

   225   double accounted_time_ms = _external_accounted_time_ms;

   361 

   363     print_stats(Indents[1], "Root Region Scan Waiting", _root_region_scan_wait_time_ms);

   227     info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms);

   364   }

   228   }

   365 

   229 

   366   print_stats(Indents[1], "Parallel Time", _cur_collection_par_time_ms);

   230   info_line_and_account("Evacuate Collection Set", _cur_collection_par_time_ms);

   367   for (int i = 0; i <= GCMainParPhasesLast; i++) {

   231   trace_phase(_gc_par_phases[GCWorkerStart], false);

   368     par_phase_printer.print((GCParPhases) i);

   232   debug_phase(_gc_par_phases[ExtRootScan]);

   369   }

   233   for (int i = ThreadRoots; i <= SATBFiltering; i++) {

   370 

   234     trace_phase(_gc_par_phases[i]);

   371   print_stats(Indents[1], "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);

   235   }

   372   print_stats(Indents[1], "Code Root Purge", _cur_strong_code_root_purge_time_ms);

   236   debug_phase(_gc_par_phases[UpdateRS]);

   237   if (ConcurrentG1Refine::hot_card_cache_enabled()) {

   238     trace_phase(_gc_par_phases[ScanHCC]);

   239   }

   240   debug_phase(_gc_par_phases[ScanRS]);

   241   debug_phase(_gc_par_phases[CodeRoots]);

   242   debug_phase(_gc_par_phases[ObjCopy]);

   243   debug_phase(_gc_par_phases[Termination]);

   244   debug_phase(_gc_par_phases[Other]);

   245   debug_phase(_gc_par_phases[GCWorkerTotal]);

   246   trace_phase(_gc_par_phases[GCWorkerEnd], false);

   247 

   248   info_line_and_account("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms);

   249   debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);

   250   debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms);

   251 

   374     print_stats(Indents[1], "String Dedup Fixup", _cur_string_dedup_fixup_time_ms);

   253     info_line_and_account("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);

   375     for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {

   254     debug_phase(_gc_par_phases[StringDedupQueueFixup]);

   376       par_phase_printer.print((GCParPhases) i);

   255     debug_phase(_gc_par_phases[StringDedupTableFixup]);

   377     }

   256   }

   378   }

   257   info_line_and_account("Clear Card Table", _cur_clear_ct_time_ms);

   379   print_stats(Indents[1], "Clear CT", _cur_clear_ct_time_ms);

   258   info_line_and_account("Expand Heap After Collection", _cur_expand_heap_time_ms);

   380   print_stats(Indents[1], "Expand Heap After Collection", _cur_expand_heap_time_ms);

   259 

   381   double misc_time_ms = _gc_pause_time_ms - accounted_time_ms();

   260   double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms;

   382   print_stats(Indents[1], "Other", misc_time_ms);

   261   info_line_and_account("Free Collection Set", free_cset_time);

   262   debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms);

   263   debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms);

   264   info_line_and_account("Merge Per-Thread State", _recorded_merge_pss_time_ms);

   265 

   266   info_line("Other", _gc_pause_time_ms - accounted_time_ms);

   384     print_stats(Indents[2], "Verify Before", _cur_verify_before_time_ms);

   268     debug_line("Verify Before", _cur_verify_before_time_ms);

   389     print_stats(Indents[2], "Evacuation Failure", evac_fail_handling);

   273     debug_line("Evacuation Failure", evac_fail_handling);

   390     log_trace(gc, phases)("%sRecalculate Used: %.1lf ms", Indents[3], _cur_evac_fail_recalc_used);

   274     trace_line("Recalculate Used", _cur_evac_fail_recalc_used);

   391     log_trace(gc, phases)("%sRemove Self Forwards: %.1lf ms", Indents[3], _cur_evac_fail_remove_self_forwards);

   275     trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);

   392     log_trace(gc, phases)("%sRestore RemSet: %.1lf ms", Indents[3], _cur_evac_fail_restore_remsets);

   276     trace_line("Restore RemSet", _cur_evac_fail_restore_remsets);

   393   }

   277   }

   394   print_stats(Indents[2], "Choose CSet",

   278   debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));

   395     (_recorded_young_cset_choice_time_ms +

   279   debug_line("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);

   396     _recorded_non_young_cset_choice_time_ms));

   280   debug_line("Ref Proc", _cur_ref_proc_time_ms);

   397   print_stats(Indents[2], "Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);

   281   debug_line("Ref Enq", _cur_ref_enq_time_ms);

   398   print_stats(Indents[2], "Ref Proc", _cur_ref_proc_time_ms);

   282   debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);

   399   print_stats(Indents[2], "Ref Enq", _cur_ref_enq_time_ms);

   283   trace_phase(_gc_par_phases[RedirtyCards]);

   400   print_stats(Indents[2], "Redirty Cards", _recorded_redirty_logged_cards_time_ms);

   284   trace_phase(_gc_par_phases[PreserveCMReferents]);

   401   par_phase_printer.print(RedirtyCards);

   402   par_phase_printer.print(PreserveCMReferents);

   404     print_stats(Indents[2], "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);

   286     debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);

   405 

   287     trace_line_sz("Humongous Total", _cur_fast_reclaim_humongous_total);

   406     log_trace(gc, phases)("%sHumongous Total: " SIZE_FORMAT, Indents[3], _cur_fast_reclaim_humongous_total);

   288     trace_line_sz("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);

   407     log_trace(gc, phases)("%sHumongous Candidate: " SIZE_FORMAT, Indents[3], _cur_fast_reclaim_humongous_candidates);

   289     debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);

   408     print_stats(Indents[2], "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);

   290     trace_line_sz("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);

   409     log_trace(gc, phases)("%sHumongous Reclaimed: " SIZE_FORMAT, Indents[3], _cur_fast_reclaim_humongous_reclaimed);

   291   }

   410   }

   411   print_stats(Indents[2], "Free CSet",

   412     (_recorded_young_free_cset_time_ms +

   413     _recorded_non_young_free_cset_time_ms));

   414   log_trace(gc, phases)("%sYoung Free CSet: %.1lf ms", Indents[3], _recorded_young_free_cset_time_ms);

   415   log_trace(gc, phases)("%sNon-Young Free CSet: %.1lf ms", Indents[3], _recorded_non_young_free_cset_time_ms);

   416   print_stats(Indents[2], "Merge Per-Thread State", _recorded_merge_pss_time_ms);

   418     print_stats(Indents[2], "Verify After", _cur_verify_after_time_ms);

   293     debug_line("Verify After", _cur_verify_after_time_ms);