--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Thu Oct 20 12:06:20 2011 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Sun Oct 23 23:06:06 2011 -0700
@@ -320,6 +320,7 @@
_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];
// start conservatively
_expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis;
@@ -976,6 +977,7 @@
_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
@@ -984,8 +986,10 @@
_cur_aux_times_set[i] = false;
}
- _satb_drain_time_set = false;
- _last_satb_drain_processed_buffers = -1;
+ // These are initialized to zero here and they are set during
+ // the evacuation pause if marking is in progress.
+ _cur_satb_drain_time_ms = 0.0;
+ _last_satb_drain_processed_buffers = 0;
_last_young_gc_full = false;
@@ -1097,61 +1101,65 @@
(int)total, (int)avg, (int)min, (int)max, (int)max - (int)min);
}
-void G1CollectorPolicy::print_stats (int level,
- const char* str,
- double value) {
+void G1CollectorPolicy::print_stats(int level,
+ const char* str,
+ double value) {
LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value);
}
-void G1CollectorPolicy::print_stats (int level,
- const char* str,
- int value) {
+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) {
+double G1CollectorPolicy::avg_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = 0.0;
- for (uint i = 0; i < ParallelGCThreads; ++i)
+ for (uint i = 0; i < ParallelGCThreads; ++i) {
ret += data[i];
+ }
return ret / (double) ParallelGCThreads;
} else {
return data[0];
}
}
-double G1CollectorPolicy::max_value (double* data) {
+double G1CollectorPolicy::max_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = data[0];
- for (uint i = 1; i < ParallelGCThreads; ++i)
- if (data[i] > ret)
+ for (uint i = 1; i < ParallelGCThreads; ++i) {
+ if (data[i] > ret) {
ret = data[i];
+ }
+ }
return ret;
} else {
return data[0];
}
}
-double G1CollectorPolicy::sum_of_values (double* data) {
+double G1CollectorPolicy::sum_of_values(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double sum = 0.0;
- for (uint i = 0; i < ParallelGCThreads; i++)
+ for (uint i = 0; i < ParallelGCThreads; i++) {
sum += data[i];
+ }
return sum;
} else {
return data[0];
}
}
-double G1CollectorPolicy::max_sum (double* data1,
- double* data2) {
+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 < ParallelGCThreads; ++i) {
double data = data1[i] + data2[i];
- if (data > ret)
+ if (data > ret) {
ret = data;
+ }
}
}
return ret;
@@ -1251,6 +1259,10 @@
_n_pauses++;
+ // These values are used to update the summary information that is
+ // displayed when TraceGen0Time is enabled, and are output as part
+ // of the PrintGCDetails output, in the non-parallel case.
+
double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
double mark_stack_scan_time = avg_value(_par_last_mark_stack_scan_times_ms);
double update_rs_time = avg_value(_par_last_update_rs_times_ms);
@@ -1260,42 +1272,68 @@
double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
double termination_time = avg_value(_par_last_termination_times_ms);
- double parallel_known_time = update_rs_time +
- ext_root_scan_time +
- mark_stack_scan_time +
- scan_rs_time +
- obj_copy_time +
- termination_time;
-
- double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
-
- PauseSummary* summary = _summary;
+ double known_time = ext_root_scan_time +
+ mark_stack_scan_time +
+ update_rs_time +
+ scan_rs_time +
+ obj_copy_time;
+
+ double other_time_ms = elapsed_ms;
+
+ // Subtract the SATB drain time. It's initialized to zero at the
+ // start of the pause and is updated during the pause if marking
+ // is in progress.
+ other_time_ms -= _cur_satb_drain_time_ms;
+
+ if (parallel) {
+ other_time_ms -= _cur_collection_par_time_ms;
+ } else {
+ other_time_ms -= known_time;
+ }
+
+ // 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.
+ _all_pause_times_ms->add(elapsed_ms);
if (update_stats) {
_recent_rs_scan_times_ms->add(scan_rs_time);
_recent_pause_times_ms->add(elapsed_ms);
_recent_rs_sizes->add(rs_size);
- MainBodySummary* body_summary = summary->main_body_summary();
- guarantee(body_summary != NULL, "should not be null!");
-
- if (_satb_drain_time_set)
- body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms);
- else
- body_summary->record_satb_drain_time_ms(0.0);
+ _summary->record_total_time_ms(elapsed_ms);
+ _summary->record_other_time_ms(other_time_ms);
+
+ MainBodySummary* body_summary = _summary->main_body_summary();
+ assert(body_summary != NULL, "should not be null!");
+
+ // This will be non-zero iff marking is currently in progress (i.e.
+ // _g1->mark_in_progress() == true) and the currrent pause was not
+ // an initial mark pause. Since the body_summary items are NumberSeqs,
+ // however, they have to be consistent and updated in lock-step with
+ // each other. Therefore we unconditionally record the SATB drain
+ // time - even if it's zero.
+ body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms);
body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
body_summary->record_mark_stack_scan_time_ms(mark_stack_scan_time);
body_summary->record_update_rs_time_ms(update_rs_time);
body_summary->record_scan_rs_time_ms(scan_rs_time);
body_summary->record_obj_copy_time_ms(obj_copy_time);
+
if (parallel) {
body_summary->record_parallel_time_ms(_cur_collection_par_time_ms);
- body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
body_summary->record_termination_time_ms(termination_time);
+
+ double parallel_known_time = known_time + termination_time;
+ double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
body_summary->record_parallel_other_time_ms(parallel_other_time);
}
+
body_summary->record_mark_closure_time_ms(_mark_closure_time_ms);
+ body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
// We exempt parallel collection from this check because Alloc Buffer
// fragmentation can produce negative collections. Same with evac
@@ -1307,6 +1345,7 @@
|| _g1->evacuation_failed()
|| surviving_bytes <= _collection_set_bytes_used_before,
"Or else negative collection!");
+
_recent_CS_bytes_used_before->add(_collection_set_bytes_used_before);
_recent_CS_bytes_surviving->add(surviving_bytes);
@@ -1357,6 +1396,13 @@
}
}
+ for (int i = 0; i < _aux_num; ++i) {
+ if (_cur_aux_times_set[i]) {
+ _all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
+ }
+ }
+
+
if (G1PolicyVerbose > 1) {
gclog_or_tty->print_cr(" Recording collection pause(%d)", _n_pauses);
}
@@ -1383,61 +1429,60 @@
recent_avg_pause_time_ratio() * 100.0);
}
- double other_time_ms = elapsed_ms;
-
- if (_satb_drain_time_set) {
- other_time_ms -= _cur_satb_drain_time_ms;
- }
-
- if (parallel) {
- other_time_ms -= _cur_collection_par_time_ms + _cur_clear_ct_time_ms;
- } else {
- other_time_ms -=
- update_rs_time +
- ext_root_scan_time + mark_stack_scan_time +
- scan_rs_time + obj_copy_time;
- }
-
+ // PrintGCDetails output
if (PrintGCDetails) {
+ 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 (_satb_drain_time_set) {
+ if (print_marking_info) {
print_stats(1, "SATB Drain Time", _cur_satb_drain_time_ms);
- }
- if (_last_satb_drain_processed_buffers >= 0) {
print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers);
}
+
if (parallel) {
print_stats(1, "Parallel Time", _cur_collection_par_time_ms);
- print_par_stats(2, "GC Worker Start Time", _par_last_gc_worker_start_times_ms);
+ 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, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms);
+ }
print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers);
- print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
- print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms);
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);
print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts);
- print_par_stats(2, "GC Worker End Time", _par_last_gc_worker_end_times_ms);
+ print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
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_mark_stack_scan_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] = _cur_collection_par_time_ms - worker_known_time;
}
- print_par_stats(2, "GC Worker Times", _par_last_gc_worker_times_ms);
-
- print_stats(2, "Parallel Other", parallel_other_time);
- print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
+ print_par_stats(2, "GC Worker", _par_last_gc_worker_times_ms);
+ print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
} else {
+ print_stats(1, "Ext Root Scanning", ext_root_scan_time);
+ if (print_marking_info) {
+ print_stats(1, "Mark Stack Scanning", mark_stack_scan_time);
+ }
print_stats(1, "Update RS", update_rs_time);
- print_stats(2, "Processed Buffers",
- (int)update_rs_processed_buffers);
- print_stats(1, "Ext Root Scanning", ext_root_scan_time);
- print_stats(1, "Mark Stack Scanning", mark_stack_scan_time);
+ 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, "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);
@@ -1461,16 +1506,6 @@
}
}
- _all_pause_times_ms->add(elapsed_ms);
- if (update_stats) {
- summary->record_total_time_ms(elapsed_ms);
- summary->record_other_time_ms(other_time_ms);
- }
- for (int i = 0; i < _aux_num; ++i)
- if (_cur_aux_times_set[i]) {
- _all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
- }
-
// Update the efficiency-since-mark vars.
double proc_ms = elapsed_ms * (double) _parallel_gc_threads;
if (elapsed_ms < MIN_TIMER_GRANULARITY) {
@@ -2138,17 +2173,17 @@
_g1->collection_set_iterate(&cs_closure);
}
-void G1CollectorPolicy::print_summary (int level,
- const char* str,
- NumberSeq* seq) const {
+void G1CollectorPolicy::print_summary(int level,
+ const char* str,
+ NumberSeq* seq) const {
double sum = seq->sum();
LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
str, sum / 1000.0, seq->avg());
}
-void G1CollectorPolicy::print_summary_sd (int level,
- const char* str,
- NumberSeq* seq) const {
+void G1CollectorPolicy::print_summary_sd(int level,
+ const char* str,
+ 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());
@@ -2211,20 +2246,18 @@
print_summary(1, "SATB Drain", body_summary->get_satb_drain_seq());
if (parallel) {
print_summary(1, "Parallel Time", body_summary->get_parallel_seq());
+ print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
+ print_summary(2, "Mark Stack Scanning", body_summary->get_mark_stack_scan_seq());
print_summary(2, "Update RS", body_summary->get_update_rs_seq());
- print_summary(2, "Ext Root Scanning",
- body_summary->get_ext_root_scan_seq());
- print_summary(2, "Mark Stack Scanning",
- body_summary->get_mark_stack_scan_seq());
print_summary(2, "Scan RS", body_summary->get_scan_rs_seq());
print_summary(2, "Object Copy", body_summary->get_obj_copy_seq());
print_summary(2, "Termination", body_summary->get_termination_seq());
- print_summary(2, "Other", body_summary->get_parallel_other_seq());
+ print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
{
NumberSeq* other_parts[] = {
- body_summary->get_update_rs_seq(),
body_summary->get_ext_root_scan_seq(),
body_summary->get_mark_stack_scan_seq(),
+ body_summary->get_update_rs_seq(),
body_summary->get_scan_rs_seq(),
body_summary->get_obj_copy_seq(),
body_summary->get_termination_seq()
@@ -2234,18 +2267,16 @@
check_other_times(2, body_summary->get_parallel_other_seq(),
&calc_other_times_ms);
}
- print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq());
- print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
} else {
+ print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
+ print_summary(1, "Mark Stack Scanning", body_summary->get_mark_stack_scan_seq());
print_summary(1, "Update RS", body_summary->get_update_rs_seq());
- print_summary(1, "Ext Root Scanning",
- body_summary->get_ext_root_scan_seq());
- print_summary(1, "Mark Stack Scanning",
- body_summary->get_mark_stack_scan_seq());
print_summary(1, "Scan RS", body_summary->get_scan_rs_seq());
print_summary(1, "Object Copy", body_summary->get_obj_copy_seq());
}
}
+ print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq());
+ print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
print_summary(1, "Other", summary->get_other_seq());
{
if (body_summary != NULL) {