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