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