1 /* 2 * Copyright (c) 2013, 2018, Oracle and/or its affiliates. All rights reserved. 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 4 * 5 * This code is free software; you can redistribute it and/or modify it 6 * under the terms of the GNU General Public License version 2 only, as 7 * published by the Free Software Foundation. 8 * 9 * This code is distributed in the hope that it will be useful, but WITHOUT 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 12 * version 2 for more details (a copy is included in the LICENSE file that 13 * accompanied this code). 14 * 15 * You should have received a copy of the GNU General Public License version 16 * 2 along with this work; if not, write to the Free Software Foundation, 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 18 * 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 20 * or visit www.oracle.com if you need additional information or have any 21 * questions. 22 * 23 */ 24 25 #include "precompiled.hpp" 26 #include "gc/g1/g1CollectedHeap.inline.hpp" 27 #include "gc/g1/g1GCPhaseTimes.hpp" 28 #include "gc/g1/g1HotCardCache.hpp" 29 #include "gc/g1/g1ParScanThreadState.inline.hpp" 30 #include "gc/g1/g1StringDedup.hpp" 31 #include "gc/shared/gcTimer.hpp" 32 #include "gc/shared/workerDataArray.inline.hpp" 33 #include "memory/resourceArea.hpp" 34 #include "logging/log.hpp" 35 #include "logging/logStream.hpp" 36 #include "runtime/timer.hpp" 37 #include "runtime/os.hpp" 38 #include "utilities/macros.hpp" 39 40 static const char* Indents[5] = {"", " ", " ", " ", " "}; 41 42 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) : 43 _max_gc_threads(max_gc_threads), 44 _gc_start_counter(0), 45 _gc_pause_time_ms(0.0), 46 _ref_phase_times(gc_timer, max_gc_threads), 47 _weak_phase_times(max_gc_threads) 48 { 49 assert(max_gc_threads > 0, "Must have some GC threads"); 50 51 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):"); 52 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):"); 53 54 // Root scanning phases 55 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):"); 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; 155 _recorded_start_new_cset_time_ms = 0.0; 156 _recorded_total_free_cset_time_ms = 0.0; 157 _recorded_serial_free_cset_time_ms = 0.0; 158 _cur_fast_reclaim_humongous_time_ms = 0.0; 159 _cur_fast_reclaim_humongous_register_time_ms = 0.0; 160 _cur_fast_reclaim_humongous_total = 0; 161 _cur_fast_reclaim_humongous_candidates = 0; 162 _cur_fast_reclaim_humongous_reclaimed = 0; 163 _cur_verify_before_time_ms = 0.0; 164 _cur_verify_after_time_ms = 0.0; 165 166 for (int i = 0; i < GCParPhasesSentinel; i++) { 167 if (_gc_par_phases[i] != NULL) { 168 _gc_par_phases[i]->reset(); 169 } 170 } 171 172 _ref_phase_times.reset(); 173 _weak_phase_times.reset(); 174 } 175 176 void G1GCPhaseTimes::note_gc_start() { 177 _gc_start_counter = os::elapsed_counter(); 178 reset(); 179 } 180 181 #define ASSERT_PHASE_UNINITIALIZED(phase) \ 182 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started"); 183 184 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) { 185 if (_gc_par_phases[phase] == NULL) { 186 return 0.0; 187 } 188 double value = _gc_par_phases[phase]->get(worker); 189 if (value != WorkerDataArray<double>::uninitialized()) { 190 return value; 191 } 192 return 0.0; 193 } 194 195 void G1GCPhaseTimes::note_gc_end() { 196 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 197 198 double uninitialized = WorkerDataArray<double>::uninitialized(); 199 200 for (uint i = 0; i < _max_gc_threads; i++) { 201 double worker_start = _gc_par_phases[GCWorkerStart]->get(i); 202 if (worker_start != uninitialized) { 203 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended."); 204 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 205 record_time_secs(GCWorkerTotal, i , total_worker_time); 206 207 double worker_known_time = worker_time(ExtRootScan, i) + 208 worker_time(ScanHCC, i) + 209 worker_time(UpdateRS, i) + 210 worker_time(ScanRS, i) + 211 worker_time(CodeRoots, i) + 212 worker_time(ObjCopy, i) + 213 worker_time(Termination, i); 214 215 record_time_secs(Other, i, total_worker_time - worker_known_time); 216 } else { 217 // Make sure all slots are uninitialized since this thread did not seem to have been started 218 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd); 219 ASSERT_PHASE_UNINITIALIZED(ExtRootScan); 220 ASSERT_PHASE_UNINITIALIZED(ScanHCC); 221 ASSERT_PHASE_UNINITIALIZED(UpdateRS); 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 278 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const { 279 out->print("%s", Indents[indent]); 280 phase->print_summary_on(out, print_sum); 281 details(phase, Indents[indent]); 282 283 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) { 284 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i); 285 if (work_items != NULL) { 286 out->print("%s", Indents[indent + 1]); 287 work_items->print_summary_on(out, true); 288 details(work_items, Indents[indent + 1]); 289 } 290 } 291 } 292 293 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) const { 294 LogTarget(Debug, gc, phases) lt; 295 if (lt.is_enabled()) { 296 ResourceMark rm; 297 LogStream ls(lt); 298 log_phase(phase, 2, &ls, true); 299 } 300 } 301 302 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const { 303 LogTarget(Trace, gc, phases) lt; 304 if (lt.is_enabled()) { 305 LogStream ls(lt); 306 log_phase(phase, 3, &ls, print_sum); 307 } 308 } 309 310 #define TIME_FORMAT "%.1lfms" 311 312 void G1GCPhaseTimes::info_time(const char* name, double value) const { 313 log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value); 314 } 315 316 void G1GCPhaseTimes::debug_time(const char* name, double value) const { 317 log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value); 318 } 319 320 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const { 321 LogTarget(Debug, gc, phases) lt; 322 LogTarget(Debug, gc, phases, ref) lt2; 323 324 if (lt.is_enabled()) { 325 LogStream ls(lt); 326 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 327 } else if (lt2.is_enabled()) { 328 LogStream ls(lt2); 329 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 330 } 331 } 332 333 void G1GCPhaseTimes::trace_time(const char* name, double value) const { 334 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value); 335 } 336 337 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const { 338 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value); 339 } 340 341 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const { 342 const double sum_ms = _root_region_scan_wait_time_ms + 343 _recorded_young_cset_choice_time_ms + 344 _recorded_non_young_cset_choice_time_ms + 345 _cur_fast_reclaim_humongous_register_time_ms + 346 _recorded_clear_claimed_marks_time_ms; 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]); 397 debug_phase(_gc_par_phases[Termination]); 398 debug_phase(_gc_par_phases[Other]); 399 debug_phase(_gc_par_phases[GCWorkerTotal]); 400 trace_phase(_gc_par_phases[GCWorkerEnd], false); 401 402 return sum_ms; 403 } 404 405 double G1GCPhaseTimes::print_post_evacuate_collection_set() const { 406 const double evac_fail_handling = _cur_evac_fail_recalc_used + 407 _cur_evac_fail_remove_self_forwards; 408 const double sum_ms = evac_fail_handling + 409 _cur_collection_code_root_fixup_time_ms + 410 _recorded_preserve_cm_referents_time_ms + 411 _cur_ref_proc_time_ms + 412 (_weak_phase_times.total_time_sec() * MILLIUNITS) + 413 _cur_clear_ct_time_ms + 414 _recorded_merge_pss_time_ms + 415 _cur_strong_code_root_purge_time_ms + 416 _recorded_redirty_logged_cards_time_ms + 417 _recorded_total_free_cset_time_ms + 418 _cur_fast_reclaim_humongous_time_ms + 419 _cur_expand_heap_time_ms + 420 _cur_string_dedup_fixup_time_ms; 421 422 info_time("Post Evacuate Collection Set", sum_ms); 423 424 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); 425 426 debug_time("Clear Card Table", _cur_clear_ct_time_ms); 427 428 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms); 429 _ref_phase_times.print_all_references(2, false); 430 _weak_phase_times.log_print(2); 431 432 if (G1StringDedup::is_enabled()) { 433 debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms); 434 debug_phase(_gc_par_phases[StringDedupQueueFixup]); 435 debug_phase(_gc_par_phases[StringDedupTableFixup]); 436 } 437 438 if (G1CollectedHeap::heap()->evacuation_failed()) { 439 debug_time("Evacuation Failure", evac_fail_handling); 440 trace_time("Recalculate Used", _cur_evac_fail_recalc_used); 441 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); 442 } 443 444 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms); 445 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms); 446 447 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms); 448 trace_phase(_gc_par_phases[RedirtyCards]); 449 #if COMPILER2_OR_JVMCI 450 debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms); 451 #endif 452 453 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms); 454 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms); 455 trace_phase(_gc_par_phases[YoungFreeCSet]); 456 trace_phase(_gc_par_phases[NonYoungFreeCSet]); 457 458 if (G1EagerReclaimHumongousObjects) { 459 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); 460 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); 461 } 462 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms); 463 if (UseTLAB && ResizeTLAB) { 464 debug_time("Resize TLABs", _cur_resize_tlab_time_ms); 465 } 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()), 542 _total_time(total_time), 543 _trim_time(trim_time), 544 _stopped(false) { 545 546 assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use"); 547 } 548 549 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() { 550 if (!_stopped) { 551 stop(); 552 } 553 } 554 555 void G1EvacPhaseWithTrimTimeTracker::stop() { 556 assert(!_stopped, "Should only be called once"); 557 _total_time += (Ticks::now() - _start) - _pss->trim_ticks(); 558 _trim_time += _pss->trim_ticks(); 559 _pss->reset_trim_ticks(); 560 _stopped = true; 561 } 562 563 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) : 564 _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() { 565 if (_phase_times != NULL) { 566 _start_time = Ticks::now(); 567 } 568 } 569 570 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { 571 if (_phase_times != NULL) { 572 _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds()); 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