1.1 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Mon Jul 02 10:54:17 2012 -0400
1.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed Jul 11 22:47:38 2012 +0200
1.3 @@ -29,6 +29,7 @@
1.4 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
1.5 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
1.6 #include "gc_implementation/g1/g1ErgoVerbose.hpp"
1.7 +#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
1.8 #include "gc_implementation/g1/g1Log.hpp"
1.9 #include "gc_implementation/g1/heapRegionRemSet.hpp"
1.10 #include "gc_implementation/shared/gcPolicyCounters.hpp"
1.11 @@ -77,57 +78,6 @@
1.12 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30
1.13 };
1.14
1.15 -// Help class for avoiding interleaved logging
1.16 -class LineBuffer: public StackObj {
1.17 -
1.18 -private:
1.19 - static const int BUFFER_LEN = 1024;
1.20 - static const int INDENT_CHARS = 3;
1.21 - char _buffer[BUFFER_LEN];
1.22 - int _indent_level;
1.23 - int _cur;
1.24 -
1.25 - void vappend(const char* format, va_list ap) {
1.26 - int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
1.27 - if (res != -1) {
1.28 - _cur += res;
1.29 - } else {
1.30 - DEBUG_ONLY(warning("buffer too small in LineBuffer");)
1.31 - _buffer[BUFFER_LEN -1] = 0;
1.32 - _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
1.33 - }
1.34 - }
1.35 -
1.36 -public:
1.37 - explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
1.38 - for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
1.39 - _buffer[_cur] = ' ';
1.40 - }
1.41 - }
1.42 -
1.43 -#ifndef PRODUCT
1.44 - ~LineBuffer() {
1.45 - assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
1.46 - }
1.47 -#endif
1.48 -
1.49 - void append(const char* format, ...) {
1.50 - va_list ap;
1.51 - va_start(ap, format);
1.52 - vappend(format, ap);
1.53 - va_end(ap);
1.54 - }
1.55 -
1.56 - void append_and_print_cr(const char* format, ...) {
1.57 - va_list ap;
1.58 - va_start(ap, format);
1.59 - vappend(format, ap);
1.60 - va_end(ap);
1.61 - gclog_or_tty->print_cr("%s", _buffer);
1.62 - _cur = _indent_level * INDENT_CHARS;
1.63 - }
1.64 -};
1.65 -
1.66 G1CollectorPolicy::G1CollectorPolicy() :
1.67 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
1.68 ? ParallelGCThreads : 1),
1.69 @@ -135,20 +85,6 @@
1.70 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
1.71 _stop_world_start(0.0),
1.72
1.73 - _cur_clear_ct_time_ms(0.0),
1.74 - _root_region_scan_wait_time_ms(0.0),
1.75 -
1.76 - _cur_ref_proc_time_ms(0.0),
1.77 - _cur_ref_enq_time_ms(0.0),
1.78 -
1.79 -#ifndef PRODUCT
1.80 - _min_clear_cc_time_ms(-1.0),
1.81 - _max_clear_cc_time_ms(-1.0),
1.82 - _cur_clear_cc_time_ms(0.0),
1.83 - _cum_clear_cc_time_ms(0.0),
1.84 - _num_cc_clears(0L),
1.85 -#endif
1.86 -
1.87 _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
1.88 _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
1.89
1.90 @@ -257,30 +193,9 @@
1.91 _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
1.92 _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
1.93
1.94 - _par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads];
1.95 - _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads];
1.96 - _par_last_satb_filtering_times_ms = new double[_parallel_gc_threads];
1.97 + _phase_times = new G1GCPhaseTimes(_parallel_gc_threads);
1.98
1.99 - _par_last_update_rs_times_ms = new double[_parallel_gc_threads];
1.100 - _par_last_update_rs_processed_buffers = new double[_parallel_gc_threads];
1.101 -
1.102 - _par_last_scan_rs_times_ms = new double[_parallel_gc_threads];
1.103 -
1.104 - _par_last_obj_copy_times_ms = new double[_parallel_gc_threads];
1.105 -
1.106 - _par_last_termination_times_ms = new double[_parallel_gc_threads];
1.107 - _par_last_termination_attempts = new double[_parallel_gc_threads];
1.108 - _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads];
1.109 - _par_last_gc_worker_times_ms = new double[_parallel_gc_threads];
1.110 - _par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads];
1.111 -
1.112 - int index;
1.113 - if (ParallelGCThreads == 0)
1.114 - index = 0;
1.115 - else if (ParallelGCThreads > 8)
1.116 - index = 7;
1.117 - else
1.118 - index = ParallelGCThreads - 1;
1.119 + int index = MIN2(_parallel_gc_threads - 1, 7);
1.120
1.121 _pending_card_diff_seq->add(0.0);
1.122 _rs_length_diff_seq->add(rs_length_diff_defaults[index]);
1.123 @@ -824,7 +739,7 @@
1.124 #endif // PRODUCT
1.125
1.126 void G1CollectorPolicy::record_full_collection_start() {
1.127 - _cur_collection_start_sec = os::elapsedTime();
1.128 + _full_collection_start_sec = os::elapsedTime();
1.129 // Release the future to-space so that it is available for compaction into.
1.130 _g1->set_full_collection();
1.131 }
1.132 @@ -833,7 +748,7 @@
1.133 // Consider this like a collection pause for the purposes of allocation
1.134 // since last pause.
1.135 double end_sec = os::elapsedTime();
1.136 - double full_gc_time_sec = end_sec - _cur_collection_start_sec;
1.137 + double full_gc_time_sec = end_sec - _full_collection_start_sec;
1.138 double full_gc_time_ms = full_gc_time_sec * 1000.0;
1.139
1.140 _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
1.141 @@ -869,12 +784,6 @@
1.142
1.143 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
1.144 size_t start_used) {
1.145 - if (G1Log::finer()) {
1.146 - gclog_or_tty->stamp(PrintGCTimeStamps);
1.147 - gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
1.148 - .append(gcs_are_young() ? " (young)" : " (mixed)"));
1.149 - }
1.150 -
1.151 // We only need to do this here as the policy will only be applied
1.152 // to the GC we're about to start. so, no point is calculating this
1.153 // every time we calculate / recalculate the target young length.
1.154 @@ -888,7 +797,7 @@
1.155 _trace_gen0_time_data.record_start_collection(s_w_t_ms);
1.156 _stop_world_start = 0.0;
1.157
1.158 - _cur_collection_start_sec = start_time_sec;
1.159 + phase_times()->_cur_collection_start_sec = start_time_sec;
1.160 _cur_collection_pause_used_at_start_bytes = start_used;
1.161 _cur_collection_pause_used_regions_at_start = _g1->used_regions();
1.162 _pending_cards = _g1->pending_card_num();
1.163 @@ -902,30 +811,6 @@
1.164 _survivor_bytes_before_gc = young_list->survivor_used_bytes();
1.165 _capacity_before_gc = _g1->capacity();
1.166
1.167 -#ifdef DEBUG
1.168 - // initialise these to something well known so that we can spot
1.169 - // if they are not set properly
1.170 -
1.171 - for (int i = 0; i < _parallel_gc_threads; ++i) {
1.172 - _par_last_gc_worker_start_times_ms[i] = -1234.0;
1.173 - _par_last_ext_root_scan_times_ms[i] = -1234.0;
1.174 - _par_last_satb_filtering_times_ms[i] = -1234.0;
1.175 - _par_last_update_rs_times_ms[i] = -1234.0;
1.176 - _par_last_update_rs_processed_buffers[i] = -1234.0;
1.177 - _par_last_scan_rs_times_ms[i] = -1234.0;
1.178 - _par_last_obj_copy_times_ms[i] = -1234.0;
1.179 - _par_last_termination_times_ms[i] = -1234.0;
1.180 - _par_last_termination_attempts[i] = -1234.0;
1.181 - _par_last_gc_worker_end_times_ms[i] = -1234.0;
1.182 - _par_last_gc_worker_times_ms[i] = -1234.0;
1.183 - _par_last_gc_worker_other_times_ms[i] = -1234.0;
1.184 - }
1.185 -#endif
1.186 -
1.187 - // This is initialized to zero here and is set during the evacuation
1.188 - // pause if we actually waited for the root region scanning to finish.
1.189 - _root_region_scan_wait_time_ms = 0.0;
1.190 -
1.191 _last_gc_was_young = false;
1.192
1.193 // do that for any other surv rate groups
1.194 @@ -974,127 +859,6 @@
1.195 }
1.196 }
1.197
1.198 -void G1CollectorPolicy::record_concurrent_pause_end() {
1.199 -}
1.200 -
1.201 -template<class T>
1.202 -T sum_of(T* sum_arr, int start, int n, int N) {
1.203 - T sum = (T)0;
1.204 - for (int i = 0; i < n; i++) {
1.205 - int j = (start + i) % N;
1.206 - sum += sum_arr[j];
1.207 - }
1.208 - return sum;
1.209 -}
1.210 -
1.211 -void G1CollectorPolicy::print_par_stats(int level,
1.212 - const char* str,
1.213 - double* data,
1.214 - bool showDecimals) {
1.215 - double min = data[0], max = data[0];
1.216 - double total = 0.0;
1.217 - LineBuffer buf(level);
1.218 - buf.append("[%s (ms):", str);
1.219 - for (uint i = 0; i < no_of_gc_threads(); ++i) {
1.220 - double val = data[i];
1.221 - if (val < min)
1.222 - min = val;
1.223 - if (val > max)
1.224 - max = val;
1.225 - total += val;
1.226 - if (G1Log::finest()) {
1.227 - if (showDecimals) {
1.228 - buf.append(" %.1lf", val);
1.229 - } else {
1.230 - buf.append(" %d", (int)val);
1.231 - }
1.232 - }
1.233 - }
1.234 -
1.235 - if (G1Log::finest()) {
1.236 - buf.append_and_print_cr("");
1.237 - }
1.238 - double avg = total / (double) no_of_gc_threads();
1.239 - if (showDecimals) {
1.240 - buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
1.241 - min, avg, max, max - min, total);
1.242 - } else {
1.243 - buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
1.244 - (int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
1.245 - }
1.246 -}
1.247 -
1.248 -void G1CollectorPolicy::print_stats(int level,
1.249 - const char* str,
1.250 - double value) {
1.251 - LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
1.252 -}
1.253 -
1.254 -void G1CollectorPolicy::print_stats(int level,
1.255 - const char* str,
1.256 - double value,
1.257 - int workers) {
1.258 - LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
1.259 -}
1.260 -
1.261 -void G1CollectorPolicy::print_stats(int level,
1.262 - const char* str,
1.263 - int value) {
1.264 - LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
1.265 -}
1.266 -
1.267 -double G1CollectorPolicy::avg_value(double* data) {
1.268 - if (G1CollectedHeap::use_parallel_gc_threads()) {
1.269 - double ret = 0.0;
1.270 - for (uint i = 0; i < no_of_gc_threads(); ++i) {
1.271 - ret += data[i];
1.272 - }
1.273 - return ret / (double) no_of_gc_threads();
1.274 - } else {
1.275 - return data[0];
1.276 - }
1.277 -}
1.278 -
1.279 -double G1CollectorPolicy::max_value(double* data) {
1.280 - if (G1CollectedHeap::use_parallel_gc_threads()) {
1.281 - double ret = data[0];
1.282 - for (uint i = 1; i < no_of_gc_threads(); ++i) {
1.283 - if (data[i] > ret) {
1.284 - ret = data[i];
1.285 - }
1.286 - }
1.287 - return ret;
1.288 - } else {
1.289 - return data[0];
1.290 - }
1.291 -}
1.292 -
1.293 -double G1CollectorPolicy::sum_of_values(double* data) {
1.294 - if (G1CollectedHeap::use_parallel_gc_threads()) {
1.295 - double sum = 0.0;
1.296 - for (uint i = 0; i < no_of_gc_threads(); i++) {
1.297 - sum += data[i];
1.298 - }
1.299 - return sum;
1.300 - } else {
1.301 - return data[0];
1.302 - }
1.303 -}
1.304 -
1.305 -double G1CollectorPolicy::max_sum(double* data1, double* data2) {
1.306 - double ret = data1[0] + data2[0];
1.307 -
1.308 - if (G1CollectedHeap::use_parallel_gc_threads()) {
1.309 - for (uint i = 1; i < no_of_gc_threads(); ++i) {
1.310 - double data = data1[i] + data2[i];
1.311 - if (data > ret) {
1.312 - ret = data;
1.313 - }
1.314 - }
1.315 - }
1.316 - return ret;
1.317 -}
1.318 -
1.319 bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) {
1.320 if (_g1->concurrent_mark()->cmThread()->during_cycle()) {
1.321 return false;
1.322 @@ -1142,10 +906,8 @@
1.323 // Anything below that is considered to be zero
1.324 #define MIN_TIMER_GRANULARITY 0.0000001
1.325
1.326 -void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
1.327 +void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
1.328 double end_time_sec = os::elapsedTime();
1.329 - double elapsed_ms = _last_pause_time_ms;
1.330 - bool parallel = G1CollectedHeap::use_parallel_gc_threads();
1.331 assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
1.332 "otherwise, the subtraction below does not make sense");
1.333 size_t rs_size =
1.334 @@ -1154,7 +916,6 @@
1.335 assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
1.336 bool last_pause_included_initial_mark = false;
1.337 bool update_stats = !_g1->evacuation_failed();
1.338 - set_no_of_gc_threads(no_of_gc_threads);
1.339
1.340 #ifndef PRODUCT
1.341 if (G1YoungSurvRateVerbose) {
1.342 @@ -1174,7 +935,7 @@
1.343 set_initiate_conc_mark_if_possible();
1.344 }
1.345
1.346 - _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
1.347 + _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0,
1.348 end_time_sec, false);
1.349
1.350 size_t freed_bytes =
1.351 @@ -1185,58 +946,11 @@
1.352 (double)surviving_bytes/
1.353 (double)_collection_set_bytes_used_before;
1.354
1.355 - // These values are used to update the summary information that is
1.356 - // displayed when TraceGen0Time is enabled, and are output as part
1.357 - // of the "finer" output, in the non-parallel case.
1.358 -
1.359 - double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
1.360 - double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
1.361 - double update_rs_time = avg_value(_par_last_update_rs_times_ms);
1.362 - double update_rs_processed_buffers =
1.363 - sum_of_values(_par_last_update_rs_processed_buffers);
1.364 - double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
1.365 - double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
1.366 - double termination_time = avg_value(_par_last_termination_times_ms);
1.367 -
1.368 - double known_time = ext_root_scan_time +
1.369 - satb_filtering_time +
1.370 - update_rs_time +
1.371 - scan_rs_time +
1.372 - obj_copy_time;
1.373 -
1.374 - double other_time_ms = elapsed_ms;
1.375 -
1.376 - // Subtract the root region scanning wait time. It's initialized to
1.377 - // zero at the start of the pause.
1.378 - other_time_ms -= _root_region_scan_wait_time_ms;
1.379 -
1.380 - if (parallel) {
1.381 - other_time_ms -= _cur_collection_par_time_ms;
1.382 - } else {
1.383 - other_time_ms -= known_time;
1.384 - }
1.385 -
1.386 - // Now subtract the time taken to fix up roots in generated code
1.387 - other_time_ms -= _cur_collection_code_root_fixup_time_ms;
1.388 -
1.389 - // Subtract the time taken to clean the card table from the
1.390 - // current value of "other time"
1.391 - other_time_ms -= _cur_clear_ct_time_ms;
1.392 -
1.393 - // TraceGen0Time and TraceGen1Time summary info updating.
1.394 -
1.395 if (update_stats) {
1.396 - double parallel_known_time = known_time + termination_time;
1.397 - double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
1.398 -
1.399 - _trace_gen0_time_data.record_end_collection(
1.400 - elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
1.401 - ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
1.402 - termination_time, parallel_other_time, _cur_clear_ct_time_ms);
1.403 -
1.404 + _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
1.405 // this is where we update the allocation rate of the application
1.406 double app_time_ms =
1.407 - (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
1.408 + (phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
1.409 if (app_time_ms < MIN_TIMER_GRANULARITY) {
1.410 // This usually happens due to the timer not having the required
1.411 // granularity. Some Linuxes are the usual culprits.
1.412 @@ -1257,7 +971,7 @@
1.413
1.414 double interval_ms =
1.415 (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0;
1.416 - update_recent_gc_times(end_time_sec, elapsed_ms);
1.417 + update_recent_gc_times(end_time_sec, pause_time_ms);
1.418 _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms;
1.419 if (recent_avg_pause_time_ratio() < 0.0 ||
1.420 (recent_avg_pause_time_ratio() - 1.0 > 0.0)) {
1.421 @@ -1284,90 +998,6 @@
1.422 }
1.423 }
1.424 }
1.425 -
1.426 - if (G1Log::finer()) {
1.427 - bool print_marking_info =
1.428 - _g1->mark_in_progress() && !last_pause_included_initial_mark;
1.429 -
1.430 - gclog_or_tty->print_cr("%s, %1.8lf secs]",
1.431 - (last_pause_included_initial_mark) ? " (initial-mark)" : "",
1.432 - elapsed_ms / 1000.0);
1.433 -
1.434 - if (_root_region_scan_wait_time_ms > 0.0) {
1.435 - print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1.436 - }
1.437 - if (parallel) {
1.438 - print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads);
1.439 - print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1.440 - print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1.441 - if (print_marking_info) {
1.442 - print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1.443 - }
1.444 - print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1.445 - if (G1Log::finest()) {
1.446 - print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
1.447 - false /* showDecimals */);
1.448 - }
1.449 - print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
1.450 - print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
1.451 - print_par_stats(2, "Termination", _par_last_termination_times_ms);
1.452 - if (G1Log::finest()) {
1.453 - print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
1.454 - false /* showDecimals */);
1.455 - }
1.456 -
1.457 - for (int i = 0; i < _parallel_gc_threads; i++) {
1.458 - _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
1.459 - _par_last_gc_worker_start_times_ms[i];
1.460 -
1.461 - double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
1.462 - _par_last_satb_filtering_times_ms[i] +
1.463 - _par_last_update_rs_times_ms[i] +
1.464 - _par_last_scan_rs_times_ms[i] +
1.465 - _par_last_obj_copy_times_ms[i] +
1.466 - _par_last_termination_times_ms[i];
1.467 -
1.468 - _par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
1.469 - worker_known_time;
1.470 - }
1.471 -
1.472 - print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
1.473 - print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms);
1.474 - print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
1.475 - } else {
1.476 - print_stats(1, "Ext Root Scanning", ext_root_scan_time);
1.477 - if (print_marking_info) {
1.478 - print_stats(1, "SATB Filtering", satb_filtering_time);
1.479 - }
1.480 - print_stats(1, "Update RS", update_rs_time);
1.481 - if (G1Log::finest()) {
1.482 - print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers);
1.483 - }
1.484 - print_stats(1, "Scan RS", scan_rs_time);
1.485 - print_stats(1, "Object Copying", obj_copy_time);
1.486 - }
1.487 - print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
1.488 - print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
1.489 -#ifndef PRODUCT
1.490 - print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
1.491 - print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
1.492 - print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
1.493 - print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
1.494 - if (_num_cc_clears > 0) {
1.495 - print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
1.496 - }
1.497 -#endif
1.498 - print_stats(1, "Other", other_time_ms);
1.499 - print_stats(2, "Choose CSet",
1.500 - (_recorded_young_cset_choice_time_ms +
1.501 - _recorded_non_young_cset_choice_time_ms));
1.502 - print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
1.503 - print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
1.504 - print_stats(2, "Free CSet",
1.505 - (_recorded_young_free_cset_time_ms +
1.506 - _recorded_non_young_free_cset_time_ms));
1.507 - }
1.508 -
1.509 bool new_in_marking_window = _in_marking_window;
1.510 bool new_in_marking_window_im = false;
1.511 if (during_initial_mark_pause()) {
1.512 @@ -1406,8 +1036,6 @@
1.513 // do that for any other surv rate groupsx
1.514
1.515 if (update_stats) {
1.516 - double pause_time_ms = elapsed_ms;
1.517 -
1.518 size_t diff = 0;
1.519 if (_max_pending_cards >= _pending_cards) {
1.520 diff = _max_pending_cards - _pending_cards;
1.521 @@ -1416,7 +1044,7 @@
1.522
1.523 double cost_per_card_ms = 0.0;
1.524 if (_pending_cards > 0) {
1.525 - cost_per_card_ms = update_rs_time / (double) _pending_cards;
1.526 + cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards;
1.527 _cost_per_card_ms_seq->add(cost_per_card_ms);
1.528 }
1.529
1.530 @@ -1424,7 +1052,7 @@
1.531
1.532 double cost_per_entry_ms = 0.0;
1.533 if (cards_scanned > 10) {
1.534 - cost_per_entry_ms = scan_rs_time / (double) cards_scanned;
1.535 + cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned;
1.536 if (_last_gc_was_young) {
1.537 _cost_per_entry_ms_seq->add(cost_per_entry_ms);
1.538 } else {
1.539 @@ -1464,7 +1092,7 @@
1.540 size_t copied_bytes = surviving_bytes;
1.541 double cost_per_byte_ms = 0.0;
1.542 if (copied_bytes > 0) {
1.543 - cost_per_byte_ms = obj_copy_time / (double) copied_bytes;
1.544 + cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes;
1.545 if (_in_marking_window) {
1.546 _cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
1.547 } else {
1.548 @@ -1473,21 +1101,21 @@
1.549 }
1.550
1.551 double all_other_time_ms = pause_time_ms -
1.552 - (update_rs_time + scan_rs_time + obj_copy_time + termination_time);
1.553 + (phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time);
1.554
1.555 double young_other_time_ms = 0.0;
1.556 if (young_cset_region_length() > 0) {
1.557 young_other_time_ms =
1.558 - _recorded_young_cset_choice_time_ms +
1.559 - _recorded_young_free_cset_time_ms;
1.560 + phase_times()->_recorded_young_cset_choice_time_ms +
1.561 + phase_times()->_recorded_young_free_cset_time_ms;
1.562 _young_other_cost_per_region_ms_seq->add(young_other_time_ms /
1.563 (double) young_cset_region_length());
1.564 }
1.565 double non_young_other_time_ms = 0.0;
1.566 if (old_cset_region_length() > 0) {
1.567 non_young_other_time_ms =
1.568 - _recorded_non_young_cset_choice_time_ms +
1.569 - _recorded_non_young_free_cset_time_ms;
1.570 + phase_times()->_recorded_non_young_cset_choice_time_ms +
1.571 + phase_times()->_recorded_non_young_free_cset_time_ms;
1.572
1.573 _non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms /
1.574 (double) old_cset_region_length());
1.575 @@ -1514,7 +1142,7 @@
1.576
1.577 // Note that _mmu_tracker->max_gc_time() returns the time in seconds.
1.578 double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
1.579 - adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms);
1.580 + adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms);
1.581
1.582 _collectionSetChooser->verify();
1.583 }
1.584 @@ -2323,7 +1951,7 @@
1.585 set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
1.586
1.587 double young_end_time_sec = os::elapsedTime();
1.588 - _recorded_young_cset_choice_time_ms =
1.589 + phase_times()->_recorded_young_cset_choice_time_ms =
1.590 (young_end_time_sec - young_start_time_sec) * 1000.0;
1.591
1.592 // We are doing young collections so reset this.
1.593 @@ -2439,7 +2067,7 @@
1.594 predicted_pause_time_ms, target_pause_time_ms);
1.595
1.596 double non_young_end_time_sec = os::elapsedTime();
1.597 - _recorded_non_young_cset_choice_time_ms =
1.598 + phase_times()->_recorded_non_young_cset_choice_time_ms =
1.599 (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
1.600 }
1.601
1.602 @@ -2455,33 +2083,29 @@
1.603 }
1.604 }
1.605
1.606 -void TraceGen0TimeData::record_end_collection(
1.607 - double total_ms,
1.608 - double other_ms,
1.609 - double root_region_scan_wait_ms,
1.610 - double parallel_ms,
1.611 - double ext_root_scan_ms,
1.612 - double satb_filtering_ms,
1.613 - double update_rs_ms,
1.614 - double scan_rs_ms,
1.615 - double obj_copy_ms,
1.616 - double termination_ms,
1.617 - double parallel_other_ms,
1.618 - double clear_ct_ms)
1.619 -{
1.620 +void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times) {
1.621 if(TraceGen0Time) {
1.622 - _total.add(total_ms);
1.623 - _other.add(other_ms);
1.624 - _root_region_scan_wait.add(root_region_scan_wait_ms);
1.625 - _parallel.add(parallel_ms);
1.626 - _ext_root_scan.add(ext_root_scan_ms);
1.627 - _satb_filtering.add(satb_filtering_ms);
1.628 - _update_rs.add(update_rs_ms);
1.629 - _scan_rs.add(scan_rs_ms);
1.630 - _obj_copy.add(obj_copy_ms);
1.631 - _termination.add(termination_ms);
1.632 - _parallel_other.add(parallel_other_ms);
1.633 - _clear_ct.add(clear_ct_ms);
1.634 + _total.add(pause_time_ms);
1.635 + _other.add(pause_time_ms - phase_times->accounted_time_ms());
1.636 + _root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
1.637 + _parallel.add(phase_times->_cur_collection_par_time_ms);
1.638 + _ext_root_scan.add(phase_times->_ext_root_scan_time);
1.639 + _satb_filtering.add(phase_times->_satb_filtering_time);
1.640 + _update_rs.add(phase_times->_update_rs_time);
1.641 + _scan_rs.add(phase_times->_scan_rs_time);
1.642 + _obj_copy.add(phase_times->_obj_copy_time);
1.643 + _termination.add(phase_times->_termination_time);
1.644 +
1.645 + double parallel_known_time = phase_times->_ext_root_scan_time +
1.646 + phase_times->_satb_filtering_time +
1.647 + phase_times->_update_rs_time +
1.648 + phase_times->_scan_rs_time +
1.649 + phase_times->_obj_copy_time +
1.650 + + phase_times->_termination_time;
1.651 +
1.652 + double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time;
1.653 + _parallel_other.add(parallel_other_time);
1.654 + _clear_ct.add(phase_times->_cur_clear_ct_time_ms);
1.655 }
1.656 }
1.657
1.658 @@ -2497,20 +2121,18 @@
1.659 }
1.660 }
1.661
1.662 -void TraceGen0TimeData::print_summary(int level,
1.663 - const char* str,
1.664 +void TraceGen0TimeData::print_summary(const char* str,
1.665 const NumberSeq* seq) const {
1.666 double sum = seq->sum();
1.667 - LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
1.668 + gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)",
1.669 str, sum / 1000.0, seq->avg());
1.670 }
1.671
1.672 -void TraceGen0TimeData::print_summary_sd(int level,
1.673 - const char* str,
1.674 +void TraceGen0TimeData::print_summary_sd(const char* str,
1.675 const NumberSeq* seq) const {
1.676 - print_summary(level, str, seq);
1.677 - LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
1.678 - seq->num(), seq->sd(), seq->maximum());
1.679 + print_summary(str, seq);
1.680 + gclog_or_tty->print_cr("%+45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
1.681 + "(num", seq->num(), seq->sd(), seq->maximum());
1.682 }
1.683
1.684 void TraceGen0TimeData::print() const {
1.685 @@ -2519,7 +2141,7 @@
1.686 }
1.687
1.688 gclog_or_tty->print_cr("ALL PAUSES");
1.689 - print_summary_sd(0, "Total", &_total);
1.690 + print_summary_sd(" Total", &_total);
1.691 gclog_or_tty->print_cr("");
1.692 gclog_or_tty->print_cr("");
1.693 gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
1.694 @@ -2531,24 +2153,24 @@
1.695 if (_young_pause_num == 0 && _mixed_pause_num == 0) {
1.696 gclog_or_tty->print_cr("none");
1.697 } else {
1.698 - print_summary_sd(0, "Evacuation Pauses", &_total);
1.699 - print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait);
1.700 - print_summary(1, "Parallel Time", &_parallel);
1.701 - print_summary(2, "Ext Root Scanning", &_ext_root_scan);
1.702 - print_summary(2, "SATB Filtering", &_satb_filtering);
1.703 - print_summary(2, "Update RS", &_update_rs);
1.704 - print_summary(2, "Scan RS", &_scan_rs);
1.705 - print_summary(2, "Object Copy", &_obj_copy);
1.706 - print_summary(2, "Termination", &_termination);
1.707 - print_summary(2, "Parallel Other", &_parallel_other);
1.708 - print_summary(1, "Clear CT", &_clear_ct);
1.709 - print_summary(1, "Other", &_other);
1.710 + print_summary_sd(" Evacuation Pauses", &_total);
1.711 + print_summary(" Root Region Scan Wait", &_root_region_scan_wait);
1.712 + print_summary(" Parallel Time", &_parallel);
1.713 + print_summary(" Ext Root Scanning", &_ext_root_scan);
1.714 + print_summary(" SATB Filtering", &_satb_filtering);
1.715 + print_summary(" Update RS", &_update_rs);
1.716 + print_summary(" Scan RS", &_scan_rs);
1.717 + print_summary(" Object Copy", &_obj_copy);
1.718 + print_summary(" Termination", &_termination);
1.719 + print_summary(" Parallel Other", &_parallel_other);
1.720 + print_summary(" Clear CT", &_clear_ct);
1.721 + print_summary(" Other", &_other);
1.722 }
1.723 gclog_or_tty->print_cr("");
1.724
1.725 gclog_or_tty->print_cr("MISC");
1.726 - print_summary_sd(0, "Stop World", &_all_stop_world_times_ms);
1.727 - print_summary_sd(0, "Yields", &_all_yield_times_ms);
1.728 + print_summary_sd(" Stop World", &_all_stop_world_times_ms);
1.729 + print_summary_sd(" Yields", &_all_yield_times_ms);
1.730 }
1.731
1.732 void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
