1 /* 2 * Copyright (c) 2017, Red Hat, Inc. and/or its affiliates. 3 * 4 * This code is free software; you can redistribute it and/or modify it 5 * under the terms of the GNU General Public License version 2 only, as 6 * published by the Free Software Foundation. 7 * 8 * This code is distributed in the hope that it will be useful, but WITHOUT 9 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 10 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 11 * version 2 for more details (a copy is included in the LICENSE file that 12 * accompanied this code). 13 * 14 * You should have received a copy of the GNU General Public License version 15 * 2 along with this work; if not, write to the Free Software Foundation, 16 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 17 * 18 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 19 * or visit www.oracle.com if you need additional information or have any 20 * questions. 21 * 22 */ 23 24 #include "precompiled.hpp" 25 26 #include "gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp" 27 #include "gc_implementation/shenandoah/shenandoahPhaseTimings.hpp" 28 #include "gc_implementation/shenandoah/shenandoahHeap.hpp" 29 #include "gc_implementation/shenandoah/shenandoahWorkerDataArray.hpp" 30 #include "utilities/ostream.hpp" 31 32 ShenandoahPhaseTimings::ShenandoahPhaseTimings() : _policy(NULL) { 33 _worker_times = new ShenandoahWorkerTimings((uint)MAX2(ConcGCThreads, ParallelGCThreads)); 34 _policy = ShenandoahHeap::heap()->shenandoahPolicy(); 35 assert(_policy != NULL, "Can not be NULL"); 36 init_phase_names(); 37 } 38 39 void ShenandoahPhaseTimings::record_phase_start(Phase phase) { 40 _timing_data[phase]._start = os::elapsedTime(); 41 } 42 43 void ShenandoahPhaseTimings::record_phase_end(Phase phase) { 44 assert(_policy != NULL, "Not yet initialized"); 45 double end = os::elapsedTime(); 46 double elapsed = end - _timing_data[phase]._start; 47 if (!_policy->is_at_shutdown()) { 48 _timing_data[phase]._secs.add(elapsed); 49 } 50 _policy->record_phase_time(phase, elapsed); 51 } 52 53 void ShenandoahPhaseTimings::record_phase_time(Phase phase, jint time_us) { 54 assert(_policy != NULL, "Not yet initialized"); 55 if (!_policy->is_at_shutdown()) { 56 _timing_data[phase]._secs.add((double)time_us / 1000 / 1000); 57 } 58 } 59 60 void ShenandoahPhaseTimings::record_workers_start(Phase phase) { 61 for (uint i = 0; i < GCParPhasesSentinel; i++) { 62 _worker_times->reset(i); 63 } 64 } 65 66 void ShenandoahPhaseTimings::record_workers_end(Phase phase) { 67 if (_policy->is_at_shutdown()) { 68 // Do not record the past-shutdown events 69 return; 70 } 71 72 guarantee(phase == init_evac || 73 phase == scan_roots || 74 phase == update_roots || 75 phase == partial_gc_work || 76 phase == final_update_refs_roots || 77 phase == full_gc_roots || 78 phase == _num_phases, 79 "only in these phases we can add per-thread phase times"); 80 if (phase != _num_phases) { 81 // Merge _phase_time to counters below the given phase. 82 for (uint i = 0; i < GCParPhasesSentinel; i++) { 83 double t = _worker_times->average(i); 84 _timing_data[phase + i + 1]._secs.add(t); 85 } 86 } 87 } 88 89 void ShenandoahPhaseTimings::print_on(outputStream* out) const { 90 out->cr(); 91 out->print_cr("GC STATISTICS:"); 92 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-"); 93 out->print_cr(" and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect."); 94 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code."); 95 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense."); 96 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum)."); 97 out->cr(); 98 99 for (uint i = 0; i < _num_phases; i++) { 100 if (_timing_data[i]._secs.maximum() != 0) { 101 print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs)); 102 } 103 } 104 } 105 106 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const { 107 out->print_cr("%-27s = %8.2lf s (a = %8.0lf us) (n = "INT32_FORMAT_W(5)") (lvls, us = %8.0lf, %8.0lf, %8.0lf, %8.0lf, %8.0lf)", 108 str, 109 seq->sum(), 110 seq->avg() * 1000000.0, 111 seq->num(), 112 seq->percentile(0) * 1000000.0, 113 seq->percentile(25) * 1000000.0, 114 seq->percentile(50) * 1000000.0, 115 seq->percentile(75) * 1000000.0, 116 seq->maximum() * 1000000.0 117 ); 118 } 119 120 void ShenandoahPhaseTimings::init_phase_names() { 121 _phase_names[total_pause] = "Total Pauses (N)"; 122 _phase_names[total_pause_gross] = "Total Pauses (G)"; 123 _phase_names[init_mark] = "Pause Init Mark (N)"; 124 _phase_names[init_mark_gross] = "Pause Init Mark (G)"; 125 _phase_names[final_mark] = "Pause Final Mark (N)"; 126 _phase_names[final_mark_gross] = "Pause Final Mark (G)"; 127 _phase_names[final_evac] = "Pause Final Evac (N)"; 128 _phase_names[final_evac_gross] = "Pause Final Evac (G)"; 129 _phase_names[accumulate_stats] = " Accumulate Stats"; 130 _phase_names[make_parsable] = " Make Parsable"; 131 _phase_names[clear_liveness] = " Clear Liveness"; 132 _phase_names[resize_tlabs] = " Resize TLABs"; 133 _phase_names[finish_queues] = " Finish Queues"; 134 _phase_names[weakrefs] = " Weak References"; 135 _phase_names[weakrefs_process] = " Process"; 136 _phase_names[weakrefs_enqueue] = " Enqueue"; 137 _phase_names[purge] = " System Purge"; 138 _phase_names[purge_class_unload] = " Unload Classes"; 139 _phase_names[purge_par] = " Parallel Cleanup"; 140 _phase_names[purge_par_codecache] = " Code Cache"; 141 _phase_names[purge_par_symbstring] = " String/Symbol Tables"; 142 _phase_names[purge_par_rmt] = " Resolved Methods"; 143 _phase_names[purge_par_classes] = " Clean Classes"; 144 _phase_names[purge_par_sync] = " Synchronization"; 145 _phase_names[purge_cldg] = " CLDG"; 146 _phase_names[clean_str_dedup_table] = " String Dedup Table"; 147 _phase_names[prepare_evac] = " Prepare Evacuation"; 148 149 _phase_names[scan_roots] = " Scan Roots"; 150 _phase_names[scan_thread_roots] = " S: Thread Roots"; 151 _phase_names[scan_code_roots] = " S: Code Cache Roots"; 152 _phase_names[scan_string_table_roots] = " S: String Table Roots"; 153 _phase_names[scan_universe_roots] = " S: Universe Roots"; 154 _phase_names[scan_jni_roots] = " S: JNI Roots"; 155 _phase_names[scan_jni_weak_roots] = " S: JNI Weak Roots"; 156 _phase_names[scan_synchronizer_roots] = " S: Synchronizer Roots"; 157 _phase_names[scan_flat_profiler_roots] = " S: Flat Profiler Roots"; 158 _phase_names[scan_management_roots] = " S: Management Roots"; 159 _phase_names[scan_system_dictionary_roots] = " S: System Dict Roots"; 160 _phase_names[scan_cldg_roots] = " S: CLDG Roots"; 161 _phase_names[scan_jvmti_roots] = " S: JVMTI Roots"; 162 _phase_names[scan_finish_queues] = " S: Finish Queues"; 163 164 _phase_names[update_roots] = " Update Roots"; 165 _phase_names[update_thread_roots] = " U: Thread Roots"; 166 _phase_names[update_code_roots] = " U: Code Cache Roots"; 167 _phase_names[update_string_table_roots] = " U: String Table Roots"; 168 _phase_names[update_universe_roots] = " U: Universe Roots"; 169 _phase_names[update_jni_roots] = " U: JNI Roots"; 170 _phase_names[update_jni_weak_roots] = " U: JNI Weak Roots"; 171 _phase_names[update_synchronizer_roots] = " U: Synchronizer Roots"; 172 _phase_names[update_flat_profiler_roots] = " U: Flat Profiler Roots"; 173 _phase_names[update_management_roots] = " U: Management Roots"; 174 _phase_names[update_system_dictionary_roots] = " U: System Dict Roots"; 175 _phase_names[update_cldg_roots] = " U: CLDG Roots"; 176 _phase_names[update_jvmti_roots] = " U: JVMTI Roots"; 177 _phase_names[update_finish_queues] = " U: Finish Queues"; 178 179 _phase_names[init_evac] = " Initial Evacuation"; 180 _phase_names[evac_thread_roots] = " E: Thread Roots"; 181 _phase_names[evac_code_roots] = " E: Code Cache Roots"; 182 _phase_names[evac_string_table_roots] = " E: String Table Roots"; 183 _phase_names[evac_universe_roots] = " E: Universe Roots"; 184 _phase_names[evac_jni_roots] = " E: JNI Roots"; 185 _phase_names[evac_jni_weak_roots] = " E: JNI Weak Roots"; 186 _phase_names[evac_synchronizer_roots] = " E: Synchronizer Roots"; 187 _phase_names[evac_flat_profiler_roots] = " E: Flat Profiler Roots"; 188 _phase_names[evac_management_roots] = " E: Management Roots"; 189 _phase_names[evac_system_dictionary_roots] = " E: System Dict Roots"; 190 _phase_names[evac_cldg_roots] = " E: CLDG Roots"; 191 _phase_names[evac_jvmti_roots] = " E: JVMTI Roots"; 192 _phase_names[evac_finish_queues] = " E: Finish Queues"; 193 194 _phase_names[recycle_regions] = " Recycle regions"; 195 196 _phase_names[degen_gc_gross] = "Pause Degenerated GC (G)"; 197 _phase_names[degen_gc] = "Pause Degenerated GC (N)"; 198 199 _phase_names[full_gc_gross] = "Pause Full GC (G)"; 200 _phase_names[full_gc] = "Pause Full GC (N)"; 201 _phase_names[full_gc_heapdumps] = " Heap Dumps"; 202 _phase_names[full_gc_prepare] = " Prepare"; 203 _phase_names[full_gc_roots] = " Roots"; 204 _phase_names[full_gc_thread_roots] = " F: Thread Roots"; 205 _phase_names[full_gc_code_roots] = " F: Code Cache Roots"; 206 _phase_names[full_gc_string_table_roots] = " F: String Table Roots"; 207 _phase_names[full_gc_universe_roots] = " F: Universe Roots"; 208 _phase_names[full_gc_jni_roots] = " F: JNI Roots"; 209 _phase_names[full_gc_jni_weak_roots] = " F: JNI Weak Roots"; 210 _phase_names[full_gc_synchronizer_roots] = " F: Synchronizer Roots"; 211 _phase_names[full_gc_flat_profiler_roots] = " F: Flat Profiler Roots"; 212 _phase_names[full_gc_management_roots] = " F: Management Roots"; 213 _phase_names[full_gc_system_dictionary_roots] = " F: System Dict Roots"; 214 _phase_names[full_gc_cldg_roots] = " F: CLDG Roots"; 215 _phase_names[full_gc_jvmti_roots] = " F: JVMTI Roots"; 216 _phase_names[full_gc_finish_queues] = " F: Finish Queues"; 217 _phase_names[full_gc_mark] = " Mark"; 218 _phase_names[full_gc_mark_finish_queues] = " Finish Queues"; 219 _phase_names[full_gc_weakrefs] = " Weak References"; 220 _phase_names[full_gc_weakrefs_process] = " Process"; 221 _phase_names[full_gc_weakrefs_enqueue] = " Enqueue"; 222 _phase_names[full_gc_purge] = " System Purge"; 223 _phase_names[full_gc_purge_class_unload] = " Unload Classes"; 224 _phase_names[full_gc_purge_par] = " Parallel Cleanup"; 225 _phase_names[full_gc_purge_par_codecache] = " Code Cache"; 226 _phase_names[full_gc_purge_par_symbstring] = " String/Symbol Tables"; 227 _phase_names[full_gc_purge_par_rmt] = " Resolved Methods"; 228 _phase_names[full_gc_purge_par_classes] = " Clean Classes"; 229 _phase_names[full_gc_purge_par_sync] = " Synchronization"; 230 _phase_names[full_gc_purge_cldg] = " CLDG"; 231 _phase_names[full_gc_calculate_addresses] = " Calculate Addresses"; 232 _phase_names[full_gc_calculate_addresses_regular] = " Regular Objects"; 233 _phase_names[full_gc_calculate_addresses_humong] = " Humongous Objects"; 234 _phase_names[full_gc_adjust_pointers] = " Adjust Pointers"; 235 _phase_names[full_gc_copy_objects] = " Copy Objects"; 236 _phase_names[full_gc_copy_objects_regular] = " Regular Objects"; 237 _phase_names[full_gc_copy_objects_humong] = " Humongous Objects"; 238 _phase_names[full_gc_update_str_dedup_table] = " Update String Dedup Table"; 239 _phase_names[full_gc_resize_tlabs] = " Resize TLABs"; 240 241 _phase_names[partial_gc_gross] = "Pause Partial GC (G)"; 242 _phase_names[partial_gc] = "Pause Partial GC (N)"; 243 _phase_names[partial_gc_prepare] = " Prepare"; 244 _phase_names[partial_gc_work] = " Work"; 245 _phase_names[partial_gc_thread_roots] = " P: Thread Roots"; 246 _phase_names[partial_gc_code_roots] = " P: Code Cache Roots"; 247 _phase_names[partial_gc_string_table_roots] = " P: String Table Roots"; 248 _phase_names[partial_gc_universe_roots] = " P: Universe Roots"; 249 _phase_names[partial_gc_jni_roots] = " P: JNI Roots"; 250 _phase_names[partial_gc_jni_weak_roots] = " P: JNI Weak Roots"; 251 _phase_names[partial_gc_synchronizer_roots] = " P: Synchronizer Roots"; 252 _phase_names[partial_gc_flat_profiler_roots] = " P: Flat Profiler Roots"; 253 _phase_names[partial_gc_management_roots] = " P: Management Roots"; 254 _phase_names[partial_gc_system_dict_roots] = " P: System Dict Roots"; 255 _phase_names[partial_gc_cldg_roots] = " P: CLDG Roots"; 256 _phase_names[partial_gc_jvmti_roots] = " P: JVMTI Roots"; 257 _phase_names[partial_gc_update_str_dedup_table] 258 = " Update String Dedup Table"; 259 _phase_names[partial_gc_recycle] = " Recycle"; 260 261 _phase_names[pause_other] = "Pause Other"; 262 263 _phase_names[conc_mark] = "Concurrent Marking"; 264 _phase_names[conc_preclean] = "Concurrent Precleaning"; 265 _phase_names[conc_evac] = "Concurrent Evacuation"; 266 _phase_names[conc_cleanup] = "Concurrent Cleanup"; 267 _phase_names[conc_cleanup_recycle] = " Recycle"; 268 _phase_names[conc_cleanup_reset_bitmaps] = " Reset Bitmaps"; 269 _phase_names[conc_other] = "Concurrent Other"; 270 271 _phase_names[init_update_refs_gross] = "Pause Init Update Refs (G)"; 272 _phase_names[init_update_refs] = "Pause Init Update Refs (N)"; 273 _phase_names[conc_update_refs] = "Concurrent Update Refs"; 274 _phase_names[final_update_refs_gross] = "Pause Final Update Refs (G)"; 275 _phase_names[final_update_refs] = "Pause Final Update Refs (N)"; 276 277 _phase_names[final_update_refs_finish_work] = " Finish Work"; 278 _phase_names[final_update_refs_roots] = " Update Roots"; 279 _phase_names[final_update_refs_thread_roots] = " UR: Thread Roots"; 280 _phase_names[final_update_refs_code_roots] = " UR: Code Cache Roots"; 281 _phase_names[final_update_refs_string_table_roots] = " UR: String Table Roots"; 282 _phase_names[final_update_refs_universe_roots] = " UR: Universe Roots"; 283 _phase_names[final_update_refs_jni_roots] = " UR: JNI Roots"; 284 _phase_names[final_update_refs_jni_weak_roots] = " UR: JNI Weak Roots"; 285 _phase_names[final_update_refs_synchronizer_roots] = " UR: Synchronizer Roots"; 286 _phase_names[final_update_refs_flat_profiler_roots] = " UR: Flat Profiler Roots"; 287 _phase_names[final_update_refs_management_roots] = " UR: Management Roots"; 288 _phase_names[final_update_refs_system_dict_roots] = " UR: System Dict Roots"; 289 _phase_names[final_update_refs_cldg_roots] = " UR: CLDG Roots"; 290 _phase_names[final_update_refs_jvmti_roots] = " UR: JVMTI Roots"; 291 _phase_names[final_update_refs_finish_queues] = " UR: Finish Queues"; 292 _phase_names[final_update_refs_recycle] = " Recycle"; 293 } 294 295 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) : 296 _max_gc_threads(max_gc_threads) 297 { 298 assert(max_gc_threads > 0, "Must have some GC threads"); 299 300 // Root scanning phases 301 _gc_par_phases[ShenandoahPhaseTimings::ThreadRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):"); 302 _gc_par_phases[ShenandoahPhaseTimings::CodeCacheRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms):"); 303 _gc_par_phases[ShenandoahPhaseTimings::StringTableRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):"); 304 _gc_par_phases[ShenandoahPhaseTimings::UniverseRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):"); 305 _gc_par_phases[ShenandoahPhaseTimings::JNIRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):"); 306 _gc_par_phases[ShenandoahPhaseTimings::JNIWeakRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JNI Weak Roots (ms):"); 307 _gc_par_phases[ShenandoahPhaseTimings::ObjectSynchronizerRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):"); 308 _gc_par_phases[ShenandoahPhaseTimings::FlatProfilerRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):"); 309 _gc_par_phases[ShenandoahPhaseTimings::ManagementRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Management Roots (ms):"); 310 _gc_par_phases[ShenandoahPhaseTimings::SystemDictionaryRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):"); 311 _gc_par_phases[ShenandoahPhaseTimings::CLDGRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):"); 312 _gc_par_phases[ShenandoahPhaseTimings::JVMTIRoots] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):"); 313 _gc_par_phases[ShenandoahPhaseTimings::FinishQueues] = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Finish Queues (ms):"); 314 } 315 316 // record the time a phase took in seconds 317 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) { 318 _gc_par_phases[phase]->set(worker_i, secs); 319 } 320 321 double ShenandoahWorkerTimings::average(uint i) { 322 return _gc_par_phases[i]->average(); 323 } 324 void ShenandoahWorkerTimings::reset(uint i) { 325 _gc_par_phases[i]->reset(); 326 } 327 328 void ShenandoahWorkerTimings::print() { 329 for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) { 330 _gc_par_phases[i]->print_summary_on(tty); 331 } 332 } 333 334 ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahWorkerTimings* worker_times, 335 ShenandoahPhaseTimings::GCParPhases phase, uint worker_id) : 336 _worker_times(worker_times), _phase(phase), _worker_id(worker_id) { 337 if (_worker_times != NULL) { 338 _start_time = os::elapsedTime(); 339 } 340 } 341 342 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() { 343 if (_worker_times != NULL) { 344 _worker_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time); 345 } 346 }