Mercurial > hg > truffle
diff src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 6219:922993931b3d
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
Summary: Also reviewed by: vitalyd@gmail.com. Move the timing out of G1CollectorPolicy into the G1GCPhaseTimes class
Reviewed-by: johnc
author | brutisso |
---|---|
date | Wed, 11 Jul 2012 22:47:38 +0200 |
parents | bbc900c2482a |
children | a2f7274eb6ef |
line wrap: on
line diff
--- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Mon Jul 02 10:54:17 2012 -0400 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed Jul 11 22:47:38 2012 +0200 @@ -29,6 +29,7 @@ #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" #include "gc_implementation/g1/g1CollectorPolicy.hpp" #include "gc_implementation/g1/g1ErgoVerbose.hpp" +#include "gc_implementation/g1/g1GCPhaseTimes.hpp" #include "gc_implementation/g1/g1Log.hpp" #include "gc_implementation/g1/heapRegionRemSet.hpp" #include "gc_implementation/shared/gcPolicyCounters.hpp" @@ -77,57 +78,6 @@ 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30 }; -// Help class for avoiding interleaved logging -class LineBuffer: public StackObj { - -private: - static const int BUFFER_LEN = 1024; - static const int INDENT_CHARS = 3; - char _buffer[BUFFER_LEN]; - int _indent_level; - int _cur; - - void vappend(const char* format, va_list ap) { - int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap); - if (res != -1) { - _cur += res; - } else { - DEBUG_ONLY(warning("buffer too small in LineBuffer");) - _buffer[BUFFER_LEN -1] = 0; - _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again - } - } - -public: - explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) { - for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) { - _buffer[_cur] = ' '; - } - } - -#ifndef PRODUCT - ~LineBuffer() { - assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?"); - } -#endif - - void append(const char* format, ...) { - va_list ap; - va_start(ap, format); - vappend(format, ap); - va_end(ap); - } - - void append_and_print_cr(const char* format, ...) { - va_list ap; - va_start(ap, format); - vappend(format, ap); - va_end(ap); - gclog_or_tty->print_cr("%s", _buffer); - _cur = _indent_level * INDENT_CHARS; - } -}; - G1CollectorPolicy::G1CollectorPolicy() : _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() ? ParallelGCThreads : 1), @@ -135,20 +85,6 @@ _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), _stop_world_start(0.0), - _cur_clear_ct_time_ms(0.0), - _root_region_scan_wait_time_ms(0.0), - - _cur_ref_proc_time_ms(0.0), - _cur_ref_enq_time_ms(0.0), - -#ifndef PRODUCT - _min_clear_cc_time_ms(-1.0), - _max_clear_cc_time_ms(-1.0), - _cur_clear_cc_time_ms(0.0), - _cum_clear_cc_time_ms(0.0), - _num_cc_clears(0L), -#endif - _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), @@ -257,30 +193,9 @@ _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; - _par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads]; - _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads]; - _par_last_satb_filtering_times_ms = new double[_parallel_gc_threads]; - - _par_last_update_rs_times_ms = new double[_parallel_gc_threads]; - _par_last_update_rs_processed_buffers = new double[_parallel_gc_threads]; - - _par_last_scan_rs_times_ms = new double[_parallel_gc_threads]; - - _par_last_obj_copy_times_ms = new double[_parallel_gc_threads]; + _phase_times = new G1GCPhaseTimes(_parallel_gc_threads); - _par_last_termination_times_ms = new double[_parallel_gc_threads]; - _par_last_termination_attempts = new double[_parallel_gc_threads]; - _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads]; - _par_last_gc_worker_times_ms = new double[_parallel_gc_threads]; - _par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads]; - - int index; - if (ParallelGCThreads == 0) - index = 0; - else if (ParallelGCThreads > 8) - index = 7; - else - index = ParallelGCThreads - 1; + int index = MIN2(_parallel_gc_threads - 1, 7); _pending_card_diff_seq->add(0.0); _rs_length_diff_seq->add(rs_length_diff_defaults[index]); @@ -824,7 +739,7 @@ #endif // PRODUCT void G1CollectorPolicy::record_full_collection_start() { - _cur_collection_start_sec = os::elapsedTime(); + _full_collection_start_sec = os::elapsedTime(); // Release the future to-space so that it is available for compaction into. _g1->set_full_collection(); } @@ -833,7 +748,7 @@ // Consider this like a collection pause for the purposes of allocation // since last pause. double end_sec = os::elapsedTime(); - double full_gc_time_sec = end_sec - _cur_collection_start_sec; + double full_gc_time_sec = end_sec - _full_collection_start_sec; double full_gc_time_ms = full_gc_time_sec * 1000.0; _trace_gen1_time_data.record_full_collection(full_gc_time_ms); @@ -869,12 +784,6 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, size_t start_used) { - if (G1Log::finer()) { - gclog_or_tty->stamp(PrintGCTimeStamps); - gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause()) - .append(gcs_are_young() ? " (young)" : " (mixed)")); - } - // We only need to do this here as the policy will only be applied // to the GC we're about to start. so, no point is calculating this // every time we calculate / recalculate the target young length. @@ -888,7 +797,7 @@ _trace_gen0_time_data.record_start_collection(s_w_t_ms); _stop_world_start = 0.0; - _cur_collection_start_sec = start_time_sec; + phase_times()->_cur_collection_start_sec = start_time_sec; _cur_collection_pause_used_at_start_bytes = start_used; _cur_collection_pause_used_regions_at_start = _g1->used_regions(); _pending_cards = _g1->pending_card_num(); @@ -902,30 +811,6 @@ _survivor_bytes_before_gc = young_list->survivor_used_bytes(); _capacity_before_gc = _g1->capacity(); -#ifdef DEBUG - // initialise these to something well known so that we can spot - // if they are not set properly - - for (int i = 0; i < _parallel_gc_threads; ++i) { - _par_last_gc_worker_start_times_ms[i] = -1234.0; - _par_last_ext_root_scan_times_ms[i] = -1234.0; - _par_last_satb_filtering_times_ms[i] = -1234.0; - _par_last_update_rs_times_ms[i] = -1234.0; - _par_last_update_rs_processed_buffers[i] = -1234.0; - _par_last_scan_rs_times_ms[i] = -1234.0; - _par_last_obj_copy_times_ms[i] = -1234.0; - _par_last_termination_times_ms[i] = -1234.0; - _par_last_termination_attempts[i] = -1234.0; - _par_last_gc_worker_end_times_ms[i] = -1234.0; - _par_last_gc_worker_times_ms[i] = -1234.0; - _par_last_gc_worker_other_times_ms[i] = -1234.0; - } -#endif - - // This is initialized to zero here and is set during the evacuation - // pause if we actually waited for the root region scanning to finish. - _root_region_scan_wait_time_ms = 0.0; - _last_gc_was_young = false; // do that for any other surv rate groups @@ -974,127 +859,6 @@ } } -void G1CollectorPolicy::record_concurrent_pause_end() { -} - -template<class T> -T sum_of(T* sum_arr, int start, int n, int N) { - T sum = (T)0; - for (int i = 0; i < n; i++) { - int j = (start + i) % N; - sum += sum_arr[j]; - } - return sum; -} - -void G1CollectorPolicy::print_par_stats(int level, - const char* str, - double* data, - bool showDecimals) { - double min = data[0], max = data[0]; - double total = 0.0; - LineBuffer buf(level); - buf.append("[%s (ms):", str); - for (uint i = 0; i < no_of_gc_threads(); ++i) { - double val = data[i]; - if (val < min) - min = val; - if (val > max) - max = val; - total += val; - if (G1Log::finest()) { - if (showDecimals) { - buf.append(" %.1lf", val); - } else { - buf.append(" %d", (int)val); - } - } - } - - if (G1Log::finest()) { - buf.append_and_print_cr(""); - } - double avg = total / (double) no_of_gc_threads(); - if (showDecimals) { - buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]", - min, avg, max, max - min, total); - } else { - buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]", - (int)min, (int)avg, (int)max, (int)max - (int)min, (int)total); - } -} - -void G1CollectorPolicy::print_stats(int level, - const char* str, - double value) { - LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value); -} - -void G1CollectorPolicy::print_stats(int level, - const char* str, - double value, - int workers) { - LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers); -} - -void G1CollectorPolicy::print_stats(int level, - const char* str, - int value) { - LineBuffer(level).append_and_print_cr("[%s: %d]", str, value); -} - -double G1CollectorPolicy::avg_value(double* data) { - if (G1CollectedHeap::use_parallel_gc_threads()) { - double ret = 0.0; - for (uint i = 0; i < no_of_gc_threads(); ++i) { - ret += data[i]; - } - return ret / (double) no_of_gc_threads(); - } else { - return data[0]; - } -} - -double G1CollectorPolicy::max_value(double* data) { - if (G1CollectedHeap::use_parallel_gc_threads()) { - double ret = data[0]; - for (uint i = 1; i < no_of_gc_threads(); ++i) { - if (data[i] > ret) { - ret = data[i]; - } - } - return ret; - } else { - return data[0]; - } -} - -double G1CollectorPolicy::sum_of_values(double* data) { - if (G1CollectedHeap::use_parallel_gc_threads()) { - double sum = 0.0; - for (uint i = 0; i < no_of_gc_threads(); i++) { - sum += data[i]; - } - return sum; - } else { - return data[0]; - } -} - -double G1CollectorPolicy::max_sum(double* data1, double* data2) { - double ret = data1[0] + data2[0]; - - if (G1CollectedHeap::use_parallel_gc_threads()) { - for (uint i = 1; i < no_of_gc_threads(); ++i) { - double data = data1[i] + data2[i]; - if (data > ret) { - ret = data; - } - } - } - return ret; -} - bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) { if (_g1->concurrent_mark()->cmThread()->during_cycle()) { return false; @@ -1142,10 +906,8 @@ // Anything below that is considered to be zero #define MIN_TIMER_GRANULARITY 0.0000001 -void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { +void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) { double end_time_sec = os::elapsedTime(); - double elapsed_ms = _last_pause_time_ms; - bool parallel = G1CollectedHeap::use_parallel_gc_threads(); assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(), "otherwise, the subtraction below does not make sense"); size_t rs_size = @@ -1154,7 +916,6 @@ assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); bool last_pause_included_initial_mark = false; bool update_stats = !_g1->evacuation_failed(); - set_no_of_gc_threads(no_of_gc_threads); #ifndef PRODUCT if (G1YoungSurvRateVerbose) { @@ -1174,7 +935,7 @@ set_initiate_conc_mark_if_possible(); } - _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0, + _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0, end_time_sec, false); size_t freed_bytes = @@ -1185,58 +946,11 @@ (double)surviving_bytes/ (double)_collection_set_bytes_used_before; - // These values are used to update the summary information that is - // displayed when TraceGen0Time is enabled, and are output as part - // of the "finer" output, in the non-parallel case. - - double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms); - double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms); - double update_rs_time = avg_value(_par_last_update_rs_times_ms); - double update_rs_processed_buffers = - sum_of_values(_par_last_update_rs_processed_buffers); - double scan_rs_time = avg_value(_par_last_scan_rs_times_ms); - double obj_copy_time = avg_value(_par_last_obj_copy_times_ms); - double termination_time = avg_value(_par_last_termination_times_ms); - - double known_time = ext_root_scan_time + - satb_filtering_time + - update_rs_time + - scan_rs_time + - obj_copy_time; - - double other_time_ms = elapsed_ms; - - // Subtract the root region scanning wait time. It's initialized to - // zero at the start of the pause. - other_time_ms -= _root_region_scan_wait_time_ms; - - if (parallel) { - other_time_ms -= _cur_collection_par_time_ms; - } else { - other_time_ms -= known_time; - } - - // Now subtract the time taken to fix up roots in generated code - other_time_ms -= _cur_collection_code_root_fixup_time_ms; - - // Subtract the time taken to clean the card table from the - // current value of "other time" - other_time_ms -= _cur_clear_ct_time_ms; - - // TraceGen0Time and TraceGen1Time summary info updating. - if (update_stats) { - double parallel_known_time = known_time + termination_time; - double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time; - - _trace_gen0_time_data.record_end_collection( - elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms, - ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time, - termination_time, parallel_other_time, _cur_clear_ct_time_ms); - + _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times()); // this is where we update the allocation rate of the application double app_time_ms = - (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms); + (phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms); if (app_time_ms < MIN_TIMER_GRANULARITY) { // This usually happens due to the timer not having the required // granularity. Some Linuxes are the usual culprits. @@ -1257,7 +971,7 @@ double interval_ms = (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0; - update_recent_gc_times(end_time_sec, elapsed_ms); + update_recent_gc_times(end_time_sec, pause_time_ms); _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms; if (recent_avg_pause_time_ratio() < 0.0 || (recent_avg_pause_time_ratio() - 1.0 > 0.0)) { @@ -1284,90 +998,6 @@ } } } - - if (G1Log::finer()) { - bool print_marking_info = - _g1->mark_in_progress() && !last_pause_included_initial_mark; - - gclog_or_tty->print_cr("%s, %1.8lf secs]", - (last_pause_included_initial_mark) ? " (initial-mark)" : "", - elapsed_ms / 1000.0); - - if (_root_region_scan_wait_time_ms > 0.0) { - print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); - } - if (parallel) { - print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads); - print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms); - print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); - if (print_marking_info) { - print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms); - } - print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); - if (G1Log::finest()) { - print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers, - false /* showDecimals */); - } - print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); - print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms); - print_par_stats(2, "Termination", _par_last_termination_times_ms); - if (G1Log::finest()) { - print_par_stats(3, "Termination Attempts", _par_last_termination_attempts, - false /* showDecimals */); - } - - for (int i = 0; i < _parallel_gc_threads; i++) { - _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - - _par_last_gc_worker_start_times_ms[i]; - - double worker_known_time = _par_last_ext_root_scan_times_ms[i] + - _par_last_satb_filtering_times_ms[i] + - _par_last_update_rs_times_ms[i] + - _par_last_scan_rs_times_ms[i] + - _par_last_obj_copy_times_ms[i] + - _par_last_termination_times_ms[i]; - - _par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] - - worker_known_time; - } - - print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms); - print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms); - print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms); - } else { - print_stats(1, "Ext Root Scanning", ext_root_scan_time); - if (print_marking_info) { - print_stats(1, "SATB Filtering", satb_filtering_time); - } - print_stats(1, "Update RS", update_rs_time); - if (G1Log::finest()) { - print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers); - } - print_stats(1, "Scan RS", scan_rs_time); - print_stats(1, "Object Copying", obj_copy_time); - } - print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); - print_stats(1, "Clear CT", _cur_clear_ct_time_ms); -#ifndef PRODUCT - print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms); - print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms); - print_stats(1, "Min Clear CC", _min_clear_cc_time_ms); - print_stats(1, "Max Clear CC", _max_clear_cc_time_ms); - if (_num_cc_clears > 0) { - print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears)); - } -#endif - print_stats(1, "Other", other_time_ms); - print_stats(2, "Choose CSet", - (_recorded_young_cset_choice_time_ms + - _recorded_non_young_cset_choice_time_ms)); - print_stats(2, "Ref Proc", _cur_ref_proc_time_ms); - print_stats(2, "Ref Enq", _cur_ref_enq_time_ms); - print_stats(2, "Free CSet", - (_recorded_young_free_cset_time_ms + - _recorded_non_young_free_cset_time_ms)); - } - bool new_in_marking_window = _in_marking_window; bool new_in_marking_window_im = false; if (during_initial_mark_pause()) { @@ -1406,8 +1036,6 @@ // do that for any other surv rate groupsx if (update_stats) { - double pause_time_ms = elapsed_ms; - size_t diff = 0; if (_max_pending_cards >= _pending_cards) { diff = _max_pending_cards - _pending_cards; @@ -1416,7 +1044,7 @@ double cost_per_card_ms = 0.0; if (_pending_cards > 0) { - cost_per_card_ms = update_rs_time / (double) _pending_cards; + cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards; _cost_per_card_ms_seq->add(cost_per_card_ms); } @@ -1424,7 +1052,7 @@ double cost_per_entry_ms = 0.0; if (cards_scanned > 10) { - cost_per_entry_ms = scan_rs_time / (double) cards_scanned; + cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned; if (_last_gc_was_young) { _cost_per_entry_ms_seq->add(cost_per_entry_ms); } else { @@ -1464,7 +1092,7 @@ size_t copied_bytes = surviving_bytes; double cost_per_byte_ms = 0.0; if (copied_bytes > 0) { - cost_per_byte_ms = obj_copy_time / (double) copied_bytes; + cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes; if (_in_marking_window) { _cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms); } else { @@ -1473,21 +1101,21 @@ } double all_other_time_ms = pause_time_ms - - (update_rs_time + scan_rs_time + obj_copy_time + termination_time); + (phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time); double young_other_time_ms = 0.0; if (young_cset_region_length() > 0) { young_other_time_ms = - _recorded_young_cset_choice_time_ms + - _recorded_young_free_cset_time_ms; + phase_times()->_recorded_young_cset_choice_time_ms + + phase_times()->_recorded_young_free_cset_time_ms; _young_other_cost_per_region_ms_seq->add(young_other_time_ms / (double) young_cset_region_length()); } double non_young_other_time_ms = 0.0; if (old_cset_region_length() > 0) { non_young_other_time_ms = - _recorded_non_young_cset_choice_time_ms + - _recorded_non_young_free_cset_time_ms; + phase_times()->_recorded_non_young_cset_choice_time_ms + + phase_times()->_recorded_non_young_free_cset_time_ms; _non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms / (double) old_cset_region_length()); @@ -1514,7 +1142,7 @@ // Note that _mmu_tracker->max_gc_time() returns the time in seconds. double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0; - adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms); + adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms); _collectionSetChooser->verify(); } @@ -2323,7 +1951,7 @@ set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths); double young_end_time_sec = os::elapsedTime(); - _recorded_young_cset_choice_time_ms = + phase_times()->_recorded_young_cset_choice_time_ms = (young_end_time_sec - young_start_time_sec) * 1000.0; // We are doing young collections so reset this. @@ -2439,7 +2067,7 @@ predicted_pause_time_ms, target_pause_time_ms); double non_young_end_time_sec = os::elapsedTime(); - _recorded_non_young_cset_choice_time_ms = + phase_times()->_recorded_non_young_cset_choice_time_ms = (non_young_end_time_sec - non_young_start_time_sec) * 1000.0; } @@ -2455,33 +2083,29 @@ } } -void TraceGen0TimeData::record_end_collection( - double total_ms, - double other_ms, - double root_region_scan_wait_ms, - double parallel_ms, - double ext_root_scan_ms, - double satb_filtering_ms, - double update_rs_ms, - double scan_rs_ms, - double obj_copy_ms, - double termination_ms, - double parallel_other_ms, - double clear_ct_ms) -{ +void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times) { if(TraceGen0Time) { - _total.add(total_ms); - _other.add(other_ms); - _root_region_scan_wait.add(root_region_scan_wait_ms); - _parallel.add(parallel_ms); - _ext_root_scan.add(ext_root_scan_ms); - _satb_filtering.add(satb_filtering_ms); - _update_rs.add(update_rs_ms); - _scan_rs.add(scan_rs_ms); - _obj_copy.add(obj_copy_ms); - _termination.add(termination_ms); - _parallel_other.add(parallel_other_ms); - _clear_ct.add(clear_ct_ms); + _total.add(pause_time_ms); + _other.add(pause_time_ms - phase_times->accounted_time_ms()); + _root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms); + _parallel.add(phase_times->_cur_collection_par_time_ms); + _ext_root_scan.add(phase_times->_ext_root_scan_time); + _satb_filtering.add(phase_times->_satb_filtering_time); + _update_rs.add(phase_times->_update_rs_time); + _scan_rs.add(phase_times->_scan_rs_time); + _obj_copy.add(phase_times->_obj_copy_time); + _termination.add(phase_times->_termination_time); + + double parallel_known_time = phase_times->_ext_root_scan_time + + phase_times->_satb_filtering_time + + phase_times->_update_rs_time + + phase_times->_scan_rs_time + + phase_times->_obj_copy_time + + + phase_times->_termination_time; + + double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time; + _parallel_other.add(parallel_other_time); + _clear_ct.add(phase_times->_cur_clear_ct_time_ms); } } @@ -2497,20 +2121,18 @@ } } -void TraceGen0TimeData::print_summary(int level, - const char* str, +void TraceGen0TimeData::print_summary(const char* str, const NumberSeq* seq) const { double sum = seq->sum(); - LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", + gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)", str, sum / 1000.0, seq->avg()); } -void TraceGen0TimeData::print_summary_sd(int level, - const char* str, +void TraceGen0TimeData::print_summary_sd(const char* str, const NumberSeq* seq) const { - print_summary(level, str, seq); - LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", - seq->num(), seq->sd(), seq->maximum()); + print_summary(str, seq); + gclog_or_tty->print_cr("%+45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", + "(num", seq->num(), seq->sd(), seq->maximum()); } void TraceGen0TimeData::print() const { @@ -2519,7 +2141,7 @@ } gclog_or_tty->print_cr("ALL PAUSES"); - print_summary_sd(0, "Total", &_total); + print_summary_sd(" Total", &_total); gclog_or_tty->print_cr(""); gclog_or_tty->print_cr(""); gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num); @@ -2531,24 +2153,24 @@ if (_young_pause_num == 0 && _mixed_pause_num == 0) { gclog_or_tty->print_cr("none"); } else { - print_summary_sd(0, "Evacuation Pauses", &_total); - print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait); - print_summary(1, "Parallel Time", &_parallel); - print_summary(2, "Ext Root Scanning", &_ext_root_scan); - print_summary(2, "SATB Filtering", &_satb_filtering); - print_summary(2, "Update RS", &_update_rs); - print_summary(2, "Scan RS", &_scan_rs); - print_summary(2, "Object Copy", &_obj_copy); - print_summary(2, "Termination", &_termination); - print_summary(2, "Parallel Other", &_parallel_other); - print_summary(1, "Clear CT", &_clear_ct); - print_summary(1, "Other", &_other); + print_summary_sd(" Evacuation Pauses", &_total); + print_summary(" Root Region Scan Wait", &_root_region_scan_wait); + print_summary(" Parallel Time", &_parallel); + print_summary(" Ext Root Scanning", &_ext_root_scan); + print_summary(" SATB Filtering", &_satb_filtering); + print_summary(" Update RS", &_update_rs); + print_summary(" Scan RS", &_scan_rs); + print_summary(" Object Copy", &_obj_copy); + print_summary(" Termination", &_termination); + print_summary(" Parallel Other", &_parallel_other); + print_summary(" Clear CT", &_clear_ct); + print_summary(" Other", &_other); } gclog_or_tty->print_cr(""); gclog_or_tty->print_cr("MISC"); - print_summary_sd(0, "Stop World", &_all_stop_world_times_ms); - print_summary_sd(0, "Yields", &_all_yield_times_ms); + print_summary_sd(" Stop World", &_all_stop_world_times_ms); + print_summary_sd(" Yields", &_all_yield_times_ms); } void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {