g1GCPhaseTimes.cpp revision 9056:dc9930a04ab0
11541Srgrimes/* 21541Srgrimes * Copyright (c) 2013, 2015, Oracle and/or its affiliates. All rights reserved. 31541Srgrimes * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 41541Srgrimes * 51541Srgrimes * This code is free software; you can redistribute it and/or modify it 61541Srgrimes * under the terms of the GNU General Public License version 2 only, as 71541Srgrimes * published by the Free Software Foundation. 81541Srgrimes * 91541Srgrimes * This code is distributed in the hope that it will be useful, but WITHOUT 101541Srgrimes * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 111541Srgrimes * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 121541Srgrimes * version 2 for more details (a copy is included in the LICENSE file that 131541Srgrimes * accompanied this code). 141541Srgrimes * 151541Srgrimes * You should have received a copy of the GNU General Public License version 161541Srgrimes * 2 along with this work; if not, write to the Free Software Foundation, 171541Srgrimes * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 181541Srgrimes * 191541Srgrimes * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 201541Srgrimes * or visit www.oracle.com if you need additional information or have any 211541Srgrimes * questions. 221541Srgrimes * 231541Srgrimes */ 241541Srgrimes 251541Srgrimes#include "precompiled.hpp" 261541Srgrimes#include "gc/g1/g1CollectedHeap.inline.hpp" 271541Srgrimes#include "gc/g1/g1GCPhaseTimes.hpp" 281541Srgrimes#include "gc/g1/g1Log.hpp" 291541Srgrimes#include "gc/g1/g1StringDedup.hpp" 301541Srgrimes#include "memory/allocation.hpp" 311541Srgrimes#include "runtime/os.hpp" 321541Srgrimes 331541Srgrimes// Helper class for avoiding interleaved logging 3450477Speterclass LineBuffer: public StackObj { 351541Srgrimes 361541Srgrimesprivate: 3713203Swollman static const int BUFFER_LEN = 1024; 381541Srgrimes static const int INDENT_CHARS = 3; 391541Srgrimes char _buffer[BUFFER_LEN]; 402112Swollman int _indent_level; 4112221Sbde int _cur; 4241059Speter 431541Srgrimes void vappend(const char* format, va_list ap) ATTRIBUTE_PRINTF(2, 0) { 4424131Sbde int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap); 4531561Sbde if (res != -1) { 461541Srgrimes _cur += res; 471541Srgrimes } else { 481541Srgrimes DEBUG_ONLY(warning("buffer too small in LineBuffer");) 491541Srgrimes _buffer[BUFFER_LEN -1] = 0; 501541Srgrimes _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again 5170707Salfred } 521541Srgrimes } 5330354Sphk 5430309Sphkpublic: 5513203Swollman explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) { 5612819Sphk for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) { 5762378Sgreen _buffer[_cur] = ' '; 5812819Sphk } 5912819Sphk } 6012819Sphk 6112577Sbde#ifndef PRODUCT 6212819Sphk ~LineBuffer() { 6312819Sphk assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?"); 641541Srgrimes } 651541Srgrimes#endif 661541Srgrimes 671541Srgrimes void append(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) { 681541Srgrimes va_list ap; 691541Srgrimes va_start(ap, format); 708876Srgrimes vappend(format, ap); 7117429Sphk va_end(ap); 721541Srgrimes } 731541Srgrimes 741541Srgrimes void print_cr() { 7551484Smarcel gclog_or_tty->print_cr("%s", _buffer); 761541Srgrimes _cur = _indent_level * INDENT_CHARS; 771541Srgrimes } 781541Srgrimes 791549Srgrimes void append_and_print_cr(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) { 801541Srgrimes va_list ap; 811541Srgrimes va_start(ap, format); 8247955Sdt vappend(format, ap); 8347955Sdt va_end(ap); 841541Srgrimes print_cr(); 851541Srgrimes } 861541Srgrimes}; 8747955Sdt 8847955Sdttemplate <class T> 891541Srgrimesclass WorkerDataArray : public CHeapObj<mtGC> { 9047955Sdt friend class G1GCParPhasePrinter; 9147955Sdt T* _data; 921541Srgrimes uint _length; 931541Srgrimes const char* _title; 941541Srgrimes bool _print_sum; 9517429Sphk int _log_level; 961541Srgrimes uint _indent_level; 971541Srgrimes bool _enabled; 9847955Sdt 991541Srgrimes WorkerDataArray<size_t>* _thread_work_items; 1001541Srgrimes 10165556Sjasone NOT_PRODUCT(T uninitialized();) 1021541Srgrimes 10362378Sgreen // We are caching the sum and average to only have to calculate them once. 10417429Sphk // This is not done in an MT-safe way. It is intended to allow single 10517429Sphk // threaded code to call sum() and average() multiple times in any order 1061541Srgrimes // without having to worry about the cost. 1071541Srgrimes bool _has_new_data; 1081541Srgrimes T _sum; 1091549Srgrimes T _min; 1101541Srgrimes T _max; 1111541Srgrimes double _average; 11247955Sdt 11347955Sdt public: 1141541Srgrimes WorkerDataArray(uint length, const char* title, bool print_sum, int log_level, uint indent_level) : 1151541Srgrimes _title(title), _length(0), _print_sum(print_sum), _log_level(log_level), _indent_level(indent_level), 1161541Srgrimes _has_new_data(true), _thread_work_items(NULL), _enabled(true) { 1171541Srgrimes assert(length > 0, "Must have some workers to store data for"); 1181541Srgrimes _length = length; 1191541Srgrimes _data = NEW_C_HEAP_ARRAY(T, _length, mtGC); 1201541Srgrimes } 1211541Srgrimes 1221541Srgrimes ~WorkerDataArray() { 1231541Srgrimes FREE_C_HEAP_ARRAY(T, _data); 1241541Srgrimes } 12565556Sjasone 1261541Srgrimes void link_thread_work_items(WorkerDataArray<size_t>* thread_work_items) { 1271541Srgrimes _thread_work_items = thread_work_items; 12862378Sgreen } 12917429Sphk 1301541Srgrimes WorkerDataArray<size_t>* thread_work_items() { return _thread_work_items; } 1311541Srgrimes 1321541Srgrimes void set(uint worker_i, T value) { 1331549Srgrimes assert(worker_i < _length, "Worker %d is greater than max: %d", worker_i, _length); 1341541Srgrimes assert(_data[worker_i] == WorkerDataArray<T>::uninitialized(), "Overwriting data for worker %d in %s", worker_i, _title); 1351541Srgrimes _data[worker_i] = value; 1361541Srgrimes _has_new_data = true; 1371541Srgrimes } 1381541Srgrimes 1391541Srgrimes void set_thread_work_item(uint worker_i, size_t value) { 1401541Srgrimes assert(_thread_work_items != NULL, "No sub count"); 1411541Srgrimes _thread_work_items->set(worker_i, value); 1421541Srgrimes } 1431541Srgrimes 14465556Sjasone T get(uint worker_i) { 1451541Srgrimes assert(worker_i < _length, "Worker %d is greater than max: %d", worker_i, _length); 14662378Sgreen assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), "No data added for worker %d", worker_i); 14717429Sphk return _data[worker_i]; 1481541Srgrimes } 1491541Srgrimes 1501541Srgrimes void add(uint worker_i, T value) { 1511549Srgrimes assert(worker_i < _length, "Worker %d is greater than max: %d", worker_i, _length); 15262378Sgreen assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), "No data to add to for worker %d", worker_i); 1531541Srgrimes _data[worker_i] += value; 1541541Srgrimes _has_new_data = true; 1551541Srgrimes } 15662378Sgreen 15762378Sgreen double average(uint active_threads){ 1581541Srgrimes calculate_totals(active_threads); 1591541Srgrimes return _average; 16062378Sgreen } 1611541Srgrimes 1628876Srgrimes T sum(uint active_threads) { 1631541Srgrimes calculate_totals(active_threads); 1641541Srgrimes return _sum; 1651541Srgrimes } 1661541Srgrimes 16762378Sgreen T minimum(uint active_threads) { 16862378Sgreen calculate_totals(active_threads); 16965556Sjasone return _min; 17062378Sgreen } 17162378Sgreen 17262791Sgreen T maximum(uint active_threads) { 1731541Srgrimes calculate_totals(active_threads); 17462378Sgreen return _max; 17517429Sphk } 1761541Srgrimes 1771541Srgrimes void reset() PRODUCT_RETURN; 1781541Srgrimes void verify(uint active_threads) PRODUCT_RETURN; 1791549Srgrimes 1801541Srgrimes void set_enabled(bool enabled) { _enabled = enabled; } 1811541Srgrimes 18251941Smarcel int log_level() { return _log_level; } 1831541Srgrimes 18451791Smarcel private: 18551941Smarcel 1861541Srgrimes void calculate_totals(uint active_threads){ 1871541Srgrimes if (!_has_new_data) { 1881541Srgrimes return; 1891541Srgrimes } 1901541Srgrimes 1911541Srgrimes _sum = (T)0; 1921541Srgrimes _min = _data[0]; 1931541Srgrimes _max = _min; 1941541Srgrimes assert(active_threads <= _length, "Wrong number of active threads"); 19551791Smarcel for (uint i = 0; i < active_threads; ++i) { 1961541Srgrimes T val = _data[i]; 19765556Sjasone _sum += val; 1981541Srgrimes _min = MIN2(_min, val); 1991541Srgrimes _max = MAX2(_max, val); 20062378Sgreen } 20117429Sphk _average = (double)_sum / (double)active_threads; 2021541Srgrimes _has_new_data = false; 2031541Srgrimes } 2041541Srgrimes}; 2051549Srgrimes 2061541Srgrimes 2071541Srgrimes#ifndef PRODUCT 2081541Srgrimes 2091541Srgrimestemplate <> 2101541Srgrimessize_t WorkerDataArray<size_t>::uninitialized() { 2111541Srgrimes return (size_t)-1; 2121541Srgrimes} 2131541Srgrimes 2141541Srgrimestemplate <> 2151541Srgrimesdouble WorkerDataArray<double>::uninitialized() { 2161541Srgrimes return -1.0; 2171541Srgrimes} 21865556Sjasone 2191541Srgrimestemplate <class T> 2201541Srgrimesvoid WorkerDataArray<T>::reset() { 22162378Sgreen for (uint i = 0; i < _length; i++) { 22217429Sphk _data[i] = WorkerDataArray<T>::uninitialized(); 2231541Srgrimes } 2241541Srgrimes if (_thread_work_items != NULL) { 22513203Swollman _thread_work_items->reset(); 2261541Srgrimes } 2271541Srgrimes} 2281541Srgrimes 2291541Srgrimestemplate <class T> 2301541Srgrimesvoid WorkerDataArray<T>::verify(uint active_threads) { 2311541Srgrimes if (!_enabled) { 23212221Sbde return; 2331541Srgrimes } 2341541Srgrimes 2351541Srgrimes assert(active_threads <= _length, "Wrong number of active threads"); 2361541Srgrimes for (uint i = 0; i < active_threads; i++) { 2371541Srgrimes assert(_data[i] != WorkerDataArray<T>::uninitialized(), 2381541Srgrimes "Invalid data for worker %u in '%s'", i, _title); 23912221Sbde } 2401541Srgrimes if (_thread_work_items != NULL) { 2411549Srgrimes _thread_work_items->verify(active_threads); 24230994Sphk } 2431541Srgrimes} 2441541Srgrimes 2451541Srgrimes#endif 24613203Swollman 2471541SrgrimesG1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : 2481541Srgrimes _max_gc_threads(max_gc_threads) 2491541Srgrimes{ 2501541Srgrimes assert(max_gc_threads > 0, "Must have some GC threads"); 2511541Srgrimes 2521541Srgrimes _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2); 2531541Srgrimes _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2); 25462550Smckusick 2551541Srgrimes // Root scanning phases 2561541Srgrimes _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3); 2571541Srgrimes _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3); 2581541Srgrimes _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3); 2591541Srgrimes _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3); 2601541Srgrimes _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3); 2611541Srgrimes _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3); 26250668Sdima _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3); 26362550Smckusick _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3); 26462550Smckusick _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3); 2653308Sphk _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3); 2661541Srgrimes _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3); 2671541Srgrimes _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3); 2681541Srgrimes _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3); 26954655Seivind _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3); 2701541Srgrimes 27122521Sdyson _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2); 2721541Srgrimes _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2); 2731541Srgrimes _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2); 2741541Srgrimes _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms)", true, G1Log::LevelFiner, 2); 2751541Srgrimes _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms)", true, G1Log::LevelFiner, 2); 2761541Srgrimes _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms)", true, G1Log::LevelFiner, 2); 2771541Srgrimes _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms)", false, G1Log::LevelFiner, 2); 2781541Srgrimes _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms)", true, G1Log::LevelFiner, 2); 2791541Srgrimes 2801541Srgrimes _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers", true, G1Log::LevelFiner, 3); 2811541Srgrimes _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers); 28269947Sjake 28353212Sphk _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts", true, G1Log::LevelFinest, 3); 2841541Srgrimes _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 2851541Srgrimes 2861541Srgrimes _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2); 2871541Srgrimes _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2); 2881541Srgrimes 2891541Srgrimes _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3); 2901541Srgrimes _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3); 2911541Srgrimes _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 2921541Srgrimes} 2931541Srgrimes 29469947Sjakevoid G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress) { 2951541Srgrimes assert(active_gc_threads > 0, "The number of threads must be > 0"); 2961541Srgrimes assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads"); 2971541Srgrimes _active_gc_threads = active_gc_threads; 2981541Srgrimes 2991541Srgrimes for (int i = 0; i < GCParPhasesSentinel; i++) { 3001541Srgrimes _gc_par_phases[i]->reset(); 3011541Srgrimes } 3021541Srgrimes 3031541Srgrimes _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled()); 3048876Srgrimes _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled()); 3051541Srgrimes} 3061541Srgrimes 3071541Srgrimesvoid G1GCPhaseTimes::note_gc_end() { 3081541Srgrimes for (uint i = 0; i < _active_gc_threads; i++) { 3091541Srgrimes double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 3101541Srgrimes record_time_secs(GCWorkerTotal, i , worker_time); 3111541Srgrimes 3121541Srgrimes double worker_known_time = 3131541Srgrimes _gc_par_phases[ExtRootScan]->get(i) + 3141541Srgrimes _gc_par_phases[SATBFiltering]->get(i) + 3151541Srgrimes _gc_par_phases[UpdateRS]->get(i) + 31653212Sphk _gc_par_phases[ScanRS]->get(i) + 3171541Srgrimes _gc_par_phases[CodeRoots]->get(i) + 3181541Srgrimes _gc_par_phases[ObjCopy]->get(i) + 3198876Srgrimes _gc_par_phases[Termination]->get(i); 3201541Srgrimes 3211541Srgrimes record_time_secs(Other, i, worker_time - worker_known_time); 3221541Srgrimes } 3231541Srgrimes 3241541Srgrimes for (int i = 0; i < GCParPhasesSentinel; i++) { 3251541Srgrimes _gc_par_phases[i]->verify(_active_gc_threads); 3261541Srgrimes } 3271541Srgrimes} 3281541Srgrimes 3291541Srgrimesvoid G1GCPhaseTimes::print_stats(int level, const char* str, double value) { 3301541Srgrimes LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value); 3311541Srgrimes} 3321541Srgrimes 3331541Srgrimesvoid G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) { 3341541Srgrimes LineBuffer(level).append_and_print_cr("[%s: " SIZE_FORMAT "]", str, value); 3351541Srgrimes} 3361541Srgrimes 3371541Srgrimesvoid G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) { 3381541Srgrimes LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers); 3391541Srgrimes} 3401541Srgrimes 3411541Srgrimesdouble G1GCPhaseTimes::accounted_time_ms() { 34213203Swollman // Subtract the root region scanning wait time. It's initialized to 34313203Swollman // zero at the start of the pause. 34413203Swollman double misc_time_ms = _root_region_scan_wait_time_ms; 3451541Srgrimes 3461541Srgrimes misc_time_ms += _cur_collection_par_time_ms; 34718398Sphk 34818398Sphk // Now subtract the time taken to fix up roots in generated code 34918398Sphk misc_time_ms += _cur_collection_code_root_fixup_time_ms; 35018398Sphk 35118398Sphk // Strong code root purge time 35230994Sphk misc_time_ms += _cur_strong_code_root_purge_time_ms; 35318398Sphk 35418398Sphk if (G1StringDedup::is_enabled()) { 35518398Sphk // String dedup fixup time 35613203Swollman misc_time_ms += _cur_string_dedup_fixup_time_ms; 35718398Sphk } 35818398Sphk 35918398Sphk // Subtract the time taken to clean the card table from the 36018398Sphk // current value of "other time" 36118398Sphk misc_time_ms += _cur_clear_ct_time_ms; 36218398Sphk 36370707Salfred return misc_time_ms; 36470707Salfred} 36518398Sphk 36618398Sphk// record the time a phase took in seconds 36718469Sphkvoid G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 36818398Sphk _gc_par_phases[phase]->set(worker_i, secs); 36965556Sjasone} 37018469Sphk 37162378Sgreen// add a number of seconds to a phase 37218398Sphkvoid G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 37318398Sphk _gc_par_phases[phase]->add(worker_i, secs); 37418469Sphk} 37518398Sphk 37618398Sphkvoid G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) { 37718398Sphk _gc_par_phases[phase]->set_thread_work_item(worker_i, count); 37818398Sphk} 37918398Sphk 38018398Sphk// return the average time for a phase in milliseconds 38118398Sphkdouble G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 38218398Sphk return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0; 38318398Sphk} 38412819Sphk 3851541Srgrimesdouble G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) { 3861541Srgrimes return _gc_par_phases[phase]->get(worker_i) * 1000.0; 3871541Srgrimes} 3881541Srgrimes 3891541Srgrimesdouble G1GCPhaseTimes::sum_time_ms(GCParPhases phase) { 3901541Srgrimes return _gc_par_phases[phase]->sum(_active_gc_threads) * 1000.0; 3911541Srgrimes} 3921541Srgrimes 3931541Srgrimesdouble G1GCPhaseTimes::min_time_ms(GCParPhases phase) { 3948876Srgrimes return _gc_par_phases[phase]->minimum(_active_gc_threads) * 1000.0; 3951541Srgrimes} 3961541Srgrimes 3971541Srgrimesdouble G1GCPhaseTimes::max_time_ms(GCParPhases phase) { 3981541Srgrimes return _gc_par_phases[phase]->maximum(_active_gc_threads) * 1000.0; 3991541Srgrimes} 4001541Srgrimes 4011541Srgrimessize_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i) { 4021541Srgrimes assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 4031541Srgrimes return _gc_par_phases[phase]->thread_work_items()->get(worker_i); 4041541Srgrimes} 4051541Srgrimes 4068876Srgrimessize_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) { 4071541Srgrimes assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 4081541Srgrimes return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads); 4091541Srgrimes} 4101541Srgrimes 4111541Srgrimesdouble G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) { 4121541Srgrimes assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 4131541Srgrimes return _gc_par_phases[phase]->thread_work_items()->average(_active_gc_threads); 4141541Srgrimes} 4151541Srgrimes 4161541Srgrimessize_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) { 4171541Srgrimes assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 4181541Srgrimes return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads); 4191541Srgrimes} 4201541Srgrimes 42112819Sphksize_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) { 4221541Srgrimes assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 4231541Srgrimes return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads); 4241541Srgrimes} 4251541Srgrimes 4261541Srgrimesclass G1GCParPhasePrinter : public StackObj { 4271541Srgrimes G1GCPhaseTimes* _phase_times; 4281541Srgrimes public: 4291541Srgrimes G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {} 4301541Srgrimes 43170317Sjake void print(G1GCPhaseTimes::GCParPhases phase_id) { 4321541Srgrimes WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id]; 4331541Srgrimes 4341541Srgrimes if (phase->_log_level > G1Log::level() || !phase->_enabled) { 4351541Srgrimes return; 4361541Srgrimes } 4371541Srgrimes 4381541Srgrimes if (phase->_length == 1) { 43953212Sphk print_single_length(phase_id, phase); 44053212Sphk } else { 4411541Srgrimes print_multi_length(phase_id, phase); 44270317Sjake } 44370317Sjake } 4441541Srgrimes 44570317Sjake private: 44653212Sphk 44753212Sphk void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) { 4481541Srgrimes // No need for min, max, average and sum for only one worker 4491541Srgrimes LineBuffer buf(phase->_indent_level); 45014529Shsu buf.append_and_print_cr("[%s: %.1lf]", phase->_title, _phase_times->get_time_ms(phase_id, 0)); 4511541Srgrimes 4521541Srgrimes if (phase->_thread_work_items != NULL) { 4531541Srgrimes LineBuffer buf2(phase->_thread_work_items->_indent_level); 4541541Srgrimes buf2.append_and_print_cr("[%s: " SIZE_FORMAT "]", phase->_thread_work_items->_title, _phase_times->sum_thread_work_items(phase_id)); 4551541Srgrimes } 45612819Sphk } 45762378Sgreen 4581541Srgrimes void print_time_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) { 4591541Srgrimes uint active_length = _phase_times->_active_gc_threads; 46062378Sgreen for (uint i = 0; i < active_length; ++i) { 4611541Srgrimes buf.append(" %.1lf", _phase_times->get_time_ms(phase_id, i)); 4621541Srgrimes } 4631541Srgrimes buf.print_cr(); 46462976Smckusick } 46562976Smckusick 4661541Srgrimes void print_count_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) { 4671541Srgrimes uint active_length = _phase_times->_active_gc_threads; 4681541Srgrimes for (uint i = 0; i < active_length; ++i) { 4691541Srgrimes buf.append(" " SIZE_FORMAT, _phase_times->get_thread_work_item(phase_id, i)); 4701541Srgrimes } 4711541Srgrimes buf.print_cr(); 4721541Srgrimes } 4731541Srgrimes 4741541Srgrimes void print_thread_work_items(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) { 4751541Srgrimes LineBuffer buf(thread_work_items->_indent_level); 4761541Srgrimes buf.append("[%s:", thread_work_items->_title); 4771541Srgrimes 47841628Srvb if (G1Log::finest()) { 4791541Srgrimes print_count_values(buf, phase_id, thread_work_items); 4801541Srgrimes } 48165556Sjasone 4821541Srgrimes assert(thread_work_items->_print_sum, "%s does not have print sum true even though it is a count", thread_work_items->_title); 4831541Srgrimes 48462378Sgreen buf.append_and_print_cr(" Min: " SIZE_FORMAT ", Avg: %.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT "]", 48562378Sgreen _phase_times->min_thread_work_items(phase_id), _phase_times->average_thread_work_items(phase_id), _phase_times->max_thread_work_items(phase_id), 4861541Srgrimes _phase_times->max_thread_work_items(phase_id) - _phase_times->min_thread_work_items(phase_id), _phase_times->sum_thread_work_items(phase_id)); 48762976Smckusick } 48822521Sdyson 48962378Sgreen void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) { 49062378Sgreen LineBuffer buf(phase->_indent_level); 49162378Sgreen buf.append("[%s:", phase->_title); 49262378Sgreen 49362378Sgreen if (G1Log::finest()) { 49462378Sgreen print_time_values(buf, phase_id, phase); 49522521Sdyson } 49662976Smckusick 4971541Srgrimes buf.append(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf", 4981541Srgrimes _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id), 4991541Srgrimes _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id)); 5001541Srgrimes 5011541Srgrimes if (phase->_print_sum) { 5021541Srgrimes // for things like the start and end times the sum is not 5031541Srgrimes // that relevant 50469947Sjake buf.append(", Sum: %.1lf", _phase_times->sum_time_ms(phase_id)); 50553212Sphk } 5061541Srgrimes 5071541Srgrimes buf.append_and_print_cr("]"); 5081541Srgrimes 5091541Srgrimes if (phase->_thread_work_items != NULL) { 5101541Srgrimes print_thread_work_items(phase_id, phase->_thread_work_items); 5111541Srgrimes } 51269947Sjake } 5131541Srgrimes}; 5141541Srgrimes 5151541Srgrimesvoid G1GCPhaseTimes::print(double pause_time_sec) { 5161541Srgrimes G1GCParPhasePrinter par_phase_printer(this); 5171541Srgrimes 5181541Srgrimes if (_root_region_scan_wait_time_ms > 0.0) { 5198876Srgrimes print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); 5201541Srgrimes } 5211541Srgrimes 52265237Srwatson print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads); 52365237Srwatson for (int i = 0; i <= GCMainParPhasesLast; i++) { 5241541Srgrimes par_phase_printer.print((GCParPhases) i); 5251541Srgrimes } 52612819Sphk 5271541Srgrimes print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); 5281541Srgrimes print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms); 5291541Srgrimes if (G1StringDedup::is_enabled()) { 5301541Srgrimes print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads); 5311541Srgrimes for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) { 5321541Srgrimes par_phase_printer.print((GCParPhases) i); 53346155Sphk } 53446155Sphk } 5351541Srgrimes print_stats(1, "Clear CT", _cur_clear_ct_time_ms); 5361541Srgrimes double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms(); 5371541Srgrimes print_stats(1, "Other", misc_time_ms); 5381541Srgrimes if (_cur_verify_before_time_ms > 0.0) { 5391541Srgrimes print_stats(2, "Verify Before", _cur_verify_before_time_ms); 5401541Srgrimes } 5411541Srgrimes if (G1CollectedHeap::heap()->evacuation_failed()) { 5421541Srgrimes double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards + 5431541Srgrimes _cur_evac_fail_restore_remsets; 5441541Srgrimes print_stats(2, "Evacuation Failure", evac_fail_handling); 5451541Srgrimes if (G1Log::finest()) { 54613203Swollman print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used); 547 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards); 548 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets); 549 } 550 } 551 print_stats(2, "Choose CSet", 552 (_recorded_young_cset_choice_time_ms + 553 _recorded_non_young_cset_choice_time_ms)); 554 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms); 555 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms); 556 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms); 557 par_phase_printer.print(RedirtyCards); 558 if (G1EagerReclaimHumongousObjects) { 559 print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms); 560 if (G1Log::finest()) { 561 print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total); 562 print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates); 563 } 564 print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); 565 if (G1Log::finest()) { 566 print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); 567 } 568 } 569 print_stats(2, "Free CSet", 570 (_recorded_young_free_cset_time_ms + 571 _recorded_non_young_free_cset_time_ms)); 572 if (G1Log::finest()) { 573 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms); 574 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms); 575 } 576 if (_cur_verify_after_time_ms > 0.0) { 577 print_stats(2, "Verify After", _cur_verify_after_time_ms); 578 } 579} 580 581G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) : 582 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) { 583 if (_phase_times != NULL) { 584 _start_time = os::elapsedTime(); 585 } 586} 587 588G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { 589 if (_phase_times != NULL) { 590 _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time); 591 } 592} 593 594