1.1 --- a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Thu Oct 23 11:43:29 2014 +0200
1.2 +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Thu Mar 26 13:19:32 2015 +0100
1.3 @@ -22,12 +22,13 @@
1.4 *
1.5 */
1.6
1.7 -
1.8 #include "precompiled.hpp"
1.9 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
1.10 #include "gc_implementation/g1/g1GCPhaseTimes.hpp"
1.11 #include "gc_implementation/g1/g1Log.hpp"
1.12 #include "gc_implementation/g1/g1StringDedup.hpp"
1.13 +#include "memory/allocation.hpp"
1.14 +#include "runtime/os.hpp"
1.15
1.16 // Helper class for avoiding interleaved logging
1.17 class LineBuffer: public StackObj {
1.18 @@ -70,184 +71,243 @@
1.19 va_end(ap);
1.20 }
1.21
1.22 + void print_cr() {
1.23 + gclog_or_tty->print_cr("%s", _buffer);
1.24 + _cur = _indent_level * INDENT_CHARS;
1.25 + }
1.26 +
1.27 void append_and_print_cr(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
1.28 va_list ap;
1.29 va_start(ap, format);
1.30 vappend(format, ap);
1.31 va_end(ap);
1.32 - gclog_or_tty->print_cr("%s", _buffer);
1.33 - _cur = _indent_level * INDENT_CHARS;
1.34 + print_cr();
1.35 }
1.36 };
1.37
1.38 -PRAGMA_DIAG_PUSH
1.39 -PRAGMA_FORMAT_NONLITERAL_IGNORED
1.40 template <class T>
1.41 -void WorkerDataArray<T>::print(int level, const char* title) {
1.42 - if (_length == 1) {
1.43 - // No need for min, max, average and sum for only one worker
1.44 - LineBuffer buf(level);
1.45 - buf.append("[%s: ", title);
1.46 - buf.append(_print_format, _data[0]);
1.47 - buf.append_and_print_cr("]");
1.48 - return;
1.49 +class WorkerDataArray : public CHeapObj<mtGC> {
1.50 + friend class G1GCParPhasePrinter;
1.51 + T* _data;
1.52 + uint _length;
1.53 + const char* _title;
1.54 + bool _print_sum;
1.55 + int _log_level;
1.56 + uint _indent_level;
1.57 + bool _enabled;
1.58 +
1.59 + WorkerDataArray<size_t>* _thread_work_items;
1.60 +
1.61 + NOT_PRODUCT(T uninitialized();)
1.62 +
1.63 + // We are caching the sum and average to only have to calculate them once.
1.64 + // This is not done in an MT-safe way. It is intended to allow single
1.65 + // threaded code to call sum() and average() multiple times in any order
1.66 + // without having to worry about the cost.
1.67 + bool _has_new_data;
1.68 + T _sum;
1.69 + T _min;
1.70 + T _max;
1.71 + double _average;
1.72 +
1.73 + public:
1.74 + WorkerDataArray(uint length, const char* title, bool print_sum, int log_level, uint indent_level) :
1.75 + _title(title), _length(0), _print_sum(print_sum), _log_level(log_level), _indent_level(indent_level),
1.76 + _has_new_data(true), _thread_work_items(NULL), _enabled(true) {
1.77 + assert(length > 0, "Must have some workers to store data for");
1.78 + _length = length;
1.79 + _data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
1.80 }
1.81
1.82 - T min = _data[0];
1.83 - T max = _data[0];
1.84 - T sum = 0;
1.85 -
1.86 - LineBuffer buf(level);
1.87 - buf.append("[%s:", title);
1.88 - for (uint i = 0; i < _length; ++i) {
1.89 - T val = _data[i];
1.90 - min = MIN2(val, min);
1.91 - max = MAX2(val, max);
1.92 - sum += val;
1.93 - if (G1Log::finest()) {
1.94 - buf.append(" ");
1.95 - buf.append(_print_format, val);
1.96 - }
1.97 + ~WorkerDataArray() {
1.98 + FREE_C_HEAP_ARRAY(T, _data, mtGC);
1.99 }
1.100
1.101 - if (G1Log::finest()) {
1.102 - buf.append_and_print_cr("%s", "");
1.103 + void link_thread_work_items(WorkerDataArray<size_t>* thread_work_items) {
1.104 + _thread_work_items = thread_work_items;
1.105 }
1.106
1.107 - double avg = (double)sum / (double)_length;
1.108 - buf.append(" Min: ");
1.109 - buf.append(_print_format, min);
1.110 - buf.append(", Avg: ");
1.111 - buf.append("%.1lf", avg); // Always print average as a double
1.112 - buf.append(", Max: ");
1.113 - buf.append(_print_format, max);
1.114 - buf.append(", Diff: ");
1.115 - buf.append(_print_format, max - min);
1.116 - if (_print_sum) {
1.117 - // for things like the start and end times the sum is not
1.118 - // that relevant
1.119 - buf.append(", Sum: ");
1.120 - buf.append(_print_format, sum);
1.121 + WorkerDataArray<size_t>* thread_work_items() { return _thread_work_items; }
1.122 +
1.123 + void set(uint worker_i, T value) {
1.124 + assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
1.125 + assert(_data[worker_i] == WorkerDataArray<T>::uninitialized(), err_msg("Overwriting data for worker %d in %s", worker_i, _title));
1.126 + _data[worker_i] = value;
1.127 + _has_new_data = true;
1.128 }
1.129 - buf.append_and_print_cr("]");
1.130 -}
1.131 -PRAGMA_DIAG_POP
1.132 +
1.133 + void set_thread_work_item(uint worker_i, size_t value) {
1.134 + assert(_thread_work_items != NULL, "No sub count");
1.135 + _thread_work_items->set(worker_i, value);
1.136 + }
1.137 +
1.138 + T get(uint worker_i) {
1.139 + assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
1.140 + assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), err_msg("No data added for worker %d", worker_i));
1.141 + return _data[worker_i];
1.142 + }
1.143 +
1.144 + void add(uint worker_i, T value) {
1.145 + assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
1.146 + assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), err_msg("No data to add to for worker %d", worker_i));
1.147 + _data[worker_i] += value;
1.148 + _has_new_data = true;
1.149 + }
1.150 +
1.151 + double average(){
1.152 + calculate_totals();
1.153 + return _average;
1.154 + }
1.155 +
1.156 + T sum() {
1.157 + calculate_totals();
1.158 + return _sum;
1.159 + }
1.160 +
1.161 + T minimum() {
1.162 + calculate_totals();
1.163 + return _min;
1.164 + }
1.165 +
1.166 + T maximum() {
1.167 + calculate_totals();
1.168 + return _max;
1.169 + }
1.170 +
1.171 + void reset() PRODUCT_RETURN;
1.172 + void verify() PRODUCT_RETURN;
1.173 +
1.174 + void set_enabled(bool enabled) { _enabled = enabled; }
1.175 +
1.176 + int log_level() { return _log_level; }
1.177 +
1.178 + private:
1.179 +
1.180 + void calculate_totals(){
1.181 + if (!_has_new_data) {
1.182 + return;
1.183 + }
1.184 +
1.185 + _sum = (T)0;
1.186 + _min = _data[0];
1.187 + _max = _min;
1.188 + for (uint i = 0; i < _length; ++i) {
1.189 + T val = _data[i];
1.190 + _sum += val;
1.191 + _min = MIN2(_min, val);
1.192 + _max = MAX2(_max, val);
1.193 + }
1.194 + _average = (double)_sum / (double)_length;
1.195 + _has_new_data = false;
1.196 + }
1.197 +};
1.198 +
1.199
1.200 #ifndef PRODUCT
1.201
1.202 -template <> const int WorkerDataArray<int>::_uninitialized = -1;
1.203 -template <> const double WorkerDataArray<double>::_uninitialized = -1.0;
1.204 -template <> const size_t WorkerDataArray<size_t>::_uninitialized = (size_t)-1;
1.205 +template <>
1.206 +size_t WorkerDataArray<size_t>::uninitialized() {
1.207 + return (size_t)-1;
1.208 +}
1.209 +
1.210 +template <>
1.211 +double WorkerDataArray<double>::uninitialized() {
1.212 + return -1.0;
1.213 +}
1.214
1.215 template <class T>
1.216 void WorkerDataArray<T>::reset() {
1.217 for (uint i = 0; i < _length; i++) {
1.218 - _data[i] = (T)_uninitialized;
1.219 + _data[i] = WorkerDataArray<T>::uninitialized();
1.220 + }
1.221 + if (_thread_work_items != NULL) {
1.222 + _thread_work_items->reset();
1.223 }
1.224 }
1.225
1.226 template <class T>
1.227 void WorkerDataArray<T>::verify() {
1.228 + if (!_enabled) {
1.229 + return;
1.230 + }
1.231 +
1.232 for (uint i = 0; i < _length; i++) {
1.233 - assert(_data[i] != _uninitialized,
1.234 - err_msg("Invalid data for worker " UINT32_FORMAT ", data: %lf, uninitialized: %lf",
1.235 - i, (double)_data[i], (double)_uninitialized));
1.236 + assert(_data[i] != WorkerDataArray<T>::uninitialized(),
1.237 + err_msg("Invalid data for worker %u in '%s'", i, _title));
1.238 + }
1.239 + if (_thread_work_items != NULL) {
1.240 + _thread_work_items->verify();
1.241 }
1.242 }
1.243
1.244 #endif
1.245
1.246 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
1.247 - _max_gc_threads(max_gc_threads),
1.248 - _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
1.249 - _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
1.250 - _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
1.251 - _last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
1.252 - _last_update_rs_processed_buffers(_max_gc_threads, "%d"),
1.253 - _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
1.254 - _last_strong_code_root_scan_times_ms(_max_gc_threads, "%.1lf"),
1.255 - _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
1.256 - _last_termination_times_ms(_max_gc_threads, "%.1lf"),
1.257 - _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
1.258 - _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
1.259 - _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
1.260 - _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"),
1.261 - _last_redirty_logged_cards_time_ms(_max_gc_threads, "%.1lf"),
1.262 - _last_redirty_logged_cards_processed_cards(_max_gc_threads, SIZE_FORMAT),
1.263 - _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"),
1.264 - _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf")
1.265 + _max_gc_threads(max_gc_threads)
1.266 {
1.267 assert(max_gc_threads > 0, "Must have some GC threads");
1.268 +
1.269 + _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2);
1.270 + _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2);
1.271 + _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFiner, 2);
1.272 + _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);
1.273 + _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);
1.274 + _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);
1.275 + _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms)", true, G1Log::LevelFiner, 2);
1.276 + _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms)", true, G1Log::LevelFiner, 2);
1.277 + _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms)", true, G1Log::LevelFiner, 2);
1.278 + _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms)", false, G1Log::LevelFiner, 2);
1.279 + _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms)", true, G1Log::LevelFiner, 2);
1.280 +
1.281 + _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers", true, G1Log::LevelFiner, 3);
1.282 + _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
1.283 +
1.284 + _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts", true, G1Log::LevelFinest, 3);
1.285 + _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
1.286 +
1.287 + _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2);
1.288 + _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2);
1.289 +
1.290 + _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3);
1.291 + _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3);
1.292 + _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
1.293 }
1.294
1.295 -void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
1.296 +void G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress) {
1.297 assert(active_gc_threads > 0, "The number of threads must be > 0");
1.298 - assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
1.299 + assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
1.300 _active_gc_threads = active_gc_threads;
1.301
1.302 - _last_gc_worker_start_times_ms.reset();
1.303 - _last_ext_root_scan_times_ms.reset();
1.304 - _last_satb_filtering_times_ms.reset();
1.305 - _last_update_rs_times_ms.reset();
1.306 - _last_update_rs_processed_buffers.reset();
1.307 - _last_scan_rs_times_ms.reset();
1.308 - _last_strong_code_root_scan_times_ms.reset();
1.309 - _last_obj_copy_times_ms.reset();
1.310 - _last_termination_times_ms.reset();
1.311 - _last_termination_attempts.reset();
1.312 - _last_gc_worker_end_times_ms.reset();
1.313 - _last_gc_worker_times_ms.reset();
1.314 - _last_gc_worker_other_times_ms.reset();
1.315 + for (int i = 0; i < GCParPhasesSentinel; i++) {
1.316 + _gc_par_phases[i]->reset();
1.317 + }
1.318
1.319 - _last_redirty_logged_cards_time_ms.reset();
1.320 - _last_redirty_logged_cards_processed_cards.reset();
1.321 + _gc_par_phases[SATBFiltering]->set_enabled(mark_in_progress);
1.322
1.323 + _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
1.324 + _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
1.325 }
1.326
1.327 void G1GCPhaseTimes::note_gc_end() {
1.328 - _last_gc_worker_start_times_ms.verify();
1.329 - _last_ext_root_scan_times_ms.verify();
1.330 - _last_satb_filtering_times_ms.verify();
1.331 - _last_update_rs_times_ms.verify();
1.332 - _last_update_rs_processed_buffers.verify();
1.333 - _last_scan_rs_times_ms.verify();
1.334 - _last_strong_code_root_scan_times_ms.verify();
1.335 - _last_obj_copy_times_ms.verify();
1.336 - _last_termination_times_ms.verify();
1.337 - _last_termination_attempts.verify();
1.338 - _last_gc_worker_end_times_ms.verify();
1.339 + for (uint i = 0; i < _active_gc_threads; i++) {
1.340 + double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
1.341 + record_time_secs(GCWorkerTotal, i , worker_time);
1.342
1.343 - for (uint i = 0; i < _active_gc_threads; i++) {
1.344 - double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i);
1.345 - _last_gc_worker_times_ms.set(i, worker_time);
1.346 + double worker_known_time =
1.347 + _gc_par_phases[ExtRootScan]->get(i) +
1.348 + _gc_par_phases[SATBFiltering]->get(i) +
1.349 + _gc_par_phases[UpdateRS]->get(i) +
1.350 + _gc_par_phases[ScanRS]->get(i) +
1.351 + _gc_par_phases[CodeRoots]->get(i) +
1.352 + _gc_par_phases[ObjCopy]->get(i) +
1.353 + _gc_par_phases[Termination]->get(i);
1.354
1.355 - double worker_known_time = _last_ext_root_scan_times_ms.get(i) +
1.356 - _last_satb_filtering_times_ms.get(i) +
1.357 - _last_update_rs_times_ms.get(i) +
1.358 - _last_scan_rs_times_ms.get(i) +
1.359 - _last_strong_code_root_scan_times_ms.get(i) +
1.360 - _last_obj_copy_times_ms.get(i) +
1.361 - _last_termination_times_ms.get(i);
1.362 -
1.363 - double worker_other_time = worker_time - worker_known_time;
1.364 - _last_gc_worker_other_times_ms.set(i, worker_other_time);
1.365 + record_time_secs(Other, i, worker_time - worker_known_time);
1.366 }
1.367
1.368 - _last_gc_worker_times_ms.verify();
1.369 - _last_gc_worker_other_times_ms.verify();
1.370 -
1.371 - _last_redirty_logged_cards_time_ms.verify();
1.372 - _last_redirty_logged_cards_processed_cards.verify();
1.373 -}
1.374 -
1.375 -void G1GCPhaseTimes::note_string_dedup_fixup_start() {
1.376 - _cur_string_dedup_queue_fixup_worker_times_ms.reset();
1.377 - _cur_string_dedup_table_fixup_worker_times_ms.reset();
1.378 -}
1.379 -
1.380 -void G1GCPhaseTimes::note_string_dedup_fixup_end() {
1.381 - _cur_string_dedup_queue_fixup_worker_times_ms.verify();
1.382 - _cur_string_dedup_table_fixup_worker_times_ms.verify();
1.383 + for (int i = 0; i < GCParPhasesSentinel; i++) {
1.384 + _gc_par_phases[i]->verify();
1.385 + }
1.386 }
1.387
1.388 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
1.389 @@ -259,7 +319,7 @@
1.390 }
1.391
1.392 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
1.393 - LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: " UINT32_FORMAT "]", str, value, workers);
1.394 + LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
1.395 }
1.396
1.397 double G1GCPhaseTimes::accounted_time_ms() {
1.398 @@ -287,46 +347,172 @@
1.399 return misc_time_ms;
1.400 }
1.401
1.402 +// record the time a phase took in seconds
1.403 +void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
1.404 + _gc_par_phases[phase]->set(worker_i, secs);
1.405 +}
1.406 +
1.407 +// add a number of seconds to a phase
1.408 +void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
1.409 + _gc_par_phases[phase]->add(worker_i, secs);
1.410 +}
1.411 +
1.412 +void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) {
1.413 + _gc_par_phases[phase]->set_thread_work_item(worker_i, count);
1.414 +}
1.415 +
1.416 +// return the average time for a phase in milliseconds
1.417 +double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
1.418 + return _gc_par_phases[phase]->average() * 1000.0;
1.419 +}
1.420 +
1.421 +double G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) {
1.422 + return _gc_par_phases[phase]->get(worker_i) * 1000.0;
1.423 +}
1.424 +
1.425 +double G1GCPhaseTimes::sum_time_ms(GCParPhases phase) {
1.426 + return _gc_par_phases[phase]->sum() * 1000.0;
1.427 +}
1.428 +
1.429 +double G1GCPhaseTimes::min_time_ms(GCParPhases phase) {
1.430 + return _gc_par_phases[phase]->minimum() * 1000.0;
1.431 +}
1.432 +
1.433 +double G1GCPhaseTimes::max_time_ms(GCParPhases phase) {
1.434 + return _gc_par_phases[phase]->maximum() * 1000.0;
1.435 +}
1.436 +
1.437 +size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i) {
1.438 + assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
1.439 + return _gc_par_phases[phase]->thread_work_items()->get(worker_i);
1.440 +}
1.441 +
1.442 +size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
1.443 + assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
1.444 + return _gc_par_phases[phase]->thread_work_items()->sum();
1.445 +}
1.446 +
1.447 +double G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) {
1.448 + assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
1.449 + return _gc_par_phases[phase]->thread_work_items()->average();
1.450 +}
1.451 +
1.452 +size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {
1.453 + assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
1.454 + return _gc_par_phases[phase]->thread_work_items()->minimum();
1.455 +}
1.456 +
1.457 +size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {
1.458 + assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
1.459 + return _gc_par_phases[phase]->thread_work_items()->maximum();
1.460 +}
1.461 +
1.462 +class G1GCParPhasePrinter : public StackObj {
1.463 + G1GCPhaseTimes* _phase_times;
1.464 + public:
1.465 + G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {}
1.466 +
1.467 + void print(G1GCPhaseTimes::GCParPhases phase_id) {
1.468 + WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id];
1.469 +
1.470 + if (phase->_log_level > G1Log::level() || !phase->_enabled) {
1.471 + return;
1.472 + }
1.473 +
1.474 + if (phase->_length == 1) {
1.475 + print_single_length(phase_id, phase);
1.476 + } else {
1.477 + print_multi_length(phase_id, phase);
1.478 + }
1.479 + }
1.480 +
1.481 + private:
1.482 +
1.483 + void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
1.484 + // No need for min, max, average and sum for only one worker
1.485 + LineBuffer buf(phase->_indent_level);
1.486 + buf.append_and_print_cr("[%s: %.1lf]", phase->_title, _phase_times->get_time_ms(phase_id, 0));
1.487 +
1.488 + if (phase->_thread_work_items != NULL) {
1.489 + LineBuffer buf2(phase->_thread_work_items->_indent_level);
1.490 + buf2.append_and_print_cr("[%s: "SIZE_FORMAT"]", phase->_thread_work_items->_title, _phase_times->sum_thread_work_items(phase_id));
1.491 + }
1.492 + }
1.493 +
1.494 + void print_time_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
1.495 + for (uint i = 0; i < phase->_length; ++i) {
1.496 + buf.append(" %.1lf", _phase_times->get_time_ms(phase_id, i));
1.497 + }
1.498 + buf.print_cr();
1.499 + }
1.500 +
1.501 + void print_count_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
1.502 + for (uint i = 0; i < thread_work_items->_length; ++i) {
1.503 + buf.append(" " SIZE_FORMAT, _phase_times->get_thread_work_item(phase_id, i));
1.504 + }
1.505 + buf.print_cr();
1.506 + }
1.507 +
1.508 + void print_thread_work_items(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
1.509 + LineBuffer buf(thread_work_items->_indent_level);
1.510 + buf.append("[%s:", thread_work_items->_title);
1.511 +
1.512 + if (G1Log::finest()) {
1.513 + print_count_values(buf, phase_id, thread_work_items);
1.514 + }
1.515 +
1.516 + assert(thread_work_items->_print_sum, err_msg("%s does not have print sum true even though it is a count", thread_work_items->_title));
1.517 +
1.518 + buf.append_and_print_cr(" Min: " SIZE_FORMAT ", Avg: %.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT "]",
1.519 + _phase_times->min_thread_work_items(phase_id), _phase_times->average_thread_work_items(phase_id), _phase_times->max_thread_work_items(phase_id),
1.520 + _phase_times->max_thread_work_items(phase_id) - _phase_times->min_thread_work_items(phase_id), _phase_times->sum_thread_work_items(phase_id));
1.521 + }
1.522 +
1.523 + void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
1.524 + LineBuffer buf(phase->_indent_level);
1.525 + buf.append("[%s:", phase->_title);
1.526 +
1.527 + if (G1Log::finest()) {
1.528 + print_time_values(buf, phase_id, phase);
1.529 + }
1.530 +
1.531 + buf.append(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf",
1.532 + _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
1.533 + _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
1.534 +
1.535 + if (phase->_print_sum) {
1.536 + // for things like the start and end times the sum is not
1.537 + // that relevant
1.538 + buf.append(", Sum: %.1lf", _phase_times->sum_time_ms(phase_id));
1.539 + }
1.540 +
1.541 + buf.append_and_print_cr("]");
1.542 +
1.543 + if (phase->_thread_work_items != NULL) {
1.544 + print_thread_work_items(phase_id, phase->_thread_work_items);
1.545 + }
1.546 + }
1.547 +};
1.548 +
1.549 void G1GCPhaseTimes::print(double pause_time_sec) {
1.550 + G1GCParPhasePrinter par_phase_printer(this);
1.551 +
1.552 if (_root_region_scan_wait_time_ms > 0.0) {
1.553 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1.554 }
1.555 - if (G1CollectedHeap::use_parallel_gc_threads()) {
1.556 - print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
1.557 - _last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)");
1.558 - _last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)");
1.559 - if (_last_satb_filtering_times_ms.sum() > 0.0) {
1.560 - _last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)");
1.561 - }
1.562 - _last_update_rs_times_ms.print(2, "Update RS (ms)");
1.563 - _last_update_rs_processed_buffers.print(3, "Processed Buffers");
1.564 - _last_scan_rs_times_ms.print(2, "Scan RS (ms)");
1.565 - _last_strong_code_root_scan_times_ms.print(2, "Code Root Scanning (ms)");
1.566 - _last_obj_copy_times_ms.print(2, "Object Copy (ms)");
1.567 - _last_termination_times_ms.print(2, "Termination (ms)");
1.568 - if (G1Log::finest()) {
1.569 - _last_termination_attempts.print(3, "Termination Attempts");
1.570 - }
1.571 - _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)");
1.572 - _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)");
1.573 - _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)");
1.574 - } else {
1.575 - _last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)");
1.576 - if (_last_satb_filtering_times_ms.sum() > 0.0) {
1.577 - _last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)");
1.578 - }
1.579 - _last_update_rs_times_ms.print(1, "Update RS (ms)");
1.580 - _last_update_rs_processed_buffers.print(2, "Processed Buffers");
1.581 - _last_scan_rs_times_ms.print(1, "Scan RS (ms)");
1.582 - _last_strong_code_root_scan_times_ms.print(1, "Code Root Scanning (ms)");
1.583 - _last_obj_copy_times_ms.print(1, "Object Copy (ms)");
1.584 +
1.585 + print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
1.586 + for (int i = 0; i <= GCMainParPhasesLast; i++) {
1.587 + par_phase_printer.print((GCParPhases) i);
1.588 }
1.589 +
1.590 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
1.591 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
1.592 if (G1StringDedup::is_enabled()) {
1.593 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
1.594 - _cur_string_dedup_queue_fixup_worker_times_ms.print(2, "Queue Fixup (ms)");
1.595 - _cur_string_dedup_table_fixup_worker_times_ms.print(2, "Table Fixup (ms)");
1.596 + for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
1.597 + par_phase_printer.print((GCParPhases) i);
1.598 + }
1.599 }
1.600 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
1.601 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
1.602 @@ -350,10 +536,7 @@
1.603 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
1.604 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
1.605 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
1.606 - if (G1Log::finest()) {
1.607 - _last_redirty_logged_cards_time_ms.print(3, "Parallel Redirty");
1.608 - _last_redirty_logged_cards_processed_cards.print(3, "Redirtied Cards");
1.609 - }
1.610 + par_phase_printer.print(RedirtyCards);
1.611 if (G1ReclaimDeadHumongousObjectsAtYoungGC) {
1.612 print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
1.613 if (G1Log::finest()) {
1.614 @@ -373,3 +556,17 @@
1.615 print_stats(2, "Verify After", _cur_verify_after_time_ms);
1.616 }
1.617 }
1.618 +
1.619 +G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
1.620 + _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
1.621 + if (_phase_times != NULL) {
1.622 + _start_time = os::elapsedTime();
1.623 + }
1.624 +}
1.625 +
1.626 +G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
1.627 + if (_phase_times != NULL) {
1.628 + _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
1.629 + }
1.630 +}
1.631 +
