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) {
|
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_ms) {
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_ms - 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) {
|