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