95 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
96 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
97 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
98
99 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
100 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
101
102 _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
103
104 reset();
105 }
106
107 void G1GCPhaseTimes::reset() {
108 _cur_collection_par_time_ms = 0.0;
109 _cur_collection_code_root_fixup_time_ms = 0.0;
110 _cur_strong_code_root_purge_time_ms = 0.0;
111 _cur_evac_fail_recalc_used = 0.0;
112 _cur_evac_fail_restore_remsets = 0.0;
113 _cur_evac_fail_remove_self_forwards = 0.0;
114 _cur_string_dedup_fixup_time_ms = 0.0;
115 _cur_clear_ct_time_ms = 0.0;
116 _cur_expand_heap_time_ms = 0.0;
117 _cur_ref_proc_time_ms = 0.0;
118 _cur_ref_enq_time_ms = 0.0;
119 _cur_collection_start_sec = 0.0;
120 _root_region_scan_wait_time_ms = 0.0;
121 _external_accounted_time_ms = 0.0;
122 _recorded_clear_claimed_marks_time_ms = 0.0;
123 _recorded_young_cset_choice_time_ms = 0.0;
124 _recorded_non_young_cset_choice_time_ms = 0.0;
125 _recorded_redirty_logged_cards_time_ms = 0.0;
126 _recorded_preserve_cm_referents_time_ms = 0.0;
127 _recorded_merge_pss_time_ms = 0.0;
128 _recorded_total_free_cset_time_ms = 0.0;
129 _recorded_serial_free_cset_time_ms = 0.0;
130 _cur_fast_reclaim_humongous_time_ms = 0.0;
131 _cur_fast_reclaim_humongous_register_time_ms = 0.0;
132 _cur_fast_reclaim_humongous_total = 0;
133 _cur_fast_reclaim_humongous_candidates = 0;
134 _cur_fast_reclaim_humongous_reclaimed = 0;
135 _cur_verify_before_time_ms = 0.0;
136 _cur_verify_after_time_ms = 0.0;
137
138 for (int i = 0; i < GCParPhasesSentinel; i++) {
139 if (_gc_par_phases[i] != NULL) {
140 _gc_par_phases[i]->reset();
141 }
142 }
143 }
144
145 void G1GCPhaseTimes::note_gc_start() {
146 _gc_start_counter = os::elapsed_counter();
147 reset();
271
272 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
273 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
274 }
275
276 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
277 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
278 }
279
280 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
281 const double sum_ms = _root_region_scan_wait_time_ms +
282 _recorded_young_cset_choice_time_ms +
283 _recorded_non_young_cset_choice_time_ms +
284 _cur_fast_reclaim_humongous_register_time_ms;
285
286 info_time("Pre Evacuate Collection Set", sum_ms);
287
288 if (_root_region_scan_wait_time_ms > 0.0) {
289 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
290 }
291 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
292 if (G1EagerReclaimHumongousObjects) {
293 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
294 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
295 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
296 }
297
298 return sum_ms;
299 }
300
301 double G1GCPhaseTimes::print_evacuate_collection_set() const {
302 const double sum_ms = _cur_collection_par_time_ms;
303
304 info_time("Evacuate Collection Set", sum_ms);
305
306 trace_phase(_gc_par_phases[GCWorkerStart], false);
307 debug_phase(_gc_par_phases[ExtRootScan]);
308 for (int i = ThreadRoots; i <= SATBFiltering; i++) {
309 trace_phase(_gc_par_phases[i]);
310 }
358 debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
359 debug_phase(_gc_par_phases[StringDedupQueueFixup]);
360 debug_phase(_gc_par_phases[StringDedupTableFixup]);
361 }
362
363 debug_time("Clear Card Table", _cur_clear_ct_time_ms);
364
365 if (G1CollectedHeap::heap()->evacuation_failed()) {
366 debug_time("Evacuation Failure", evac_fail_handling);
367 trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
368 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
369 trace_time("Restore RemSet", _cur_evac_fail_restore_remsets);
370 }
371
372 debug_time("Reference Enqueuing", _cur_ref_enq_time_ms);
373
374 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
375 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
376
377 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
378 if (_recorded_clear_claimed_marks_time_ms > 0.0) {
379 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
380 }
381
382 trace_phase(_gc_par_phases[RedirtyCards]);
383
384 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
385 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
386 trace_phase(_gc_par_phases[YoungFreeCSet]);
387 trace_phase(_gc_par_phases[NonYoungFreeCSet]);
388
389 if (G1EagerReclaimHumongousObjects) {
390 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
391 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
392 }
393 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
394
395
396 return sum_ms;
397 }
398
399 void G1GCPhaseTimes::print_other(double accounted_ms) const {
400 info_time("Other", _gc_pause_time_ms - accounted_ms);
401 }
402
403 void G1GCPhaseTimes::print() {
404 note_gc_end();
405
406 if (_cur_verify_before_time_ms > 0.0) {
407 debug_time("Verify Before", _cur_verify_before_time_ms);
408 }
409
410 double accounted_ms = 0.0;
411 accounted_ms += print_pre_evacuate_collection_set();
|
95 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
96 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
97 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
98
99 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
100 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
101
102 _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
103
104 reset();
105 }
106
107 void G1GCPhaseTimes::reset() {
108 _cur_collection_par_time_ms = 0.0;
109 _cur_collection_code_root_fixup_time_ms = 0.0;
110 _cur_strong_code_root_purge_time_ms = 0.0;
111 _cur_evac_fail_recalc_used = 0.0;
112 _cur_evac_fail_restore_remsets = 0.0;
113 _cur_evac_fail_remove_self_forwards = 0.0;
114 _cur_string_dedup_fixup_time_ms = 0.0;
115 _cur_prepare_tlab_time_ms = 0.0;
116 _cur_resize_tlab_time_ms = 0.0;
117 _cur_dpt_update_time_ms = 0.0;
118 _cur_clear_ct_time_ms = 0.0;
119 _cur_expand_heap_time_ms = 0.0;
120 _cur_ref_proc_time_ms = 0.0;
121 _cur_ref_enq_time_ms = 0.0;
122 _cur_collection_start_sec = 0.0;
123 _root_region_scan_wait_time_ms = 0.0;
124 _external_accounted_time_ms = 0.0;
125 _recorded_clear_claimed_marks_time_ms = 0.0;
126 _recorded_young_cset_choice_time_ms = 0.0;
127 _recorded_non_young_cset_choice_time_ms = 0.0;
128 _recorded_redirty_logged_cards_time_ms = 0.0;
129 _recorded_preserve_cm_referents_time_ms = 0.0;
130 _recorded_merge_pss_time_ms = 0.0;
131 _recorded_start_new_cset_time_ms = 0.0;
132 _recorded_total_free_cset_time_ms = 0.0;
133 _recorded_serial_free_cset_time_ms = 0.0;
134 _cur_fast_reclaim_humongous_time_ms = 0.0;
135 _cur_fast_reclaim_humongous_register_time_ms = 0.0;
136 _cur_fast_reclaim_humongous_total = 0;
137 _cur_fast_reclaim_humongous_candidates = 0;
138 _cur_fast_reclaim_humongous_reclaimed = 0;
139 _cur_verify_before_time_ms = 0.0;
140 _cur_verify_after_time_ms = 0.0;
141
142 for (int i = 0; i < GCParPhasesSentinel; i++) {
143 if (_gc_par_phases[i] != NULL) {
144 _gc_par_phases[i]->reset();
145 }
146 }
147 }
148
149 void G1GCPhaseTimes::note_gc_start() {
150 _gc_start_counter = os::elapsed_counter();
151 reset();
275
276 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
277 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
278 }
279
280 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
281 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
282 }
283
284 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
285 const double sum_ms = _root_region_scan_wait_time_ms +
286 _recorded_young_cset_choice_time_ms +
287 _recorded_non_young_cset_choice_time_ms +
288 _cur_fast_reclaim_humongous_register_time_ms;
289
290 info_time("Pre Evacuate Collection Set", sum_ms);
291
292 if (_root_region_scan_wait_time_ms > 0.0) {
293 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
294 }
295 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
296 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
297 if (G1EagerReclaimHumongousObjects) {
298 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
299 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
300 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
301 }
302
303 return sum_ms;
304 }
305
306 double G1GCPhaseTimes::print_evacuate_collection_set() const {
307 const double sum_ms = _cur_collection_par_time_ms;
308
309 info_time("Evacuate Collection Set", sum_ms);
310
311 trace_phase(_gc_par_phases[GCWorkerStart], false);
312 debug_phase(_gc_par_phases[ExtRootScan]);
313 for (int i = ThreadRoots; i <= SATBFiltering; i++) {
314 trace_phase(_gc_par_phases[i]);
315 }
363 debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
364 debug_phase(_gc_par_phases[StringDedupQueueFixup]);
365 debug_phase(_gc_par_phases[StringDedupTableFixup]);
366 }
367
368 debug_time("Clear Card Table", _cur_clear_ct_time_ms);
369
370 if (G1CollectedHeap::heap()->evacuation_failed()) {
371 debug_time("Evacuation Failure", evac_fail_handling);
372 trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
373 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
374 trace_time("Restore RemSet", _cur_evac_fail_restore_remsets);
375 }
376
377 debug_time("Reference Enqueuing", _cur_ref_enq_time_ms);
378
379 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
380 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
381
382 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
383 #if defined(COMPILER2) || INCLUDE_JVMCI
384 debug_time("DPT Update", _cur_dpt_update_time_ms);
385 #endif
386 if (_recorded_clear_claimed_marks_time_ms > 0.0) {
387 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
388 }
389
390 trace_phase(_gc_par_phases[RedirtyCards]);
391
392 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
393 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
394 trace_phase(_gc_par_phases[YoungFreeCSet]);
395 trace_phase(_gc_par_phases[NonYoungFreeCSet]);
396
397 if (G1EagerReclaimHumongousObjects) {
398 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
399 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
400 }
401 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
402 if (UseTLAB && ResizeTLAB) {
403 debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
404 }
405 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
406
407
408 return sum_ms;
409 }
410
411 void G1GCPhaseTimes::print_other(double accounted_ms) const {
412 info_time("Other", _gc_pause_time_ms - accounted_ms);
413 }
414
415 void G1GCPhaseTimes::print() {
416 note_gc_end();
417
418 if (_cur_verify_before_time_ms > 0.0) {
419 debug_time("Verify Before", _cur_verify_before_time_ms);
420 }
421
422 double accounted_ms = 0.0;
423 accounted_ms += print_pre_evacuate_collection_set();
|