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 AOT_ONLY(_gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scan (ms):");) 64 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):"); 65 _gc_par_phases[WaitForStrongRoots] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong Roots (ms):"); 66 67 _gc_par_phases[MergeER] = new WorkerDataArray<double>(max_gc_threads, "Eager Reclaim (ms):"); 68 69 _gc_par_phases[MergeRS] = new WorkerDataArray<double>(max_gc_threads, "Remembered Sets (ms):"); 70 _merge_rs_merged_sparse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Sparse:"); 71 _gc_par_phases[MergeRS]->link_thread_work_items(_merge_rs_merged_sparse, MergeRSMergedSparse); 72 _merge_rs_merged_fine = new WorkerDataArray<size_t>(max_gc_threads, "Merged Fine:"); 73 _gc_par_phases[MergeRS]->link_thread_work_items(_merge_rs_merged_fine, MergeRSMergedFine); 74 _merge_rs_merged_coarse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Coarse:"); 75 _gc_par_phases[MergeRS]->link_thread_work_items(_merge_rs_merged_coarse, MergeRSMergedCoarse); 76 77 _gc_par_phases[OptMergeRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Remembered Sets (ms):"); 78 _opt_merge_rs_merged_sparse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Sparse:"); 79 _gc_par_phases[OptMergeRS]->link_thread_work_items(_opt_merge_rs_merged_sparse, MergeRSMergedSparse); 80 _opt_merge_rs_merged_fine = new WorkerDataArray<size_t>(max_gc_threads, "Merged Fine:"); 81 _gc_par_phases[OptMergeRS]->link_thread_work_items(_opt_merge_rs_merged_fine, MergeRSMergedFine); 82 _opt_merge_rs_merged_coarse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Coarse:"); 83 _gc_par_phases[OptMergeRS]->link_thread_work_items(_opt_merge_rs_merged_coarse, MergeRSMergedCoarse); 84 85 _gc_par_phases[MergeLB] = new WorkerDataArray<double>(max_gc_threads, "Log Buffers (ms):"); 86 if (G1HotCardCache::default_use_cache()) { 87 _gc_par_phases[MergeHCC] = new WorkerDataArray<double>(max_gc_threads, "Hot Card Cache (ms):"); 88 _merge_hcc_dirty_cards = new WorkerDataArray<size_t>(max_gc_threads, "Dirty Cards:"); 89 _gc_par_phases[MergeHCC]->link_thread_work_items(_merge_hcc_dirty_cards, MergeHCCDirtyCards); 90 _merge_hcc_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:"); 91 _gc_par_phases[MergeHCC]->link_thread_work_items(_merge_hcc_skipped_cards, MergeHCCSkippedCards); 92 } else { 93 _gc_par_phases[MergeHCC] = NULL; 94 _merge_hcc_dirty_cards = NULL; 95 _merge_hcc_skipped_cards = NULL; 96 } 97 _gc_par_phases[ScanHR] = new WorkerDataArray<double>(max_gc_threads, "Scan Heap Roots (ms):"); 98 _gc_par_phases[OptScanHR] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan Heap Roots (ms):"); 99 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scan (ms):"); 100 _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Optional Code Root Scan (ms):"); 101 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):"); 102 _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):"); 103 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):"); 104 _gc_par_phases[OptTermination] = new WorkerDataArray<double>(max_gc_threads, "Optional Termination (ms):"); 105 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):"); 106 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):"); 107 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):"); 108 109 _scan_hr_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:"); 110 _gc_par_phases[ScanHR]->link_thread_work_items(_scan_hr_scanned_cards, ScanHRScannedCards); 111 _scan_hr_scanned_blocks = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Blocks:"); 112 _gc_par_phases[ScanHR]->link_thread_work_items(_scan_hr_scanned_blocks, ScanHRScannedBlocks); 113 _scan_hr_claimed_chunks = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Chunks:"); 114 _gc_par_phases[ScanHR]->link_thread_work_items(_scan_hr_claimed_chunks, ScanHRClaimedChunks); 115 116 _opt_scan_hr_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:"); 117 _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_scanned_cards, ScanHRScannedCards); 118 _opt_scan_hr_scanned_blocks = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Blocks:"); 119 _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_scanned_blocks, ScanHRScannedBlocks); 120 _opt_scan_hr_claimed_chunks = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Chunks:"); 121 _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_claimed_chunks, ScanHRClaimedChunks); 122 _opt_scan_hr_scanned_opt_refs = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Refs:"); 123 _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_scanned_opt_refs, ScanHRScannedOptRefs); 124 _opt_scan_hr_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:"); 125 _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_used_memory, ScanHRUsedMemory); 126 127 _merge_lb_dirty_cards = new WorkerDataArray<size_t>(max_gc_threads, "Dirty Cards:"); 128 _gc_par_phases[MergeLB]->link_thread_work_items(_merge_lb_dirty_cards, MergeLBDirtyCards); 129 _merge_lb_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:"); 130 _gc_par_phases[MergeLB]->link_thread_work_items(_merge_lb_skipped_cards, MergeLBSkippedCards); 131 132 _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste"); 133 _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste); 134 _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste"); 135 _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste); 136 137 _opt_obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste"); 138 _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste); 139 _opt_obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste"); 140 _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste); 141 142 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); 143 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 144 145 _opt_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Optional Termination Attempts:"); 146 _gc_par_phases[OptTermination]->link_thread_work_items(_opt_termination_attempts); 147 148 if (UseStringDeduplication) { 149 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); 150 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); 151 } else { 152 _gc_par_phases[StringDedupQueueFixup] = NULL; 153 _gc_par_phases[StringDedupTableFixup] = NULL; 154 } 155 156 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):"); 157 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); 158 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 159 160 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):"); 161 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):"); 162 163 reset(); 164 } 165 166 void G1GCPhaseTimes::reset() { 167 _cur_collection_initial_evac_time_ms = 0.0; 168 _cur_optional_evac_ms = 0.0; 169 _cur_collection_code_root_fixup_time_ms = 0.0; 170 _cur_strong_code_root_purge_time_ms = 0.0; 171 _cur_merge_heap_roots_time_ms = 0.0; 172 _cur_optional_merge_heap_roots_time_ms = 0.0; 173 _cur_prepare_merge_heap_roots_time_ms = 0.0; 174 _cur_optional_prepare_merge_heap_roots_time_ms = 0.0; 175 _cur_evac_fail_recalc_used = 0.0; 176 _cur_evac_fail_remove_self_forwards = 0.0; 177 _cur_string_deduplication_time_ms = 0.0; 178 _cur_prepare_tlab_time_ms = 0.0; 179 _cur_resize_tlab_time_ms = 0.0; 180 _cur_derived_pointer_table_update_time_ms = 0.0; 181 _cur_clear_ct_time_ms = 0.0; 182 _cur_expand_heap_time_ms = 0.0; 183 _cur_ref_proc_time_ms = 0.0; 184 _cur_collection_start_sec = 0.0; 185 _root_region_scan_wait_time_ms = 0.0; 186 _external_accounted_time_ms = 0.0; 187 _recorded_prepare_heap_roots_time_ms = 0.0; 188 _recorded_clear_claimed_marks_time_ms = 0.0; 189 _recorded_young_cset_choice_time_ms = 0.0; 190 _recorded_non_young_cset_choice_time_ms = 0.0; 191 _recorded_redirty_logged_cards_time_ms = 0.0; 192 _recorded_preserve_cm_referents_time_ms = 0.0; 193 _recorded_merge_pss_time_ms = 0.0; 194 _recorded_start_new_cset_time_ms = 0.0; 195 _recorded_total_free_cset_time_ms = 0.0; 196 _recorded_serial_free_cset_time_ms = 0.0; 197 _cur_fast_reclaim_humongous_time_ms = 0.0; 198 _cur_region_register_time = 0.0; 199 _cur_fast_reclaim_humongous_total = 0; 200 _cur_fast_reclaim_humongous_candidates = 0; 201 _cur_fast_reclaim_humongous_reclaimed = 0; 202 _cur_verify_before_time_ms = 0.0; 203 _cur_verify_after_time_ms = 0.0; 204 205 for (int i = 0; i < GCParPhasesSentinel; i++) { 206 if (_gc_par_phases[i] != NULL) { 207 _gc_par_phases[i]->reset(); 208 } 209 } 210 211 _ref_phase_times.reset(); 212 _weak_phase_times.reset(); 213 } 214 215 void G1GCPhaseTimes::note_gc_start() { 216 _gc_start_counter = os::elapsed_counter(); 217 reset(); 218 } 219 220 #define ASSERT_PHASE_UNINITIALIZED(phase) \ 221 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started"); 222 223 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) { 224 if (_gc_par_phases[phase] == NULL) { 225 return 0.0; 226 } 227 double value = _gc_par_phases[phase]->get(worker); 228 if (value != WorkerDataArray<double>::uninitialized()) { 229 return value; 230 } 231 return 0.0; 232 } 233 234 void G1GCPhaseTimes::note_gc_end() { 235 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 236 237 double uninitialized = WorkerDataArray<double>::uninitialized(); 238 239 for (uint i = 0; i < _max_gc_threads; i++) { 240 double worker_start = _gc_par_phases[GCWorkerStart]->get(i); 241 if (worker_start != uninitialized) { 242 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended."); 243 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 244 record_time_secs(GCWorkerTotal, i , total_worker_time); 245 246 double worker_known_time = worker_time(ExtRootScan, i) + 247 worker_time(ScanHR, i) + 248 worker_time(CodeRoots, i) + 249 worker_time(ObjCopy, i) + 250 worker_time(Termination, i); 251 252 record_time_secs(Other, i, total_worker_time - worker_known_time); 253 } else { 254 // Make sure all slots are uninitialized since this thread did not seem to have been started 255 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd); 256 ASSERT_PHASE_UNINITIALIZED(ExtRootScan); 257 ASSERT_PHASE_UNINITIALIZED(MergeER); 258 ASSERT_PHASE_UNINITIALIZED(MergeRS); 259 ASSERT_PHASE_UNINITIALIZED(OptMergeRS); 260 ASSERT_PHASE_UNINITIALIZED(MergeHCC); 261 ASSERT_PHASE_UNINITIALIZED(MergeLB); 262 ASSERT_PHASE_UNINITIALIZED(ScanHR); 263 ASSERT_PHASE_UNINITIALIZED(CodeRoots); 264 ASSERT_PHASE_UNINITIALIZED(OptCodeRoots); 265 ASSERT_PHASE_UNINITIALIZED(ObjCopy); 266 ASSERT_PHASE_UNINITIALIZED(OptObjCopy); 267 ASSERT_PHASE_UNINITIALIZED(Termination); 268 } 269 } 270 } 271 272 #undef ASSERT_PHASE_UNINITIALIZED 273 274 // record the time a phase took in seconds 275 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 276 _gc_par_phases[phase]->set(worker_i, secs); 277 } 278 279 // add a number of seconds to a phase 280 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 281 _gc_par_phases[phase]->add(worker_i, secs); 282 } 283 284 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) { 285 if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) { 286 record_time_secs(phase, worker_i, secs); 287 } else { 288 add_time_secs(phase, worker_i, secs); 289 } 290 } 291 292 double G1GCPhaseTimes::get_time_secs(GCParPhases phase, uint worker_i) { 293 return _gc_par_phases[phase]->get(worker_i); 294 } 295 296 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) { 297 _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index); 298 } 299 300 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) { 301 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index); 302 } 303 304 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i, uint index) { 305 return _gc_par_phases[phase]->get_thread_work_item(worker_i, index); 306 } 307 308 // return the average time for a phase in milliseconds 309 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 310 return _gc_par_phases[phase]->average() * 1000.0; 311 } 312 313 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) { 314 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count"); 315 return _gc_par_phases[phase]->thread_work_items(index)->sum(); 316 } 317 318 template <class T> 319 void G1GCPhaseTimes::details(T* phase, const char* indent) const { 320 LogTarget(Trace, gc, phases, task) lt; 321 if (lt.is_enabled()) { 322 LogStream ls(lt); 323 ls.print("%s", indent); 324 phase->print_details_on(&ls); 325 } 326 } 327 328 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const { 329 out->print("%s", Indents[indent]); 330 phase->print_summary_on(out, print_sum); 331 details(phase, Indents[indent]); 332 333 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) { 334 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i); 335 if (work_items != NULL) { 336 out->print("%s", Indents[indent + 1]); 337 work_items->print_summary_on(out, true); 338 details(work_items, Indents[indent + 1]); 339 } 340 } 341 } 342 343 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const { 344 LogTarget(Debug, gc, phases) lt; 345 if (lt.is_enabled()) { 346 ResourceMark rm; 347 LogStream ls(lt); 348 log_phase(phase, 2 + extra_indent, &ls, true); 349 } 350 } 351 352 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const { 353 LogTarget(Trace, gc, phases) lt; 354 if (lt.is_enabled()) { 355 LogStream ls(lt); 356 log_phase(phase, 3, &ls, print_sum); 357 } 358 } 359 360 #define TIME_FORMAT "%.1lfms" 361 362 void G1GCPhaseTimes::info_time(const char* name, double value) const { 363 log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value); 364 } 365 366 void G1GCPhaseTimes::debug_time(const char* name, double value) const { 367 log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value); 368 } 369 370 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const { 371 LogTarget(Debug, gc, phases) lt; 372 LogTarget(Debug, gc, phases, ref) lt2; 373 374 if (lt.is_enabled()) { 375 LogStream ls(lt); 376 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 377 } else if (lt2.is_enabled()) { 378 LogStream ls(lt2); 379 ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value); 380 } 381 } 382 383 void G1GCPhaseTimes::trace_time(const char* name, double value) const { 384 log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value); 385 } 386 387 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const { 388 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value); 389 } 390 391 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const { 392 const double sum_ms = _root_region_scan_wait_time_ms + 393 _recorded_young_cset_choice_time_ms + 394 _recorded_non_young_cset_choice_time_ms + 395 _cur_region_register_time + 396 _recorded_prepare_heap_roots_time_ms + 397 _recorded_clear_claimed_marks_time_ms; 398 399 info_time("Pre Evacuate Collection Set", sum_ms); 400 401 if (_root_region_scan_wait_time_ms > 0.0) { 402 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms); 403 } 404 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms); 405 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms)); 406 debug_time("Region Register", _cur_region_register_time); 407 if (G1EagerReclaimHumongousObjects) { 408 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total); 409 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates); 410 } 411 412 debug_time("Prepare Heap Roots", _recorded_prepare_heap_roots_time_ms); 413 if (_recorded_clear_claimed_marks_time_ms > 0.0) { 414 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms); 415 } 416 return sum_ms; 417 } 418 419 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const { 420 const double sum_ms = _cur_optional_evac_ms + _cur_optional_merge_heap_roots_time_ms; 421 if (sum_ms > 0) { 422 info_time("Merge Optional Heap Roots", _cur_optional_merge_heap_roots_time_ms); 423 424 debug_time("Prepare Optional Merge Heap Roots", _cur_optional_prepare_merge_heap_roots_time_ms); 425 debug_phase(_gc_par_phases[OptMergeRS]); 426 427 info_time("Evacuate Optional Collection Set", _cur_optional_evac_ms); 428 debug_phase(_gc_par_phases[OptScanHR]); 429 debug_phase(_gc_par_phases[OptObjCopy]); 430 debug_phase(_gc_par_phases[OptCodeRoots]); 431 debug_phase(_gc_par_phases[OptTermination]); 432 } 433 return sum_ms; 434 } 435 436 double G1GCPhaseTimes::print_evacuate_initial_collection_set() const { 437 info_time("Merge Heap Roots", _cur_merge_heap_roots_time_ms); 438 439 debug_time("Prepare Merge Heap Roots", _cur_prepare_merge_heap_roots_time_ms); 440 debug_phase(_gc_par_phases[MergeER]); 441 debug_phase(_gc_par_phases[MergeRS]); 442 if (G1HotCardCache::default_use_cache()) { 443 debug_phase(_gc_par_phases[MergeHCC]); 444 } 445 debug_phase(_gc_par_phases[MergeLB]); 446 447 info_time("Evacuate Collection Set", _cur_collection_initial_evac_time_ms); 448 449 trace_phase(_gc_par_phases[GCWorkerStart], false); 450 debug_phase(_gc_par_phases[ExtRootScan]); 451 for (int i = ExtRootScanSubPhasesFirst; i <= ExtRootScanSubPhasesLast; i++) { 452 trace_phase(_gc_par_phases[i]); 453 } 454 debug_phase(_gc_par_phases[ScanHR]); 455 debug_phase(_gc_par_phases[CodeRoots]); 456 debug_phase(_gc_par_phases[ObjCopy]); 457 debug_phase(_gc_par_phases[Termination]); 458 debug_phase(_gc_par_phases[Other]); 459 debug_phase(_gc_par_phases[GCWorkerTotal]); 460 trace_phase(_gc_par_phases[GCWorkerEnd], false); 461 462 return _cur_collection_initial_evac_time_ms + _cur_merge_heap_roots_time_ms; 463 } 464 465 double G1GCPhaseTimes::print_post_evacuate_collection_set() const { 466 const double evac_fail_handling = _cur_evac_fail_recalc_used + 467 _cur_evac_fail_remove_self_forwards; 468 const double sum_ms = evac_fail_handling + 469 _cur_collection_code_root_fixup_time_ms + 470 _recorded_preserve_cm_referents_time_ms + 471 _cur_ref_proc_time_ms + 472 (_weak_phase_times.total_time_sec() * MILLIUNITS) + 473 _cur_clear_ct_time_ms + 474 _recorded_merge_pss_time_ms + 475 _cur_strong_code_root_purge_time_ms + 476 _recorded_redirty_logged_cards_time_ms + 477 _recorded_total_free_cset_time_ms + 478 _cur_fast_reclaim_humongous_time_ms + 479 _cur_expand_heap_time_ms + 480 _cur_string_deduplication_time_ms; 481 482 info_time("Post Evacuate Collection Set", sum_ms); 483 484 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); 485 486 debug_time("Clear Card Table", _cur_clear_ct_time_ms); 487 488 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms); 489 _ref_phase_times.print_all_references(2, false); 490 _weak_phase_times.log_print(2); 491 492 if (G1StringDedup::is_enabled()) { 493 debug_time("String Deduplication", _cur_string_deduplication_time_ms); 494 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1); 495 debug_phase(_gc_par_phases[StringDedupTableFixup], 1); 496 } 497 498 if (G1CollectedHeap::heap()->evacuation_failed()) { 499 debug_time("Evacuation Failure", evac_fail_handling); 500 trace_time("Recalculate Used", _cur_evac_fail_recalc_used); 501 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); 502 } 503 504 debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms); 505 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms); 506 507 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms); 508 trace_phase(_gc_par_phases[RedirtyCards]); 509 #if COMPILER2_OR_JVMCI 510 debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms); 511 #endif 512 513 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms); 514 trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms); 515 trace_phase(_gc_par_phases[YoungFreeCSet]); 516 trace_phase(_gc_par_phases[NonYoungFreeCSet]); 517 518 if (G1EagerReclaimHumongousObjects) { 519 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); 520 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); 521 } 522 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms); 523 if (UseTLAB && ResizeTLAB) { 524 debug_time("Resize TLABs", _cur_resize_tlab_time_ms); 525 } 526 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms); 527 528 529 return sum_ms; 530 } 531 532 void G1GCPhaseTimes::print_other(double accounted_ms) const { 533 info_time("Other", _gc_pause_time_ms - accounted_ms); 534 } 535 536 void G1GCPhaseTimes::print() { 537 note_gc_end(); 538 539 if (_cur_verify_before_time_ms > 0.0) { 540 debug_time("Verify Before", _cur_verify_before_time_ms); 541 } 542 543 double accounted_ms = 0.0; 544 accounted_ms += print_pre_evacuate_collection_set(); 545 accounted_ms += print_evacuate_initial_collection_set(); 546 accounted_ms += print_evacuate_optional_collection_set(); 547 accounted_ms += print_post_evacuate_collection_set(); 548 print_other(accounted_ms); 549 550 if (_cur_verify_after_time_ms > 0.0) { 551 debug_time("Verify After", _cur_verify_after_time_ms); 552 } 553 } 554 555 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) { 556 static const char* names[] = { 557 "GCWorkerStart", 558 "ExtRootScan", 559 "ThreadRoots", 560 "UniverseRoots", 561 "JNIRoots", 562 "ObjectSynchronizerRoots", 563 "ManagementRoots", 564 "SystemDictionaryRoots", 565 "CLDGRoots", 566 "JVMTIRoots", 567 AOT_ONLY("AOTCodeRoots" COMMA) 568 "CMRefRoots", 569 "WaitForStrongRoots", 570 "MergeER", 571 "MergeRS", 572 "OptMergeRS", 573 "MergeLB", 574 "MergeHCC", 575 "ScanHR", 576 "OptScanHR", 577 "CodeRoots", 578 "OptCodeRoots", 579 "ObjCopy", 580 "OptObjCopy", 581 "Termination", 582 "OptTermination", 583 "Other", 584 "GCWorkerTotal", 585 "GCWorkerEnd", 586 "StringDedupQueueFixup", 587 "StringDedupTableFixup", 588 "RedirtyCards", 589 "YoungFreeCSet", 590 "NonYoungFreeCSet" 591 //GCParPhasesSentinel only used to tell end of enum 592 }; 593 594 STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it 595 596 return names[phase]; 597 } 598 599 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) : 600 _pss(pss), 601 _start(Ticks::now()), 602 _total_time(total_time), 603 _trim_time(trim_time), 604 _stopped(false) { 605 606 assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use"); 607 } 608 609 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() { 610 if (!_stopped) { 611 stop(); 612 } 613 } 614 615 void G1EvacPhaseWithTrimTimeTracker::stop() { 616 assert(!_stopped, "Should only be called once"); 617 _total_time += (Ticks::now() - _start) - _pss->trim_ticks(); 618 _trim_time += _pss->trim_ticks(); 619 _pss->reset_trim_ticks(); 620 _stopped = true; 621 } 622 623 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id, bool must_record) : 624 _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event(), _must_record(must_record) { 625 if (_phase_times != NULL) { 626 _start_time = Ticks::now(); 627 } 628 } 629 630 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { 631 if (_phase_times != NULL) { 632 if (_must_record) { 633 _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds()); 634 } else { 635 _phase_times->record_or_add_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds()); 636 } 637 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase)); 638 } 639 } 640 641 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times, 642 G1ParScanThreadState* pss, 643 G1GCPhaseTimes::GCParPhases phase, 644 uint worker_id) : 645 G1GCParPhaseTimesTracker(phase_times, phase, worker_id), 646 _total_time(), 647 _trim_time(), 648 _trim_tracker(pss, _total_time, _trim_time) { 649 } 650 651 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() { 652 if (_phase_times != NULL) { 653 // Explicitly stop the trim tracker since it's not yet destructed. 654 _trim_tracker.stop(); 655 // Exclude trim time by increasing the start time. 656 _start_time += _trim_time; 657 _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds()); 658 } 659 } 660