Fri, 13 Nov 2009 11:55:26 -0800
6898948: G1: forensic instrumentation for out-of-bounds recent_avg_pause_time_ratio()
Summary: Added instrumentation and (temporary) assert in non-product mode; clipped the value when found out-of-bounds in product mode. Fix of original issue will follow collection of data from this instrumentation.
Reviewed-by: jcoomes, tonyp
1.1 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Tue Nov 10 11:32:48 2009 -0800 1.2 +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Fri Nov 13 11:55:26 2009 -0800 1.3 @@ -1516,8 +1516,31 @@ 1.4 (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0; 1.5 update_recent_gc_times(end_time_sec, elapsed_ms); 1.6 _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms; 1.7 - // using 1.01 to account for floating point inaccuracies 1.8 - assert(recent_avg_pause_time_ratio() < 1.01, "All GC?"); 1.9 + if (recent_avg_pause_time_ratio() < 0.0 || 1.10 + (recent_avg_pause_time_ratio() - 1.0 > 0.0)) { 1.11 +#ifndef PRODUCT 1.12 + // Dump info to allow post-facto debugging 1.13 + gclog_or_tty->print_cr("recent_avg_pause_time_ratio() out of bounds"); 1.14 + gclog_or_tty->print_cr("-------------------------------------------"); 1.15 + gclog_or_tty->print_cr("Recent GC Times (ms):"); 1.16 + _recent_gc_times_ms->dump(); 1.17 + gclog_or_tty->print_cr("(End Time=%3.3f) Recent GC End Times (s):", end_time_sec); 1.18 + _recent_prev_end_times_for_all_gcs_sec->dump(); 1.19 + gclog_or_tty->print_cr("GC = %3.3f, Interval = %3.3f, Ratio = %3.3f", 1.20 + _recent_gc_times_ms->sum(), interval_ms, recent_avg_pause_time_ratio()); 1.21 + // TEMPORARY: In debug mode, terminate the JVM, so nightly testing explicitly 1.22 + // flags the sighting by failing the test. 1.23 + assert(false, "Debugging data for CR 6898948 has been dumped above"); 1.24 +#else // PRODUCT 1.25 + // Clip ratio between 0.0 and 1.0 1.26 + if (_recent_avg_pause_time_ratio < 0.0) { 1.27 + _recent_avg_pause_time_ratio = 0.0; 1.28 + } else { 1.29 + assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant"); 1.30 + _recent_avg_pause_time_ratio = 1.0; 1.31 + } 1.32 +#endif // PRODUCT 1.33 + } 1.34 } 1.35 1.36 if (G1PolicyVerbose > 1) {
2.1 --- a/src/share/vm/utilities/numberSeq.cpp Tue Nov 10 11:32:48 2009 -0800 2.2 +++ b/src/share/vm/utilities/numberSeq.cpp Fri Nov 13 11:55:26 2009 -0800 2.3 @@ -241,3 +241,33 @@ 2.4 2.5 return b0 + b1 * num; 2.6 } 2.7 + 2.8 + 2.9 +// Printing/Debugging Support 2.10 + 2.11 +void AbsSeq::dump() { dump_on(gclog_or_tty); } 2.12 + 2.13 +void AbsSeq::dump_on(outputStream* s) { 2.14 + s->print_cr("\t _num = %d, _sum = %7.3f, _sum_of_squares = %7.3f", 2.15 + _num, _sum, _sum_of_squares); 2.16 + s->print_cr("\t _davg = %7.3f, _dvariance = %7.3f, _alpha = %7.3f", 2.17 + _davg, _dvariance, _alpha); 2.18 +} 2.19 + 2.20 +void NumberSeq::dump_on(outputStream* s) { 2.21 + AbsSeq::dump_on(s); 2.22 + s->print_cr("\t\t _last = %7.3f, _maximum = %7.3f"); 2.23 +} 2.24 + 2.25 +void TruncatedSeq::dump_on(outputStream* s) { 2.26 + AbsSeq::dump_on(s); 2.27 + s->print_cr("\t\t _length = %d, _next = %d", _length, _next); 2.28 + for (int i = 0; i < _length; i++) { 2.29 + if (i%5 == 0) { 2.30 + s->cr(); 2.31 + s->print("\t"); 2.32 + } 2.33 + s->print("\t[%d]=%7.3f", i, _sequence[i]); 2.34 + } 2.35 + s->print_cr(""); 2.36 +}
3.1 --- a/src/share/vm/utilities/numberSeq.hpp Tue Nov 10 11:32:48 2009 -0800 3.2 +++ b/src/share/vm/utilities/numberSeq.hpp Fri Nov 13 11:55:26 2009 -0800 3.3 @@ -74,6 +74,10 @@ 3.4 double davg() const; // decaying average 3.5 double dvariance() const; // decaying variance 3.6 double dsd() const; // decaying "standard deviation" 3.7 + 3.8 + // Debugging/Printing 3.9 + virtual void dump(); 3.10 + virtual void dump_on(outputStream* s); 3.11 }; 3.12 3.13 class NumberSeq: public AbsSeq { 3.14 @@ -91,6 +95,9 @@ 3.15 virtual void add(double val); 3.16 virtual double maximum() const { return _maximum; } 3.17 virtual double last() const { return _last; } 3.18 + 3.19 + // Debugging/Printing 3.20 + virtual void dump_on(outputStream* s); 3.21 }; 3.22 3.23 class TruncatedSeq: public AbsSeq { 3.24 @@ -114,4 +121,7 @@ 3.25 3.26 double oldest() const; // the oldest valid value in the sequence 3.27 double predict_next() const; // prediction based on linear regression 3.28 + 3.29 + // Debugging/Printing 3.30 + virtual void dump_on(outputStream* s); 3.31 };