1 /* 2 * Copyright (c) 2013, 2015, 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/concurrentG1Refine.hpp" 27 #include "gc/g1/g1CollectedHeap.inline.hpp" 28 #include "gc/g1/g1GCPhaseTimes.hpp" 29 #include "gc/g1/g1StringDedup.hpp" 30 #include "gc/g1/workerDataArray.inline.hpp" 31 #include "memory/resourceArea.hpp" 32 #include "logging/log.hpp" 33 #include "runtime/timer.hpp" 34 #include "runtime/os.hpp" 35 36 static const char* Indents[5] = {"", " ", " ", " ", " "}; 37 38 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : 39 _max_gc_threads(max_gc_threads) 40 { 41 assert(max_gc_threads > 0, "Must have some GC threads"); 42 43 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):"); 44 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):"); 45 46 // Root scanning phases 47 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):"); 48 _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):"); 49 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):"); 50 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):"); 51 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):"); 52 _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):"); 53 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):"); 54 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):"); 55 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):"); 56 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):"); 57 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):"); 58 _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):"); 59 _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):"); 60 _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):"); 61 62 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):"); 63 if (ConcurrentG1Refine::hot_card_cache_enabled()) { 64 _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):"); 65 } else { 66 _gc_par_phases[ScanHCC] = NULL; 67 } 68 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):"); 69 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):"); 70 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):"); 71 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):"); 72 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):"); 73 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):"); 74 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):"); 75 76 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:"); 77 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers); 78 79 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); 80 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 81 82 if (UseStringDeduplication) { 83 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); 84 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); 85 } else { 86 _gc_par_phases[StringDedupQueueFixup] = NULL; 87 _gc_par_phases[StringDedupTableFixup] = NULL; 88 } 89 90 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty: (ms)"); 91 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); 92 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 93 } 94 95 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { 96 assert(active_gc_threads > 0, "The number of threads must be > 0"); 97 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads"); 98 _gc_start_counter = os::elapsed_counter(); 99 _active_gc_threads = active_gc_threads; 100 _cur_expand_heap_time_ms = 0.0; 101 _external_accounted_time_ms = 0.0; 102 103 for (int i = 0; i < GCParPhasesSentinel; i++) { 104 if (_gc_par_phases[i] != NULL) { 105 _gc_par_phases[i]->reset(); 106 } 107 } 108 } 109 110 void G1GCPhaseTimes::note_gc_end() { 111 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 112 for (uint i = 0; i < _active_gc_threads; i++) { 113 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 114 record_time_secs(GCWorkerTotal, i , worker_time); 115 116 double worker_known_time = 117 _gc_par_phases[ExtRootScan]->get(i) + 118 _gc_par_phases[SATBFiltering]->get(i) + 119 _gc_par_phases[UpdateRS]->get(i) + 120 _gc_par_phases[ScanRS]->get(i) + 121 _gc_par_phases[CodeRoots]->get(i) + 122 _gc_par_phases[ObjCopy]->get(i) + 123 _gc_par_phases[Termination]->get(i); 124 125 record_time_secs(Other, i, worker_time - worker_known_time); 126 } 127 128 for (int i = 0; i < GCParPhasesSentinel; i++) { 129 if (_gc_par_phases[i] != NULL) { 130 _gc_par_phases[i]->verify(_active_gc_threads); 131 } 132 } 133 } 134 135 void G1GCPhaseTimes::info_line(const char* str, double value) { 136 log_info(gc, phases)("%s%s: %.1lfms", Indents[1], str, value); 137 } 138 139 void G1GCPhaseTimes::debug_line(const char* str, double value) { 140 log_debug(gc, phases)("%s%s: %.1lfms", Indents[2], str, value); 141 } 142 143 void G1GCPhaseTimes::trace_line(const char* str, double value) { 144 log_trace(gc, phases)("%s%s: %.1lfms", Indents[3], str, value); 145 } 146 147 void G1GCPhaseTimes::trace_line(const char* str, size_t value) { 148 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], str, value); 149 } 150 151 void G1GCPhaseTimes::trace_phase_tasks(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) { 152 LogHandle(gc, phases, task) log; 153 if (!log.is_trace()) { 154 return; 155 } 156 ResourceMark rm; 157 outputStream* out = log.trace_stream(); 158 out->print("%s%-25s", indent, ""); 159 for (uint i = 0; i < _active_gc_threads; ++i) { 160 out->print(" %4.1lf", get_time_ms(phase_id, i)); 161 } 162 out->print_cr(""); 163 } 164 165 void G1GCPhaseTimes::trace_phase_counts(const char* indent, G1GCPhaseTimes::GCParPhases phase_id) { 166 LogHandle(gc, phases, task) log; 167 if (!log.is_trace()) { 168 return; 169 } 170 ResourceMark rm; 171 outputStream* out = log.trace_stream(); 172 out->print("%s%-25s", indent, ""); 173 for (uint i = 0; i < _active_gc_threads; ++i) { 174 out->print(" " SIZE_FORMAT, get_thread_work_item(phase_id, i)); 175 } 176 out->print_cr(""); 177 } 178 179 void G1GCPhaseTimes::debug_phase(G1GCPhaseTimes::GCParPhases phase_id) { 180 WorkerDataArray<double>* phase = _gc_par_phases[phase_id]; 181 log_debug(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf", 182 Indents[2], phase->title(), 183 min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id), 184 max_time_ms(phase_id) - min_time_ms(phase_id), sum_time_ms(phase_id)); 185 trace_phase_tasks(Indents[2], phase_id); 186 if (phase->thread_work_items() != NULL) { 187 log_debug(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT, 188 Indents[3], phase->thread_work_items()->title(), 189 min_thread_work_items(phase_id), average_thread_work_items(phase_id), max_thread_work_items(phase_id), 190 max_thread_work_items(phase_id) - min_thread_work_items(phase_id), sum_thread_work_items(phase_id)); 191 trace_phase_counts(Indents[3], phase_id); 192 } 193 } 194 195 void G1GCPhaseTimes::trace_phase(G1GCPhaseTimes::GCParPhases phase_id) { 196 WorkerDataArray<double>* phase = _gc_par_phases[phase_id]; 197 log_trace(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf, Sum: %4.1lf", 198 Indents[3], phase->title(), 199 min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id), 200 max_time_ms(phase_id) - min_time_ms(phase_id), sum_time_ms(phase_id)); 201 trace_phase_tasks(Indents[3], phase_id); 202 if (phase->thread_work_items() != NULL) { 203 log_trace(gc, phases)("%s%-25s Min: " SIZE_FORMAT ", Avg: %4.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT, 204 Indents[4], phase->thread_work_items()->title(), 205 min_thread_work_items(phase_id), average_thread_work_items(phase_id), max_thread_work_items(phase_id), 206 max_thread_work_items(phase_id) - min_thread_work_items(phase_id), sum_thread_work_items(phase_id)); 207 trace_phase_counts(Indents[4], phase_id); 208 } 209 } 210 211 void G1GCPhaseTimes::trace_phase_no_sum(G1GCPhaseTimes::GCParPhases phase_id) { 212 WorkerDataArray<double>* phase = _gc_par_phases[phase_id]; 213 log_trace(gc, phases)("%s%-25s Min: %4.1lf, Avg: %4.1lf, Max: %4.1lf, Diff: %4.1lf", 214 Indents[3], phase->title(), 215 min_time_ms(phase_id), average_time_ms(phase_id), max_time_ms(phase_id), 216 max_time_ms(phase_id) - min_time_ms(phase_id)); 217 trace_phase_tasks(Indents[3], phase_id); 218 assert(phase->thread_work_items() == NULL, "work_items not implemented for no_sum."); 219 } 220 221 double G1GCPhaseTimes::accounted_time_ms() { 222 // First subtract any externally accounted time 223 double misc_time_ms = _external_accounted_time_ms; 224 225 // Subtract the root region scanning wait time. It's initialized to 226 // zero at the start of the pause. 227 misc_time_ms += _root_region_scan_wait_time_ms; 228 229 misc_time_ms += _cur_collection_par_time_ms; 230 231 // Now subtract the time taken to fix up roots in generated code 232 misc_time_ms += _cur_collection_code_root_fixup_time_ms; 233 234 // Strong code root purge time 235 misc_time_ms += _cur_strong_code_root_purge_time_ms; 236 237 if (G1StringDedup::is_enabled()) { 238 // String dedup fixup time 239 misc_time_ms += _cur_string_dedup_fixup_time_ms; 240 } 241 242 // Subtract the time taken to clean the card table from the 243 // current value of "other time" 244 misc_time_ms += _cur_clear_ct_time_ms; 245 246 // Remove expand heap time from "other time" 247 misc_time_ms += _cur_expand_heap_time_ms; 248 249 return misc_time_ms; 250 } 251 252 // record the time a phase took in seconds 253 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 254 _gc_par_phases[phase]->set(worker_i, secs); 255 } 256 257 // add a number of seconds to a phase 258 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 259 _gc_par_phases[phase]->add(worker_i, secs); 260 } 261 262 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) { 263 _gc_par_phases[phase]->set_thread_work_item(worker_i, count); 264 } 265 266 // return the average time for a phase in milliseconds 267 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 268 return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0; 269 } 270 271 double G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) { 272 return _gc_par_phases[phase]->get(worker_i) * 1000.0; 273 } 274 275 double G1GCPhaseTimes::sum_time_ms(GCParPhases phase) { 276 return _gc_par_phases[phase]->sum(_active_gc_threads) * 1000.0; 277 } 278 279 double G1GCPhaseTimes::min_time_ms(GCParPhases phase) { 280 return _gc_par_phases[phase]->minimum(_active_gc_threads) * 1000.0; 281 } 282 283 double G1GCPhaseTimes::max_time_ms(GCParPhases phase) { 284 return _gc_par_phases[phase]->maximum(_active_gc_threads) * 1000.0; 285 } 286 287 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i) { 288 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 289 return _gc_par_phases[phase]->thread_work_items()->get(worker_i); 290 } 291 292 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) { 293 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 294 return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads); 295 } 296 297 double G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) { 298 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 299 return _gc_par_phases[phase]->thread_work_items()->average(_active_gc_threads); 300 } 301 302 size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) { 303 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 304 return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads); 305 } 306 307 size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) { 308 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 309 return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads); 310 } 311 312 void G1GCPhaseTimes::print() { 313 note_gc_end(); 314 315 if (_root_region_scan_wait_time_ms > 0.0) { 316 info_line("Root Region Scan Waiting", _root_region_scan_wait_time_ms); 317 } 318 319 info_line("Evacuate Collection Set", _cur_collection_par_time_ms); 320 trace_phase_no_sum(GCWorkerStart); 321 debug_phase(ExtRootScan); 322 for (int i = ThreadRoots; i <= SATBFiltering; i++) { 323 trace_phase((GCParPhases) i); 324 } 325 debug_phase(UpdateRS); 326 if (ConcurrentG1Refine::hot_card_cache_enabled()) { 327 trace_phase(ScanHCC); 328 } 329 debug_phase(ScanRS); 330 debug_phase(CodeRoots); 331 debug_phase(ObjCopy); 332 debug_phase(Termination); 333 debug_phase(Other); 334 debug_phase(GCWorkerTotal); 335 trace_phase_no_sum(GCWorkerEnd); 336 337 info_line("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms); 338 debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); 339 debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms); 340 341 if (G1StringDedup::is_enabled()) { 342 info_line("String Dedup Fixup", _cur_string_dedup_fixup_time_ms); 343 debug_phase(StringDedupQueueFixup); 344 debug_phase(StringDedupTableFixup); 345 } 346 info_line("Clear Card Table", _cur_clear_ct_time_ms); 347 info_line("Expand Heap After Collection", _cur_expand_heap_time_ms); 348 349 double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms; 350 info_line("Free Collection Set", free_cset_time); 351 debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms); 352 debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms); 353 354 double misc_time_ms = _gc_pause_time_ms - accounted_time_ms() - free_cset_time; 355 info_line("Other", misc_time_ms); 356 if (_cur_verify_before_time_ms > 0.0) { 357 debug_line("Verify Before", _cur_verify_before_time_ms); 358 } 359 if (G1CollectedHeap::heap()->evacuation_failed()) { 360 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards + 361 _cur_evac_fail_restore_remsets; 362 debug_line("Evacuation Failure", evac_fail_handling); 363 trace_line("Recalculate Used", _cur_evac_fail_recalc_used); 364 trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); 365 trace_line("Restore RemSet", _cur_evac_fail_restore_remsets); 366 } 367 debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms)); 368 debug_line("Ref Proc", _cur_ref_proc_time_ms); 369 debug_line("Ref Enq", _cur_ref_enq_time_ms); 370 debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms); 371 trace_phase(RedirtyCards); 372 if (G1EagerReclaimHumongousObjects) { 373 debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms); 374 trace_line("Humongous Total", _cur_fast_reclaim_humongous_total); 375 trace_line("Humongous Candidate", _cur_fast_reclaim_humongous_candidates); 376 debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); 377 trace_line("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); 378 } 379 if (_cur_verify_after_time_ms > 0.0) { 380 debug_line("Verify After", _cur_verify_after_time_ms); 381 } 382 } 383 384 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) : 385 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) { 386 if (_phase_times != NULL) { 387 _start_time = os::elapsedTime(); 388 } 389 } 390 391 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { 392 if (_phase_times != NULL) { 393 _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time); 394 } 395 } 396