# HG changeset patch # User brutisso # Date 1300885971 -3600 # Node ID 5c0b591e1074712fcb5dcc3b51c95898def8bc42 # Parent c6580380076b7258a7c78c09e1677ee678f334d3 6948149: G1: Imbalance in termination times Summary: Changed default value of WorkStealingYieldsBeforeSleep from 1000 to 5000. Added more information to G1 pause logging. Reviewed-by: jwilhelm, tonyp, jmasa diff -r c6580380076b -r 5c0b591e1074 src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Fri Mar 25 17:39:20 2011 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed Mar 23 14:12:51 2011 +0100 @@ -307,6 +307,7 @@ _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]; // start conservatively _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis; @@ -911,6 +912,7 @@ _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; } #endif @@ -1063,8 +1065,7 @@ void G1CollectorPolicy::print_par_stats(int level, const char* str, - double* data, - bool summary) { + double* data) { double min = data[0], max = data[0]; double total = 0.0; LineBuffer buf(level); @@ -1078,20 +1079,15 @@ total += val; buf.append(" %3.1lf", val); } - if (summary) { - buf.append_and_print_cr(""); - double avg = total / (double) ParallelGCThreads; - buf.append(" "); - buf.append("Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf", - avg, min, max); - } - buf.append_and_print_cr("]"); + buf.append_and_print_cr(""); + double avg = total / (double) ParallelGCThreads; + buf.append_and_print_cr(" Avg: %5.1lf, Min: %5.1lf, Max: %5.1lf, Diff: %5.1lf]", + avg, min, max, max - min); } void G1CollectorPolicy::print_par_sizes(int level, const char* str, - double* data, - bool summary) { + double* data) { double min = data[0], max = data[0]; double total = 0.0; LineBuffer buf(level); @@ -1105,14 +1101,10 @@ total += val; buf.append(" %d", (int) val); } - if (summary) { - buf.append_and_print_cr(""); - double avg = total / (double) ParallelGCThreads; - buf.append(" "); - buf.append("Sum: %d, Avg: %d, Min: %d, Max: %d", - (int)total, (int)avg, (int)min, (int)max); - } - buf.append_and_print_cr("]"); + buf.append_and_print_cr(""); + double avg = total / (double) ParallelGCThreads; + buf.append_and_print_cr(" Sum: %d, Avg: %d, Min: %d, Max: %d, Diff: %d]", + (int)total, (int)avg, (int)min, (int)max, (int)max - (int)min); } void G1CollectorPolicy::print_stats (int level, @@ -1421,22 +1413,22 @@ } 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, false); + print_par_stats(2, "GC Worker Start Time", _par_last_gc_worker_start_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, true); - 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_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, true); - print_par_stats(2, "GC Worker End Time", - _par_last_gc_worker_end_times_ms, false); + 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); + + 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]; + } + print_par_stats(2, "GC Worker Times", _par_last_gc_worker_times_ms); + print_stats(2, "Other", parallel_other_time); print_stats(1, "Clear CT", _cur_clear_ct_time_ms); } else { diff -r c6580380076b -r 5c0b591e1074 src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Fri Mar 25 17:39:20 2011 -0700 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Wed Mar 23 14:12:51 2011 +0100 @@ -182,6 +182,7 @@ double* _par_last_termination_times_ms; double* _par_last_termination_attempts; double* _par_last_gc_worker_end_times_ms; + double* _par_last_gc_worker_times_ms; // indicates that we are in young GC mode bool _in_young_gc_mode; @@ -569,11 +570,8 @@ void print_stats(int level, const char* str, double value); void print_stats(int level, const char* str, int value); - void print_par_stats(int level, const char* str, double* data) { - print_par_stats(level, str, data, true); - } - void print_par_stats(int level, const char* str, double* data, bool summary); - void print_par_sizes(int level, const char* str, double* data, bool summary); + void print_par_stats(int level, const char* str, double* data); + void print_par_sizes(int level, const char* str, double* data); void check_other_times(int level, NumberSeq* other_times_ms, diff -r c6580380076b -r 5c0b591e1074 src/share/vm/runtime/globals.hpp --- a/src/share/vm/runtime/globals.hpp Fri Mar 25 17:39:20 2011 -0700 +++ b/src/share/vm/runtime/globals.hpp Wed Mar 23 14:12:51 2011 +0100 @@ -1924,7 +1924,7 @@ experimental(intx, WorkStealingSleepMillis, 1, \ "Sleep time when sleep is used for yields") \ \ - experimental(uintx, WorkStealingYieldsBeforeSleep, 1000, \ + experimental(uintx, WorkStealingYieldsBeforeSleep, 5000, \ "Number of yields before a sleep is done during workstealing") \ \ experimental(uintx, WorkStealingHardSpins, 4096, \