56 _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
57 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
58 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
59 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
60 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
61 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
62 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
63 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
64 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
65 _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
66 _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
67 _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
68
69 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
70 if (G1HotCardCache::default_use_cache()) {
71 _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
72 } else {
73 _gc_par_phases[ScanHCC] = NULL;
74 }
75 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
76 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
77 #if INCLUDE_AOT
78 _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
79 #endif
80 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
81 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
82 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
83 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
84 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
85
86 _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
87 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
88 _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
89 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
90 _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
91 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
92
93 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
94 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
95 _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
96 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
97 _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
98 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
99
100 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
101 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
102
103 if (UseStringDeduplication) {
104 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
105 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
106 } else {
107 _gc_par_phases[StringDedupQueueFixup] = NULL;
108 _gc_par_phases[StringDedupTableFixup] = NULL;
109 }
110
111 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
112 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
113 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
114
115 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
116 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
117
118 reset();
119 }
120
121 void G1GCPhaseTimes::reset() {
122 _cur_collection_par_time_ms = 0.0;
123 _cur_collection_code_root_fixup_time_ms = 0.0;
124 _cur_strong_code_root_purge_time_ms = 0.0;
125 _cur_evac_fail_recalc_used = 0.0;
126 _cur_evac_fail_remove_self_forwards = 0.0;
127 _cur_string_dedup_fixup_time_ms = 0.0;
128 _cur_prepare_tlab_time_ms = 0.0;
129 _cur_resize_tlab_time_ms = 0.0;
130 _cur_derived_pointer_table_update_time_ms = 0.0;
131 _cur_clear_ct_time_ms = 0.0;
132 _cur_expand_heap_time_ms = 0.0;
133 _cur_ref_proc_time_ms = 0.0;
134 _cur_collection_start_sec = 0.0;
135 _root_region_scan_wait_time_ms = 0.0;
136 _external_accounted_time_ms = 0.0;
137 _recorded_clear_claimed_marks_time_ms = 0.0;
138 _recorded_young_cset_choice_time_ms = 0.0;
139 _recorded_non_young_cset_choice_time_ms = 0.0;
140 _recorded_redirty_logged_cards_time_ms = 0.0;
141 _recorded_preserve_cm_referents_time_ms = 0.0;
142 _recorded_merge_pss_time_ms = 0.0;
210 ASSERT_PHASE_UNINITIALIZED(ScanRS);
211 ASSERT_PHASE_UNINITIALIZED(CodeRoots);
212 ASSERT_PHASE_UNINITIALIZED(ObjCopy);
213 ASSERT_PHASE_UNINITIALIZED(Termination);
214 }
215 }
216 }
217
218 #undef ASSERT_PHASE_UNINITIALIZED
219
220 // record the time a phase took in seconds
221 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
222 _gc_par_phases[phase]->set(worker_i, secs);
223 }
224
225 // add a number of seconds to a phase
226 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
227 _gc_par_phases[phase]->add(worker_i, secs);
228 }
229
230 void G1GCPhaseTimes::record_or_add_objcopy_time_secs(uint worker_i, double secs) {
231 if (_gc_par_phases[ObjCopy]->get(worker_i) == _gc_par_phases[ObjCopy]->uninitialized()) {
232 record_time_secs(ObjCopy, worker_i, secs);
233 } else {
234 add_time_secs(ObjCopy, worker_i, secs);
235 }
236 }
237
238 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
239 _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
240 }
241
242 // return the average time for a phase in milliseconds
243 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
244 return _gc_par_phases[phase]->average() * 1000.0;
245 }
246
247 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
248 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
249 return _gc_par_phases[phase]->thread_work_items(index)->sum();
250 }
251
252 template <class T>
253 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
254 LogTarget(Trace, gc, phases, task) lt;
255 if (lt.is_enabled()) {
256 LogStream ls(lt);
257 ls.print("%s", indent);
258 phase->print_details_on(&ls);
259 }
260 }
261
331
332 info_time("Pre Evacuate Collection Set", sum_ms);
333
334 if (_root_region_scan_wait_time_ms > 0.0) {
335 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
336 }
337 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
338 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
339 if (G1EagerReclaimHumongousObjects) {
340 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
341 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
342 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
343 }
344
345 if (_recorded_clear_claimed_marks_time_ms > 0.0) {
346 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
347 }
348 return sum_ms;
349 }
350
351 double G1GCPhaseTimes::print_evacuate_collection_set() const {
352 const double sum_ms = _cur_collection_par_time_ms;
353
354 info_time("Evacuate Collection Set", sum_ms);
355
356 trace_phase(_gc_par_phases[GCWorkerStart], false);
357 debug_phase(_gc_par_phases[ExtRootScan]);
358 for (int i = ThreadRoots; i <= SATBFiltering; i++) {
359 trace_phase(_gc_par_phases[i]);
360 }
361 debug_phase(_gc_par_phases[UpdateRS]);
362 if (G1HotCardCache::default_use_cache()) {
363 trace_phase(_gc_par_phases[ScanHCC]);
364 }
365 debug_phase(_gc_par_phases[ScanRS]);
366 debug_phase(_gc_par_phases[CodeRoots]);
367 #if INCLUDE_AOT
368 debug_phase(_gc_par_phases[AOTCodeRoots]);
369 #endif
370 debug_phase(_gc_par_phases[ObjCopy]);
440 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
441
442
443 return sum_ms;
444 }
445
446 void G1GCPhaseTimes::print_other(double accounted_ms) const {
447 info_time("Other", _gc_pause_time_ms - accounted_ms);
448 }
449
450 void G1GCPhaseTimes::print() {
451 note_gc_end();
452
453 if (_cur_verify_before_time_ms > 0.0) {
454 debug_time("Verify Before", _cur_verify_before_time_ms);
455 }
456
457 double accounted_ms = 0.0;
458 accounted_ms += print_pre_evacuate_collection_set();
459 accounted_ms += print_evacuate_collection_set();
460 accounted_ms += print_post_evacuate_collection_set();
461 print_other(accounted_ms);
462
463 if (_cur_verify_after_time_ms > 0.0) {
464 debug_time("Verify After", _cur_verify_after_time_ms);
465 }
466 }
467
468 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
469 static const char* names[] = {
470 "GCWorkerStart",
471 "ExtRootScan",
472 "ThreadRoots",
473 "StringTableRoots",
474 "UniverseRoots",
475 "JNIRoots",
476 "ObjectSynchronizerRoots",
477 "ManagementRoots",
478 "SystemDictionaryRoots",
479 "CLDGRoots",
480 "JVMTIRoots",
481 "CMRefRoots",
482 "WaitForStrongCLD",
483 "WeakCLDRoots",
484 "SATBFiltering",
485 "UpdateRS",
486 "ScanHCC",
487 "ScanRS",
488 "CodeRoots",
489 #if INCLUDE_AOT
490 "AOTCodeRoots",
491 #endif
492 "ObjCopy",
493 "Termination",
494 "Other",
495 "GCWorkerTotal",
496 "GCWorkerEnd",
497 "StringDedupQueueFixup",
498 "StringDedupTableFixup",
499 "RedirtyCards",
500 "YoungFreeCSet",
501 "NonYoungFreeCSet"
502 //GCParPhasesSentinel only used to tell end of enum
503 };
504
505 STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
506
507 return names[phase];
508 }
509
510 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
511 _pss(pss),
512 _start(Ticks::now()),
544 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
545 }
546 }
547
548 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
549 G1ParScanThreadState* pss,
550 G1GCPhaseTimes::GCParPhases phase,
551 uint worker_id) :
552 G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
553 _total_time(),
554 _trim_time(),
555 _trim_tracker(pss, _total_time, _trim_time) {
556 }
557
558 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
559 if (_phase_times != NULL) {
560 // Explicitly stop the trim tracker since it's not yet destructed.
561 _trim_tracker.stop();
562 // Exclude trim time by increasing the start time.
563 _start_time += _trim_time;
564 _phase_times->record_or_add_objcopy_time_secs(_worker_id, _trim_time.seconds());
565 }
566 }
567
|
56 _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
57 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
58 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
59 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
60 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
61 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
62 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
63 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
64 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
65 _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
66 _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
67 _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
68
69 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
70 if (G1HotCardCache::default_use_cache()) {
71 _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
72 } else {
73 _gc_par_phases[ScanHCC] = NULL;
74 }
75 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
76 _gc_par_phases[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):");
77 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
78 #if INCLUDE_AOT
79 _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
80 #endif
81 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
82 _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
83 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
84 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
85 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
86 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
87
88 _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
89 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
90 _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
91 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
92 _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
93 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
94
95 _opt_cset_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
96 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_scanned_cards, OptCSetScannedCards);
97 _opt_cset_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
98 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_claimed_cards, OptCSetClaimedCards);
99 _opt_cset_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
100 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_skipped_cards, OptCSetSkippedCards);
101 _opt_cset_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
102 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_used_memory, OptCSetUsedMemory);
103
104 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
105 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
106 _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
107 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
108 _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
109 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
110
111 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
112 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
113
114 if (UseStringDeduplication) {
115 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
116 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
117 } else {
118 _gc_par_phases[StringDedupQueueFixup] = NULL;
119 _gc_par_phases[StringDedupTableFixup] = NULL;
120 }
121
122 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
123 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
124 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
125
126 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
127 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
128
129 reset();
130 }
131
132 void G1GCPhaseTimes::reset() {
133 _cur_collection_par_time_ms = 0.0;
134 _cur_optional_evac_ms = 0.0;
135 _cur_collection_code_root_fixup_time_ms = 0.0;
136 _cur_strong_code_root_purge_time_ms = 0.0;
137 _cur_evac_fail_recalc_used = 0.0;
138 _cur_evac_fail_remove_self_forwards = 0.0;
139 _cur_string_dedup_fixup_time_ms = 0.0;
140 _cur_prepare_tlab_time_ms = 0.0;
141 _cur_resize_tlab_time_ms = 0.0;
142 _cur_derived_pointer_table_update_time_ms = 0.0;
143 _cur_clear_ct_time_ms = 0.0;
144 _cur_expand_heap_time_ms = 0.0;
145 _cur_ref_proc_time_ms = 0.0;
146 _cur_collection_start_sec = 0.0;
147 _root_region_scan_wait_time_ms = 0.0;
148 _external_accounted_time_ms = 0.0;
149 _recorded_clear_claimed_marks_time_ms = 0.0;
150 _recorded_young_cset_choice_time_ms = 0.0;
151 _recorded_non_young_cset_choice_time_ms = 0.0;
152 _recorded_redirty_logged_cards_time_ms = 0.0;
153 _recorded_preserve_cm_referents_time_ms = 0.0;
154 _recorded_merge_pss_time_ms = 0.0;
222 ASSERT_PHASE_UNINITIALIZED(ScanRS);
223 ASSERT_PHASE_UNINITIALIZED(CodeRoots);
224 ASSERT_PHASE_UNINITIALIZED(ObjCopy);
225 ASSERT_PHASE_UNINITIALIZED(Termination);
226 }
227 }
228 }
229
230 #undef ASSERT_PHASE_UNINITIALIZED
231
232 // record the time a phase took in seconds
233 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
234 _gc_par_phases[phase]->set(worker_i, secs);
235 }
236
237 // add a number of seconds to a phase
238 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
239 _gc_par_phases[phase]->add(worker_i, secs);
240 }
241
242 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
243 if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
244 record_time_secs(phase, worker_i, secs);
245 } else {
246 add_time_secs(phase, worker_i, secs);
247 }
248 }
249
250 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
251 _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
252 }
253
254 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
255 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index);
256 }
257
258 // return the average time for a phase in milliseconds
259 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
260 return _gc_par_phases[phase]->average() * 1000.0;
261 }
262
263 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
264 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
265 return _gc_par_phases[phase]->thread_work_items(index)->sum();
266 }
267
268 template <class T>
269 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
270 LogTarget(Trace, gc, phases, task) lt;
271 if (lt.is_enabled()) {
272 LogStream ls(lt);
273 ls.print("%s", indent);
274 phase->print_details_on(&ls);
275 }
276 }
277
347
348 info_time("Pre Evacuate Collection Set", sum_ms);
349
350 if (_root_region_scan_wait_time_ms > 0.0) {
351 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
352 }
353 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
354 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
355 if (G1EagerReclaimHumongousObjects) {
356 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
357 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
358 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
359 }
360
361 if (_recorded_clear_claimed_marks_time_ms > 0.0) {
362 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
363 }
364 return sum_ms;
365 }
366
367 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
368 const double sum_ms = _cur_optional_evac_ms;
369 if (sum_ms > 0) {
370 info_time("Evacuate Optional Collection Set", sum_ms);
371 debug_phase(_gc_par_phases[OptScanRS]);
372 debug_phase(_gc_par_phases[OptObjCopy]);
373 }
374 return sum_ms;
375 }
376
377 double G1GCPhaseTimes::print_evacuate_collection_set() const {
378 const double sum_ms = _cur_collection_par_time_ms;
379
380 info_time("Evacuate Collection Set", sum_ms);
381
382 trace_phase(_gc_par_phases[GCWorkerStart], false);
383 debug_phase(_gc_par_phases[ExtRootScan]);
384 for (int i = ThreadRoots; i <= SATBFiltering; i++) {
385 trace_phase(_gc_par_phases[i]);
386 }
387 debug_phase(_gc_par_phases[UpdateRS]);
388 if (G1HotCardCache::default_use_cache()) {
389 trace_phase(_gc_par_phases[ScanHCC]);
390 }
391 debug_phase(_gc_par_phases[ScanRS]);
392 debug_phase(_gc_par_phases[CodeRoots]);
393 #if INCLUDE_AOT
394 debug_phase(_gc_par_phases[AOTCodeRoots]);
395 #endif
396 debug_phase(_gc_par_phases[ObjCopy]);
466 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
467
468
469 return sum_ms;
470 }
471
472 void G1GCPhaseTimes::print_other(double accounted_ms) const {
473 info_time("Other", _gc_pause_time_ms - accounted_ms);
474 }
475
476 void G1GCPhaseTimes::print() {
477 note_gc_end();
478
479 if (_cur_verify_before_time_ms > 0.0) {
480 debug_time("Verify Before", _cur_verify_before_time_ms);
481 }
482
483 double accounted_ms = 0.0;
484 accounted_ms += print_pre_evacuate_collection_set();
485 accounted_ms += print_evacuate_collection_set();
486 accounted_ms += print_evacuate_optional_collection_set();
487 accounted_ms += print_post_evacuate_collection_set();
488 print_other(accounted_ms);
489
490 if (_cur_verify_after_time_ms > 0.0) {
491 debug_time("Verify After", _cur_verify_after_time_ms);
492 }
493 }
494
495 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
496 static const char* names[] = {
497 "GCWorkerStart",
498 "ExtRootScan",
499 "ThreadRoots",
500 "StringTableRoots",
501 "UniverseRoots",
502 "JNIRoots",
503 "ObjectSynchronizerRoots",
504 "ManagementRoots",
505 "SystemDictionaryRoots",
506 "CLDGRoots",
507 "JVMTIRoots",
508 "CMRefRoots",
509 "WaitForStrongCLD",
510 "WeakCLDRoots",
511 "SATBFiltering",
512 "UpdateRS",
513 "ScanHCC",
514 "ScanRS",
515 "OptScanRS",
516 "CodeRoots",
517 #if INCLUDE_AOT
518 "AOTCodeRoots",
519 #endif
520 "ObjCopy",
521 "OptObjCopy",
522 "Termination",
523 "Other",
524 "GCWorkerTotal",
525 "GCWorkerEnd",
526 "StringDedupQueueFixup",
527 "StringDedupTableFixup",
528 "RedirtyCards",
529 "YoungFreeCSet",
530 "NonYoungFreeCSet"
531 //GCParPhasesSentinel only used to tell end of enum
532 };
533
534 STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
535
536 return names[phase];
537 }
538
539 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
540 _pss(pss),
541 _start(Ticks::now()),
573 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
574 }
575 }
576
577 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
578 G1ParScanThreadState* pss,
579 G1GCPhaseTimes::GCParPhases phase,
580 uint worker_id) :
581 G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
582 _total_time(),
583 _trim_time(),
584 _trim_tracker(pss, _total_time, _trim_time) {
585 }
586
587 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
588 if (_phase_times != NULL) {
589 // Explicitly stop the trim tracker since it's not yet destructed.
590 _trim_tracker.stop();
591 // Exclude trim time by increasing the start time.
592 _start_time += _trim_time;
593 _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds());
594 }
595 }
596
|