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