238 _last_gc_worker_other_times_ms.verify();
239
240 _last_redirty_logged_cards_time_ms.verify();
241 _last_redirty_logged_cards_processed_cards.verify();
242 }
243
244 void G1GCPhaseTimes::note_string_dedup_fixup_start() {
245 _cur_string_dedup_queue_fixup_worker_times_ms.reset();
246 _cur_string_dedup_table_fixup_worker_times_ms.reset();
247 }
248
249 void G1GCPhaseTimes::note_string_dedup_fixup_end() {
250 _cur_string_dedup_queue_fixup_worker_times_ms.verify();
251 _cur_string_dedup_table_fixup_worker_times_ms.verify();
252 }
253
254 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
255 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
256 }
257
258 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
259 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
260 }
261
262 double G1GCPhaseTimes::accounted_time_ms() {
263 // Subtract the root region scanning wait time. It's initialized to
264 // zero at the start of the pause.
265 double misc_time_ms = _root_region_scan_wait_time_ms;
266
267 misc_time_ms += _cur_collection_par_time_ms;
268
269 // Now subtract the time taken to fix up roots in generated code
270 misc_time_ms += _cur_collection_code_root_fixup_time_ms;
271
272 // Strong code root migration time
273 misc_time_ms += _cur_strong_code_root_migration_time_ms;
274
275 // Strong code root purge time
276 misc_time_ms += _cur_strong_code_root_purge_time_ms;
277
340 _cur_evac_fail_restore_remsets;
341 print_stats(2, "Evacuation Failure", evac_fail_handling);
342 if (G1Log::finest()) {
343 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
344 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
345 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
346 }
347 }
348 print_stats(2, "Choose CSet",
349 (_recorded_young_cset_choice_time_ms +
350 _recorded_non_young_cset_choice_time_ms));
351 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
352 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
353 if (G1DeferredRSUpdate) {
354 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
355 if (G1Log::finest()) {
356 _last_redirty_logged_cards_time_ms.print(3, "Parallel Redirty");
357 _last_redirty_logged_cards_processed_cards.print(3, "Redirtied Cards");
358 }
359 }
360 print_stats(2, "Free CSet",
361 (_recorded_young_free_cset_time_ms +
362 _recorded_non_young_free_cset_time_ms));
363 if (G1Log::finest()) {
364 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
365 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
366 }
367 if (_cur_verify_after_time_ms > 0.0) {
368 print_stats(2, "Verify After", _cur_verify_after_time_ms);
369 }
370 }
|
238 _last_gc_worker_other_times_ms.verify();
239
240 _last_redirty_logged_cards_time_ms.verify();
241 _last_redirty_logged_cards_processed_cards.verify();
242 }
243
244 void G1GCPhaseTimes::note_string_dedup_fixup_start() {
245 _cur_string_dedup_queue_fixup_worker_times_ms.reset();
246 _cur_string_dedup_table_fixup_worker_times_ms.reset();
247 }
248
249 void G1GCPhaseTimes::note_string_dedup_fixup_end() {
250 _cur_string_dedup_queue_fixup_worker_times_ms.verify();
251 _cur_string_dedup_table_fixup_worker_times_ms.verify();
252 }
253
254 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
255 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
256 }
257
258 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
259 LineBuffer(level).append_and_print_cr("[%s: "SIZE_FORMAT"]", str, value);
260 }
261
262 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
263 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
264 }
265
266 double G1GCPhaseTimes::accounted_time_ms() {
267 // Subtract the root region scanning wait time. It's initialized to
268 // zero at the start of the pause.
269 double misc_time_ms = _root_region_scan_wait_time_ms;
270
271 misc_time_ms += _cur_collection_par_time_ms;
272
273 // Now subtract the time taken to fix up roots in generated code
274 misc_time_ms += _cur_collection_code_root_fixup_time_ms;
275
276 // Strong code root migration time
277 misc_time_ms += _cur_strong_code_root_migration_time_ms;
278
279 // Strong code root purge time
280 misc_time_ms += _cur_strong_code_root_purge_time_ms;
281
344 _cur_evac_fail_restore_remsets;
345 print_stats(2, "Evacuation Failure", evac_fail_handling);
346 if (G1Log::finest()) {
347 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
348 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
349 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
350 }
351 }
352 print_stats(2, "Choose CSet",
353 (_recorded_young_cset_choice_time_ms +
354 _recorded_non_young_cset_choice_time_ms));
355 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
356 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
357 if (G1DeferredRSUpdate) {
358 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
359 if (G1Log::finest()) {
360 _last_redirty_logged_cards_time_ms.print(3, "Parallel Redirty");
361 _last_redirty_logged_cards_processed_cards.print(3, "Redirtied Cards");
362 }
363 }
364 if (G1ReclaimDeadHumongousObjectsAtYoungGC) {
365 print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
366 if (G1Log::finest()) {
367 print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
368 print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
369 print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
370 }
371 }
372 print_stats(2, "Free CSet",
373 (_recorded_young_free_cset_time_ms +
374 _recorded_non_young_free_cset_time_ms));
375 if (G1Log::finest()) {
376 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
377 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
378 }
379 if (_cur_verify_after_time_ms > 0.0) {
380 print_stats(2, "Verify After", _cur_verify_after_time_ms);
381 }
382 }
|