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 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); 111 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 112 113 if (UseStringDeduplication) { 114 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); 115 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); 116 } else { 117 _gc_par_phases[StringDedupQueueFixup] = NULL; 118 _gc_par_phases[StringDedupTableFixup] = NULL; 119 } 120 121 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):"); 122 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); 123 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 124 125 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):"); 126 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):"); 127 128 reset(); 129 } 130 131 void G1GCPhaseTimes::reset() { 132 _cur_collection_par_time_ms = 0.0; 133 _cur_optional_evac_ms = 0.0; 134 _cur_collection_code_root_fixup_time_ms = 0.0; 135 _cur_strong_code_root_purge_time_ms = 0.0; 136 _cur_evac_fail_recalc_used = 0.0; 137 _cur_evac_fail_remove_self_forwards = 0.0; 138 _cur_string_deduplication_time_ms = 0.0; 139 _cur_prepare_tlab_time_ms = 0.0; 140 _cur_resize_tlab_time_ms = 0.0; 141 _cur_derived_pointer_table_update_time_ms = 0.0; 142 _cur_clear_ct_time_ms = 0.0; 143 _cur_expand_heap_time_ms = 0.0; 144 _cur_ref_proc_time_ms = 0.0; 145 _cur_collection_start_sec = 0.0; 146 _root_region_scan_wait_time_ms = 0.0; 147 _external_accounted_time_ms = 0.0; 148 _recorded_clear_claimed_marks_time_ms = 0.0; 149 _recorded_young_cset_choice_time_ms = 0.0; 150 _recorded_non_young_cset_choice_time_ms = 0.0; 151 _recorded_redirty_logged_cards_time_ms = 0.0; 152 _recorded_preserve_cm_referents_time_ms = 0.0; 153 _recorded_merge_pss_time_ms = 0.0; 154 _recorded_start_new_cset_time_ms = 0.0; 155 _recorded_total_free_cset_time_ms = 0.0; 156 _recorded_serial_free_cset_time_ms = 0.0; 157 _cur_fast_reclaim_humongous_time_ms = 0.0; 158 _cur_fast_reclaim_humongous_register_time_ms = 0.0; 159 _cur_fast_reclaim_humongous_total = 0; 160 _cur_fast_reclaim_humongous_candidates = 0; 161 _cur_fast_reclaim_humongous_reclaimed = 0; 162 _cur_verify_before_time_ms = 0.0; 163 _cur_verify_after_time_ms = 0.0; 164 165 for (int i = 0; i < GCParPhasesSentinel; i++) { 166 if (_gc_par_phases[i] != NULL) { 167 _gc_par_phases[i]->reset(); 168 } 169 } 170 171 _ref_phase_times.reset(); 172 _weak_phase_times.reset(); 173 } 174 175 void G1GCPhaseTimes::note_gc_start() { 176 _gc_start_counter = os::elapsed_counter(); 177 reset(); 178 } 179 180 #define ASSERT_PHASE_UNINITIALIZED(phase) \ 181 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started"); 182 183 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) { 184 if (_gc_par_phases[phase] == NULL) { 185 return 0.0; 186 } 187 double value = _gc_par_phases[phase]->get(worker); 188 if (value != WorkerDataArray<double>::uninitialized()) { 189 return value; 190 } 191 return 0.0; 192 } 193 194 void G1GCPhaseTimes::note_gc_end() { 195 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 196 197 double uninitialized = WorkerDataArray<double>::uninitialized(); 198 199 for (uint i = 0; i < _max_gc_threads; i++) { 200 double worker_start = _gc_par_phases[GCWorkerStart]->get(i); 201 if (worker_start != uninitialized) { 202 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended."); 203 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 204 record_time_secs(GCWorkerTotal, i , total_worker_time); 205 206 double worker_known_time = worker_time(ExtRootScan, i) + 207 worker_time(ScanHCC, i) + 208 worker_time(UpdateRS, i) + 209 worker_time(ScanRS, i) + 210 worker_time(CodeRoots, i) + 211 worker_time(ObjCopy, i) + 212 worker_time(Termination, i); 213 214 record_time_secs(Other, i, total_worker_time - worker_known_time); 215 } else { 216 // Make sure all slots are uninitialized since this thread did not seem to have been started 217 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd); 218 ASSERT_PHASE_UNINITIALIZED(ExtRootScan); 219 ASSERT_PHASE_UNINITIALIZED(ScanHCC); 220 ASSERT_PHASE_UNINITIALIZED(UpdateRS); 221 ASSERT_PHASE_UNINITIALIZED(ScanRS); 222 ASSERT_PHASE_UNINITIALIZED(CodeRoots); 223 ASSERT_PHASE_UNINITIALIZED(ObjCopy); 224 ASSERT_PHASE_UNINITIALIZED(Termination); 225 } 226 } 227 } 228 229 #undef ASSERT_PHASE_UNINITIALIZED 230 231 // record the time a phase took in seconds 232 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 233 _gc_par_phases[phase]->set(worker_i, secs); 234 } 235 236 // add a number of seconds to a phase 237 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 238 _gc_par_phases[phase]->add(worker_i, secs); 239 } 240 241 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) { 242 if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) { 243 record_time_secs(phase, worker_i, secs); 244 } else { 245 add_time_secs(phase, worker_i, secs); 246 } 247 } 248 249 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) { 250 _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index); 251 } 252 253 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) { 254 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index); 255 } 256 257 // return the average time for a phase in milliseconds 258 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 259 return _gc_par_phases[phase]->average() * 1000.0; 260 } 261 262 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) { 263 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count"); 264 return _gc_par_phases[phase]->thread_work_items(index)->sum(); 265 } 266 267 template <class T> 268 void G1GCPhaseTimes::details(T* phase, const char* indent) const { 269 LogTarget(Trace, gc, phases, task) lt; 270 if (lt.is_enabled()) { 271 LogStream ls(lt); 272 ls.print("%s", indent); 273 phase->print_details_on(&ls); 274 } 275 } 276 277 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const { 278 out->print("%s", Indents[indent]); 279 phase->print_summary_on(out, print_sum); 280 details(phase, Indents[indent]); 281 282 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) { 283 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i); 284 if (work_items != NULL) { 285 out->print("%s", Indents[indent + 1]); 286 work_items->print_summary_on(out, true); 287 details(work_items, Indents[indent + 1]); 288 } 289 } 290 } 291 292 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const { 293 LogTarget(Debug, gc, phases) lt; 294 if (lt.is_enabled()) { 295 ResourceMark rm; 296 LogStream ls(lt); 297 log_phase(phase, 2 + extra_indent, &ls, true); 298 } 299 } 300 301 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const { 302 LogTarget(Trace, gc, phases) lt; 303 if (lt.is_enabled()) { 304 LogStream ls(lt); 305 log_phase(phase, 3, &ls, print_sum); 306 } 307 } 308 309 #define TIME_FORMAT "%.1lfms" 310 311 void G1GCPhaseTimes::info_time(const char* name, double value) const { 312 log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value); 313 } 314 315 void G1GCPhaseTimes::debug_time(const char* name, double value) const { 316 log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value); 317 } 318 319 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const { 320 LogTarget(Debug, gc, phases) lt; 321 LogTarget(Debug, gc, phases, ref) lt2; 322 323 if (lt.is_enabled()) { 324 LogStream ls(lt); 325 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 326 } else if (lt2.is_enabled()) { 327 LogStream ls(lt2); 328 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 329 } 330 } 331 332 void G1GCPhaseTimes::trace_time(const char* name, double value) const { 333 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value); 334 } 335 336 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const { 337 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value); 338 } 339 340 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const { 341 const double sum_ms = _root_region_scan_wait_time_ms + 342 _recorded_young_cset_choice_time_ms + 343 _recorded_non_young_cset_choice_time_ms + 344 _cur_fast_reclaim_humongous_register_time_ms + 345 _recorded_clear_claimed_marks_time_ms; 346 347 info_time("Pre Evacuate Collection Set", sum_ms); 348 349 if (_root_region_scan_wait_time_ms > 0.0) { 350 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms); 351 } 352 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms); 353 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms)); 354 if (G1EagerReclaimHumongousObjects) { 355 debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms); 356 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total); 357 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates); 358 } 359 360 if (_recorded_clear_claimed_marks_time_ms > 0.0) { 361 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms); 362 } 363 return sum_ms; 364 } 365 366 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const { 367 const double sum_ms = _cur_optional_evac_ms; 368 if (sum_ms > 0) { 369 info_time("Evacuate Optional Collection Set", sum_ms); 370 debug_phase(_gc_par_phases[OptScanRS]); 371 debug_phase(_gc_par_phases[OptObjCopy]); 372 } 373 return sum_ms; 374 } 375 376 double G1GCPhaseTimes::print_evacuate_collection_set() const { 377 const double sum_ms = _cur_collection_par_time_ms; 378 379 info_time("Evacuate Collection Set", sum_ms); 380 381 trace_phase(_gc_par_phases[GCWorkerStart], false); 382 debug_phase(_gc_par_phases[ExtRootScan]); 383 for (int i = ThreadRoots; i <= SATBFiltering; i++) { 384 trace_phase(_gc_par_phases[i]); 385 } 386 debug_phase(_gc_par_phases[UpdateRS]); 387 if (G1HotCardCache::default_use_cache()) { 388 trace_phase(_gc_par_phases[ScanHCC]); 389 } 390 debug_phase(_gc_par_phases[ScanRS]); 391 debug_phase(_gc_par_phases[CodeRoots]); 392 debug_phase(_gc_par_phases[ObjCopy]); 393 debug_phase(_gc_par_phases[Termination]); 394 debug_phase(_gc_par_phases[Other]); 395 debug_phase(_gc_par_phases[GCWorkerTotal]); 396 trace_phase(_gc_par_phases[GCWorkerEnd], false); 397 398 return sum_ms; 399 } 400 401 double G1GCPhaseTimes::print_post_evacuate_collection_set() const { 402 const double evac_fail_handling = _cur_evac_fail_recalc_used + 403 _cur_evac_fail_remove_self_forwards; 404 const double sum_ms = evac_fail_handling + 405 _cur_collection_code_root_fixup_time_ms + 406 _recorded_preserve_cm_referents_time_ms + 407 _cur_ref_proc_time_ms + 408 (_weak_phase_times.total_time_sec() * MILLIUNITS) + 409 _cur_clear_ct_time_ms + 410 _recorded_merge_pss_time_ms + 411 _cur_strong_code_root_purge_time_ms + 412 _recorded_redirty_logged_cards_time_ms + 413 _recorded_total_free_cset_time_ms + 414 _cur_fast_reclaim_humongous_time_ms + 415 _cur_expand_heap_time_ms + 416 _cur_string_deduplication_time_ms; 417 418 info_time("Post Evacuate Collection Set", sum_ms); 419 420 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); 421 422 debug_time("Clear Card Table", _cur_clear_ct_time_ms); 423 424 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms); 425 _ref_phase_times.print_all_references(2, false); 426 _weak_phase_times.log_print(2); 427 428 if (G1StringDedup::is_enabled()) { 429 debug_time("String Deduplication", _cur_string_deduplication_time_ms); 430 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1); 431 debug_phase(_gc_par_phases[StringDedupTableFixup], 1); 432 } 433 434 if (G1CollectedHeap::heap()->evacuation_failed()) { 435 debug_time("Evacuation Failure", evac_fail_handling); 436 trace_time("Recalculate Used", _cur_evac_fail_recalc_used); 437 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); 438 } 439 440 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms); 441 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms); 442 443 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms); 444 trace_phase(_gc_par_phases[RedirtyCards]); 445 #if COMPILER2_OR_JVMCI 446 debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms); 447 #endif 448 449 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms); 450 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms); 451 trace_phase(_gc_par_phases[YoungFreeCSet]); 452 trace_phase(_gc_par_phases[NonYoungFreeCSet]); 453 454 if (G1EagerReclaimHumongousObjects) { 455 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); 456 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); 457 } 458 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms); 459 if (UseTLAB && ResizeTLAB) { 460 debug_time("Resize TLABs", _cur_resize_tlab_time_ms); 461 } 462 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms); 463 464 465 return sum_ms; 466 } 467 468 void G1GCPhaseTimes::print_other(double accounted_ms) const { 469 info_time("Other", _gc_pause_time_ms - accounted_ms); 470 } 471 472 void G1GCPhaseTimes::print() { 473 note_gc_end(); 474 475 if (_cur_verify_before_time_ms > 0.0) { 476 debug_time("Verify Before", _cur_verify_before_time_ms); 477 } 478 479 double accounted_ms = 0.0; 480 accounted_ms += print_pre_evacuate_collection_set(); 481 accounted_ms += print_evacuate_collection_set(); 482 accounted_ms += print_evacuate_optional_collection_set(); 483 accounted_ms += print_post_evacuate_collection_set(); 484 print_other(accounted_ms); 485 486 if (_cur_verify_after_time_ms > 0.0) { 487 debug_time("Verify After", _cur_verify_after_time_ms); 488 } 489 } 490 491 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) { 492 static const char* names[] = { 493 "GCWorkerStart", 494 "ExtRootScan", 495 "ThreadRoots", 496 "UniverseRoots", 497 "JNIRoots", 498 "ObjectSynchronizerRoots", 499 "ManagementRoots", 500 "SystemDictionaryRoots", 501 "CLDGRoots", 502 "JVMTIRoots", 503 #if INCLUDE_AOT 504 "AOTCodeRoots", 505 #endif 506 "CMRefRoots", 507 "WaitForStrongCLD", 508 "WeakCLDRoots", 509 "SATBFiltering", 510 "UpdateRS", 511 "ScanHCC", 512 "ScanRS", 513 "OptScanRS", 514 "CodeRoots", 515 "ObjCopy", 516 "OptObjCopy", 517 "Termination", 518 "Other", 519 "GCWorkerTotal", 520 "GCWorkerEnd", 521 "StringDedupQueueFixup", 522 "StringDedupTableFixup", 523 "RedirtyCards", 524 "YoungFreeCSet", 525 "NonYoungFreeCSet" 526 //GCParPhasesSentinel only used to tell end of enum 527 }; 528 529 STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it 530 531 return names[phase]; 532 } 533 534 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) : 535 _pss(pss), 536 _start(Ticks::now()), 537 _total_time(total_time), 538 _trim_time(trim_time), 539 _stopped(false) { 540 541 assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use"); 542 } 543 544 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() { 545 if (!_stopped) { 546 stop(); 547 } 548 } 549 550 void G1EvacPhaseWithTrimTimeTracker::stop() { 551 assert(!_stopped, "Should only be called once"); 552 _total_time += (Ticks::now() - _start) - _pss->trim_ticks(); 553 _trim_time += _pss->trim_ticks(); 554 _pss->reset_trim_ticks(); 555 _stopped = true; 556 } 557 558 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) : 559 _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() { 560 if (_phase_times != NULL) { 561 _start_time = Ticks::now(); 562 } 563 } 564 565 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { 566 if (_phase_times != NULL) { 567 _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds()); 568 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase)); 569 } 570 } 571 572 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times, 573 G1ParScanThreadState* pss, 574 G1GCPhaseTimes::GCParPhases phase, 575 uint worker_id) : 576 G1GCParPhaseTimesTracker(phase_times, phase, worker_id), 577 _total_time(), 578 _trim_time(), 579 _trim_tracker(pss, _total_time, _trim_time) { 580 } 581 582 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() { 583 if (_phase_times != NULL) { 584 // Explicitly stop the trim tracker since it's not yet destructed. 585 _trim_tracker.stop(); 586 // Exclude trim time by increasing the start time. 587 _start_time += _trim_time; 588 _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds()); 589 } 590 } 591