1 /* 2 * Copyright (c) 2013, 2019, 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[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):"); 57 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):"); 58 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):"); 59 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):"); 60 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):"); 61 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):"); 62 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):"); 63 #if INCLUDE_AOT 64 _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scan (ms):"); 65 #endif 66 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):"); 67 _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):"); 68 _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):"); 69 _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):"); 70 71 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):"); 72 if (G1HotCardCache::default_use_cache()) { 73 _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):"); 74 } else { 75 _gc_par_phases[ScanHCC] = NULL; 76 } 77 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):"); 78 _gc_par_phases[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):"); 79 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):"); 80 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):"); 81 _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):"); 82 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):"); 83 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):"); 84 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):"); 85 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):"); 86 87 _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:"); 88 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards); 89 _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:"); 90 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards); 91 _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:"); 92 _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards); 93 94 _opt_cset_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:"); 95 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_scanned_cards, OptCSetScannedCards); 96 _opt_cset_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:"); 97 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_claimed_cards, OptCSetClaimedCards); 98 _opt_cset_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:"); 99 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_skipped_cards, OptCSetSkippedCards); 100 _opt_cset_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:"); 101 _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_used_memory, OptCSetUsedMemory); 102 103 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:"); 104 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers); 105 _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:"); 106 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards); 107 _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:"); 108 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards); 109 110 _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste"); 111 _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste); 112 _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste"); 113 _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste); 114 115 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); 116 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 117 118 if (UseStringDeduplication) { 119 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); 120 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); 121 } else { 122 _gc_par_phases[StringDedupQueueFixup] = NULL; 123 _gc_par_phases[StringDedupTableFixup] = NULL; 124 } 125 126 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):"); 127 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); 128 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 129 130 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):"); 131 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):"); 132 133 reset(); 134 } 135 136 void G1GCPhaseTimes::reset() { 137 _cur_collection_par_time_ms = 0.0; 138 _cur_optional_evac_ms = 0.0; 139 _cur_collection_code_root_fixup_time_ms = 0.0; 140 _cur_strong_code_root_purge_time_ms = 0.0; 141 _cur_evac_fail_recalc_used = 0.0; 142 _cur_evac_fail_remove_self_forwards = 0.0; 143 _cur_string_deduplication_time_ms = 0.0; 144 _cur_prepare_tlab_time_ms = 0.0; 145 _cur_resize_tlab_time_ms = 0.0; 146 _cur_derived_pointer_table_update_time_ms = 0.0; 147 _cur_clear_ct_time_ms = 0.0; 148 _cur_expand_heap_time_ms = 0.0; 149 _cur_ref_proc_time_ms = 0.0; 150 _cur_collection_start_sec = 0.0; 151 _root_region_scan_wait_time_ms = 0.0; 152 _external_accounted_time_ms = 0.0; 153 _recorded_clear_claimed_marks_time_ms = 0.0; 154 _recorded_young_cset_choice_time_ms = 0.0; 155 _recorded_non_young_cset_choice_time_ms = 0.0; 156 _recorded_redirty_logged_cards_time_ms = 0.0; 157 _recorded_preserve_cm_referents_time_ms = 0.0; 158 _recorded_merge_pss_time_ms = 0.0; 159 _recorded_start_new_cset_time_ms = 0.0; 160 _recorded_total_free_cset_time_ms = 0.0; 161 _recorded_serial_free_cset_time_ms = 0.0; 162 _cur_fast_reclaim_humongous_time_ms = 0.0; 163 _cur_fast_reclaim_humongous_register_time_ms = 0.0; 164 _cur_fast_reclaim_humongous_total = 0; 165 _cur_fast_reclaim_humongous_candidates = 0; 166 _cur_fast_reclaim_humongous_reclaimed = 0; 167 _cur_verify_before_time_ms = 0.0; 168 _cur_verify_after_time_ms = 0.0; 169 170 for (int i = 0; i < GCParPhasesSentinel; i++) { 171 if (_gc_par_phases[i] != NULL) { 172 _gc_par_phases[i]->reset(); 173 } 174 } 175 176 _ref_phase_times.reset(); 177 _weak_phase_times.reset(); 178 } 179 180 void G1GCPhaseTimes::note_gc_start() { 181 _gc_start_counter = os::elapsed_counter(); 182 reset(); 183 } 184 185 #define ASSERT_PHASE_UNINITIALIZED(phase) \ 186 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started"); 187 188 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) { 189 if (_gc_par_phases[phase] == NULL) { 190 return 0.0; 191 } 192 double value = _gc_par_phases[phase]->get(worker); 193 if (value != WorkerDataArray<double>::uninitialized()) { 194 return value; 195 } 196 return 0.0; 197 } 198 199 void G1GCPhaseTimes::note_gc_end() { 200 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 201 202 double uninitialized = WorkerDataArray<double>::uninitialized(); 203 204 for (uint i = 0; i < _max_gc_threads; i++) { 205 double worker_start = _gc_par_phases[GCWorkerStart]->get(i); 206 if (worker_start != uninitialized) { 207 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended."); 208 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 209 record_time_secs(GCWorkerTotal, i , total_worker_time); 210 211 double worker_known_time = worker_time(ExtRootScan, i) + 212 worker_time(ScanHCC, i) + 213 worker_time(UpdateRS, i) + 214 worker_time(ScanRS, i) + 215 worker_time(CodeRoots, i) + 216 worker_time(ObjCopy, i) + 217 worker_time(Termination, i); 218 219 record_time_secs(Other, i, total_worker_time - worker_known_time); 220 } else { 221 // Make sure all slots are uninitialized since this thread did not seem to have been started 222 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd); 223 ASSERT_PHASE_UNINITIALIZED(ExtRootScan); 224 ASSERT_PHASE_UNINITIALIZED(ScanHCC); 225 ASSERT_PHASE_UNINITIALIZED(UpdateRS); 226 ASSERT_PHASE_UNINITIALIZED(ScanRS); 227 ASSERT_PHASE_UNINITIALIZED(CodeRoots); 228 ASSERT_PHASE_UNINITIALIZED(ObjCopy); 229 ASSERT_PHASE_UNINITIALIZED(Termination); 230 } 231 } 232 } 233 234 #undef ASSERT_PHASE_UNINITIALIZED 235 236 // record the time a phase took in seconds 237 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 238 _gc_par_phases[phase]->set(worker_i, secs); 239 } 240 241 // add a number of seconds to a phase 242 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 243 _gc_par_phases[phase]->add(worker_i, secs); 244 } 245 246 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) { 247 if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) { 248 record_time_secs(phase, worker_i, secs); 249 } else { 250 add_time_secs(phase, worker_i, secs); 251 } 252 } 253 254 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) { 255 _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index); 256 } 257 258 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) { 259 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index); 260 } 261 262 // return the average time for a phase in milliseconds 263 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 264 return _gc_par_phases[phase]->average() * 1000.0; 265 } 266 267 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) { 268 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count"); 269 return _gc_par_phases[phase]->thread_work_items(index)->sum(); 270 } 271 272 template <class T> 273 void G1GCPhaseTimes::details(T* phase, const char* indent) const { 274 LogTarget(Trace, gc, phases, task) lt; 275 if (lt.is_enabled()) { 276 LogStream ls(lt); 277 ls.print("%s", indent); 278 phase->print_details_on(&ls); 279 } 280 } 281 282 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const { 283 out->print("%s", Indents[indent]); 284 phase->print_summary_on(out, print_sum); 285 details(phase, Indents[indent]); 286 287 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) { 288 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i); 289 if (work_items != NULL) { 290 out->print("%s", Indents[indent + 1]); 291 work_items->print_summary_on(out, true); 292 details(work_items, Indents[indent + 1]); 293 } 294 } 295 } 296 297 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const { 298 LogTarget(Debug, gc, phases) lt; 299 if (lt.is_enabled()) { 300 ResourceMark rm; 301 LogStream ls(lt); 302 log_phase(phase, 2 + extra_indent, &ls, true); 303 } 304 } 305 306 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const { 307 LogTarget(Trace, gc, phases) lt; 308 if (lt.is_enabled()) { 309 LogStream ls(lt); 310 log_phase(phase, 3, &ls, print_sum); 311 } 312 } 313 314 #define TIME_FORMAT "%.1lfms" 315 316 void G1GCPhaseTimes::info_time(const char* name, double value) const { 317 log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value); 318 } 319 320 void G1GCPhaseTimes::debug_time(const char* name, double value) const { 321 log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value); 322 } 323 324 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const { 325 LogTarget(Debug, gc, phases) lt; 326 LogTarget(Debug, gc, phases, ref) lt2; 327 328 if (lt.is_enabled()) { 329 LogStream ls(lt); 330 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 331 } else if (lt2.is_enabled()) { 332 LogStream ls(lt2); 333 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 334 } 335 } 336 337 void G1GCPhaseTimes::trace_time(const char* name, double value) const { 338 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value); 339 } 340 341 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const { 342 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value); 343 } 344 345 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const { 346 const double sum_ms = _root_region_scan_wait_time_ms + 347 _recorded_young_cset_choice_time_ms + 348 _recorded_non_young_cset_choice_time_ms + 349 _cur_fast_reclaim_humongous_register_time_ms + 350 _recorded_clear_claimed_marks_time_ms; 351 352 info_time("Pre Evacuate Collection Set", sum_ms); 353 354 if (_root_region_scan_wait_time_ms > 0.0) { 355 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms); 356 } 357 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms); 358 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms)); 359 if (G1EagerReclaimHumongousObjects) { 360 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms); 361 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total); 362 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates); 363 } 364 365 if (_recorded_clear_claimed_marks_time_ms > 0.0) { 366 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms); 367 } 368 return sum_ms; 369 } 370 371 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const { 372 const double sum_ms = _cur_optional_evac_ms; 373 if (sum_ms > 0) { 374 info_time("Evacuate Optional Collection Set", sum_ms); 375 debug_phase(_gc_par_phases[OptScanRS]); 376 debug_phase(_gc_par_phases[OptObjCopy]); 377 } 378 return sum_ms; 379 } 380 381 double G1GCPhaseTimes::print_evacuate_collection_set() const { 382 const double sum_ms = _cur_collection_par_time_ms; 383 384 info_time("Evacuate Collection Set", sum_ms); 385 386 trace_phase(_gc_par_phases[GCWorkerStart], false); 387 debug_phase(_gc_par_phases[ExtRootScan]); 388 for (int i = ExtRootScanSubPhasesStart; i <= ExtRootScanSubPhasesEnd; i++) { 389 trace_phase(_gc_par_phases[i]); 390 } 391 if (G1HotCardCache::default_use_cache()) { 392 debug_phase(_gc_par_phases[ScanHCC]); 393 } 394 debug_phase(_gc_par_phases[UpdateRS]); 395 debug_phase(_gc_par_phases[ScanRS]); 396 debug_phase(_gc_par_phases[CodeRoots]); 397 debug_phase(_gc_par_phases[ObjCopy]); 398 debug_phase(_gc_par_phases[Termination]); 399 debug_phase(_gc_par_phases[Other]); 400 debug_phase(_gc_par_phases[GCWorkerTotal]); 401 trace_phase(_gc_par_phases[GCWorkerEnd], false); 402 403 return sum_ms; 404 } 405 406 double G1GCPhaseTimes::print_post_evacuate_collection_set() const { 407 const double evac_fail_handling = _cur_evac_fail_recalc_used + 408 _cur_evac_fail_remove_self_forwards; 409 const double sum_ms = evac_fail_handling + 410 _cur_collection_code_root_fixup_time_ms + 411 _recorded_preserve_cm_referents_time_ms + 412 _cur_ref_proc_time_ms + 413 (_weak_phase_times.total_time_sec() * MILLIUNITS) + 414 _cur_clear_ct_time_ms + 415 _recorded_merge_pss_time_ms + 416 _cur_strong_code_root_purge_time_ms + 417 _recorded_redirty_logged_cards_time_ms + 418 _recorded_total_free_cset_time_ms + 419 _cur_fast_reclaim_humongous_time_ms + 420 _cur_expand_heap_time_ms + 421 _cur_string_deduplication_time_ms; 422 423 info_time("Post Evacuate Collection Set", sum_ms); 424 425 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); 426 427 debug_time("Clear Card Table", _cur_clear_ct_time_ms); 428 429 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms); 430 _ref_phase_times.print_all_references(2, false); 431 _weak_phase_times.log_print(2); 432 433 if (G1StringDedup::is_enabled()) { 434 debug_time("String Deduplication", _cur_string_deduplication_time_ms); 435 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1); 436 debug_phase(_gc_par_phases[StringDedupTableFixup], 1); 437 } 438 439 if (G1CollectedHeap::heap()->evacuation_failed()) { 440 debug_time("Evacuation Failure", evac_fail_handling); 441 trace_time("Recalculate Used", _cur_evac_fail_recalc_used); 442 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); 443 } 444 445 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms); 446 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms); 447 448 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms); 449 trace_phase(_gc_par_phases[RedirtyCards]); 450 #if COMPILER2_OR_JVMCI 451 debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms); 452 #endif 453 454 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms); 455 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms); 456 trace_phase(_gc_par_phases[YoungFreeCSet]); 457 trace_phase(_gc_par_phases[NonYoungFreeCSet]); 458 459 if (G1EagerReclaimHumongousObjects) { 460 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); 461 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); 462 } 463 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms); 464 if (UseTLAB && ResizeTLAB) { 465 debug_time("Resize TLABs", _cur_resize_tlab_time_ms); 466 } 467 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms); 468 469 470 return sum_ms; 471 } 472 473 void G1GCPhaseTimes::print_other(double accounted_ms) const { 474 info_time("Other", _gc_pause_time_ms - accounted_ms); 475 } 476 477 void G1GCPhaseTimes::print() { 478 note_gc_end(); 479 480 if (_cur_verify_before_time_ms > 0.0) { 481 debug_time("Verify Before", _cur_verify_before_time_ms); 482 } 483 484 double accounted_ms = 0.0; 485 accounted_ms += print_pre_evacuate_collection_set(); 486 accounted_ms += print_evacuate_collection_set(); 487 accounted_ms += print_evacuate_optional_collection_set(); 488 accounted_ms += print_post_evacuate_collection_set(); 489 print_other(accounted_ms); 490 491 if (_cur_verify_after_time_ms > 0.0) { 492 debug_time("Verify After", _cur_verify_after_time_ms); 493 } 494 } 495 496 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) { 497 static const char* names[] = { 498 "GCWorkerStart", 499 "ExtRootScan", 500 "ThreadRoots", 501 "UniverseRoots", 502 "JNIRoots", 503 "ObjectSynchronizerRoots", 504 "ManagementRoots", 505 "SystemDictionaryRoots", 506 "CLDGRoots", 507 "JVMTIRoots", 508 #if INCLUDE_AOT 509 "AOTCodeRoots", 510 #endif 511 "CMRefRoots", 512 "WaitForStrongCLD", 513 "WeakCLDRoots", 514 "SATBFiltering", 515 "UpdateRS", 516 "ScanHCC", 517 "ScanRS", 518 "OptScanRS", 519 "CodeRoots", 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