144 reset();
145 }
146
147 void G1GCPhaseTimes::reset() {
148 _cur_collection_initial_evac_time_ms = 0.0;
149 _cur_optional_evac_time_ms = 0.0;
150 _cur_collection_code_root_fixup_time_ms = 0.0;
151 _cur_strong_code_root_purge_time_ms = 0.0;
152 _cur_merge_heap_roots_time_ms = 0.0;
153 _cur_optional_merge_heap_roots_time_ms = 0.0;
154 _cur_prepare_merge_heap_roots_time_ms = 0.0;
155 _cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
156 _cur_evac_fail_recalc_used = 0.0;
157 _cur_evac_fail_remove_self_forwards = 0.0;
158 _cur_string_deduplication_time_ms = 0.0;
159 _cur_prepare_tlab_time_ms = 0.0;
160 _cur_resize_tlab_time_ms = 0.0;
161 _cur_concatenate_dirty_card_logs_time_ms = 0.0;
162 _cur_derived_pointer_table_update_time_ms = 0.0;
163 _cur_clear_ct_time_ms = 0.0;
164 _cur_expand_heap_time_ms = 0.0;
165 _cur_ref_proc_time_ms = 0.0;
166 _cur_collection_start_sec = 0.0;
167 _root_region_scan_wait_time_ms = 0.0;
168 _external_accounted_time_ms = 0.0;
169 _recorded_prepare_heap_roots_time_ms = 0.0;
170 _recorded_clear_claimed_marks_time_ms = 0.0;
171 _recorded_young_cset_choice_time_ms = 0.0;
172 _recorded_non_young_cset_choice_time_ms = 0.0;
173 _recorded_redirty_logged_cards_time_ms = 0.0;
174 _recorded_preserve_cm_referents_time_ms = 0.0;
175 _recorded_start_new_cset_time_ms = 0.0;
176 _recorded_total_free_cset_time_ms = 0.0;
177 _recorded_serial_free_cset_time_ms = 0.0;
178 _recorded_total_rebuild_freelist_time_ms = 0.0;
179 _recorded_serial_rebuild_freelist_time_ms = 0.0;
180 _cur_fast_reclaim_humongous_time_ms = 0.0;
181 _cur_region_register_time = 0.0;
182 _cur_fast_reclaim_humongous_total = 0;
183 _cur_fast_reclaim_humongous_candidates = 0;
184 _cur_fast_reclaim_humongous_reclaimed = 0;
454 return _cur_collection_initial_evac_time_ms + _cur_merge_heap_roots_time_ms;
455 }
456
457 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
458 const double evac_fail_handling = _cur_evac_fail_recalc_used +
459 _cur_evac_fail_remove_self_forwards;
460 assert(_gc_par_phases[MergePSS]->get(0) != WorkerDataArray<double>::uninitialized(), "must be set");
461 const double merge_pss = _gc_par_phases[MergePSS]->get(0) * MILLIUNITS;
462 const double sum_ms = evac_fail_handling +
463 _cur_collection_code_root_fixup_time_ms +
464 _recorded_preserve_cm_referents_time_ms +
465 _cur_ref_proc_time_ms +
466 (_weak_phase_times.total_time_sec() * MILLIUNITS) +
467 _cur_clear_ct_time_ms +
468 merge_pss +
469 _cur_strong_code_root_purge_time_ms +
470 _recorded_redirty_logged_cards_time_ms +
471 _recorded_total_free_cset_time_ms +
472 _recorded_total_rebuild_freelist_time_ms +
473 _cur_fast_reclaim_humongous_time_ms +
474 _cur_expand_heap_time_ms +
475 _cur_string_deduplication_time_ms;
476
477 info_time("Post Evacuate Collection Set", sum_ms);
478
479 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
480
481 debug_time("Clear Card Table", _cur_clear_ct_time_ms);
482
483 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
484 _ref_phase_times.print_all_references(2, false);
485 _weak_phase_times.log_print(2);
486
487 if (G1StringDedup::is_enabled()) {
488 debug_time("String Deduplication", _cur_string_deduplication_time_ms);
489 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1);
490 debug_phase(_gc_par_phases[StringDedupTableFixup], 1);
491 }
492
493 if (G1CollectedHeap::heap()->evacuation_failed()) {
494 debug_time("Evacuation Failure", evac_fail_handling);
506 #endif
507
508 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
509 trace_time("Serial Free Collection Set", _recorded_serial_free_cset_time_ms);
510 trace_phase(_gc_par_phases[ParFreeCSet]);
511 trace_phase(_gc_par_phases[YoungFreeCSet], true, 1);
512 trace_phase(_gc_par_phases[NonYoungFreeCSet], true, 1);
513
514 debug_time("Rebuild Free List", _recorded_total_rebuild_freelist_time_ms);
515 trace_time("Serial Rebuild Free List ", _recorded_serial_rebuild_freelist_time_ms);
516 trace_phase(_gc_par_phases[RebuildFreeList]);
517
518 if (G1EagerReclaimHumongousObjects) {
519 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
520 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
521 }
522 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
523 if (UseTLAB && ResizeTLAB) {
524 debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
525 }
526 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
527
528
529 return sum_ms;
530 }
531
532 void G1GCPhaseTimes::print_other(double accounted_ms) const {
533 info_time("Other", _gc_pause_time_ms - accounted_ms);
534 }
535
536 void G1GCPhaseTimes::print() {
537 note_gc_end();
538
539 if (_cur_verify_before_time_ms > 0.0) {
540 debug_time("Verify Before", _cur_verify_before_time_ms);
541 }
542
543 double accounted_ms = 0.0;
544 accounted_ms += print_pre_evacuate_collection_set();
545 accounted_ms += print_evacuate_initial_collection_set();
546 accounted_ms += print_evacuate_optional_collection_set();
547 accounted_ms += print_post_evacuate_collection_set();
|
144 reset();
145 }
146
147 void G1GCPhaseTimes::reset() {
148 _cur_collection_initial_evac_time_ms = 0.0;
149 _cur_optional_evac_time_ms = 0.0;
150 _cur_collection_code_root_fixup_time_ms = 0.0;
151 _cur_strong_code_root_purge_time_ms = 0.0;
152 _cur_merge_heap_roots_time_ms = 0.0;
153 _cur_optional_merge_heap_roots_time_ms = 0.0;
154 _cur_prepare_merge_heap_roots_time_ms = 0.0;
155 _cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
156 _cur_evac_fail_recalc_used = 0.0;
157 _cur_evac_fail_remove_self_forwards = 0.0;
158 _cur_string_deduplication_time_ms = 0.0;
159 _cur_prepare_tlab_time_ms = 0.0;
160 _cur_resize_tlab_time_ms = 0.0;
161 _cur_concatenate_dirty_card_logs_time_ms = 0.0;
162 _cur_derived_pointer_table_update_time_ms = 0.0;
163 _cur_clear_ct_time_ms = 0.0;
164 _cur_resize_heap_time_ms = 0.0;
165 _cur_ref_proc_time_ms = 0.0;
166 _cur_collection_start_sec = 0.0;
167 _root_region_scan_wait_time_ms = 0.0;
168 _external_accounted_time_ms = 0.0;
169 _recorded_prepare_heap_roots_time_ms = 0.0;
170 _recorded_clear_claimed_marks_time_ms = 0.0;
171 _recorded_young_cset_choice_time_ms = 0.0;
172 _recorded_non_young_cset_choice_time_ms = 0.0;
173 _recorded_redirty_logged_cards_time_ms = 0.0;
174 _recorded_preserve_cm_referents_time_ms = 0.0;
175 _recorded_start_new_cset_time_ms = 0.0;
176 _recorded_total_free_cset_time_ms = 0.0;
177 _recorded_serial_free_cset_time_ms = 0.0;
178 _recorded_total_rebuild_freelist_time_ms = 0.0;
179 _recorded_serial_rebuild_freelist_time_ms = 0.0;
180 _cur_fast_reclaim_humongous_time_ms = 0.0;
181 _cur_region_register_time = 0.0;
182 _cur_fast_reclaim_humongous_total = 0;
183 _cur_fast_reclaim_humongous_candidates = 0;
184 _cur_fast_reclaim_humongous_reclaimed = 0;
454 return _cur_collection_initial_evac_time_ms + _cur_merge_heap_roots_time_ms;
455 }
456
457 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
458 const double evac_fail_handling = _cur_evac_fail_recalc_used +
459 _cur_evac_fail_remove_self_forwards;
460 assert(_gc_par_phases[MergePSS]->get(0) != WorkerDataArray<double>::uninitialized(), "must be set");
461 const double merge_pss = _gc_par_phases[MergePSS]->get(0) * MILLIUNITS;
462 const double sum_ms = evac_fail_handling +
463 _cur_collection_code_root_fixup_time_ms +
464 _recorded_preserve_cm_referents_time_ms +
465 _cur_ref_proc_time_ms +
466 (_weak_phase_times.total_time_sec() * MILLIUNITS) +
467 _cur_clear_ct_time_ms +
468 merge_pss +
469 _cur_strong_code_root_purge_time_ms +
470 _recorded_redirty_logged_cards_time_ms +
471 _recorded_total_free_cset_time_ms +
472 _recorded_total_rebuild_freelist_time_ms +
473 _cur_fast_reclaim_humongous_time_ms +
474 _cur_resize_heap_time_ms +
475 _cur_string_deduplication_time_ms;
476
477 info_time("Post Evacuate Collection Set", sum_ms);
478
479 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
480
481 debug_time("Clear Card Table", _cur_clear_ct_time_ms);
482
483 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
484 _ref_phase_times.print_all_references(2, false);
485 _weak_phase_times.log_print(2);
486
487 if (G1StringDedup::is_enabled()) {
488 debug_time("String Deduplication", _cur_string_deduplication_time_ms);
489 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1);
490 debug_phase(_gc_par_phases[StringDedupTableFixup], 1);
491 }
492
493 if (G1CollectedHeap::heap()->evacuation_failed()) {
494 debug_time("Evacuation Failure", evac_fail_handling);
506 #endif
507
508 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
509 trace_time("Serial Free Collection Set", _recorded_serial_free_cset_time_ms);
510 trace_phase(_gc_par_phases[ParFreeCSet]);
511 trace_phase(_gc_par_phases[YoungFreeCSet], true, 1);
512 trace_phase(_gc_par_phases[NonYoungFreeCSet], true, 1);
513
514 debug_time("Rebuild Free List", _recorded_total_rebuild_freelist_time_ms);
515 trace_time("Serial Rebuild Free List ", _recorded_serial_rebuild_freelist_time_ms);
516 trace_phase(_gc_par_phases[RebuildFreeList]);
517
518 if (G1EagerReclaimHumongousObjects) {
519 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
520 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
521 }
522 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
523 if (UseTLAB && ResizeTLAB) {
524 debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
525 }
526 debug_time("Resize Heap After Collection", _cur_resize_heap_time_ms);
527
528 return sum_ms;
529 }
530
531 void G1GCPhaseTimes::print_other(double accounted_ms) const {
532 info_time("Other", _gc_pause_time_ms - accounted_ms);
533 }
534
535 void G1GCPhaseTimes::print() {
536 note_gc_end();
537
538 if (_cur_verify_before_time_ms > 0.0) {
539 debug_time("Verify Before", _cur_verify_before_time_ms);
540 }
541
542 double accounted_ms = 0.0;
543 accounted_ms += print_pre_evacuate_collection_set();
544 accounted_ms += print_evacuate_initial_collection_set();
545 accounted_ms += print_evacuate_optional_collection_set();
546 accounted_ms += print_post_evacuate_collection_set();
|