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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Tue Nov 10 11:32:48 2009 -0800
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Fri Nov 13 11:55:26 2009 -0800
@@ -1516,8 +1516,31 @@
(end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0;
update_recent_gc_times(end_time_sec, elapsed_ms);
_recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms;
- // using 1.01 to account for floating point inaccuracies
- assert(recent_avg_pause_time_ratio() < 1.01, "All GC?");
+ if (recent_avg_pause_time_ratio() < 0.0 ||
+ (recent_avg_pause_time_ratio() - 1.0 > 0.0)) {
+#ifndef PRODUCT
+ // Dump info to allow post-facto debugging
+ gclog_or_tty->print_cr("recent_avg_pause_time_ratio() out of bounds");
+ gclog_or_tty->print_cr("-------------------------------------------");
+ gclog_or_tty->print_cr("Recent GC Times (ms):");
+ _recent_gc_times_ms->dump();
+ gclog_or_tty->print_cr("(End Time=%3.3f) Recent GC End Times (s):", end_time_sec);
+ _recent_prev_end_times_for_all_gcs_sec->dump();
+ gclog_or_tty->print_cr("GC = %3.3f, Interval = %3.3f, Ratio = %3.3f",
+ _recent_gc_times_ms->sum(), interval_ms, recent_avg_pause_time_ratio());
+ // TEMPORARY: In debug mode, terminate the JVM, so nightly testing explicitly
+ // flags the sighting by failing the test.
+ assert(false, "Debugging data for CR 6898948 has been dumped above");
+#else // PRODUCT
+ // Clip ratio between 0.0 and 1.0
+ if (_recent_avg_pause_time_ratio < 0.0) {
+ _recent_avg_pause_time_ratio = 0.0;
+ } else {
+ assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant");
+ _recent_avg_pause_time_ratio = 1.0;
+ }
+#endif // PRODUCT
+ }
}
if (G1PolicyVerbose > 1) {
--- a/hotspot/src/share/vm/utilities/numberSeq.cpp Tue Nov 10 11:32:48 2009 -0800
+++ b/hotspot/src/share/vm/utilities/numberSeq.cpp Fri Nov 13 11:55:26 2009 -0800
@@ -241,3 +241,33 @@
return b0 + b1 * num;
}
+
+
+// Printing/Debugging Support
+
+void AbsSeq::dump() { dump_on(gclog_or_tty); }
+
+void AbsSeq::dump_on(outputStream* s) {
+ s->print_cr("\t _num = %d, _sum = %7.3f, _sum_of_squares = %7.3f",
+ _num, _sum, _sum_of_squares);
+ s->print_cr("\t _davg = %7.3f, _dvariance = %7.3f, _alpha = %7.3f",
+ _davg, _dvariance, _alpha);
+}
+
+void NumberSeq::dump_on(outputStream* s) {
+ AbsSeq::dump_on(s);
+ s->print_cr("\t\t _last = %7.3f, _maximum = %7.3f");
+}
+
+void TruncatedSeq::dump_on(outputStream* s) {
+ AbsSeq::dump_on(s);
+ s->print_cr("\t\t _length = %d, _next = %d", _length, _next);
+ for (int i = 0; i < _length; i++) {
+ if (i%5 == 0) {
+ s->cr();
+ s->print("\t");
+ }
+ s->print("\t[%d]=%7.3f", i, _sequence[i]);
+ }
+ s->print_cr("");
+}
--- a/hotspot/src/share/vm/utilities/numberSeq.hpp Tue Nov 10 11:32:48 2009 -0800
+++ b/hotspot/src/share/vm/utilities/numberSeq.hpp Fri Nov 13 11:55:26 2009 -0800
@@ -74,6 +74,10 @@
double davg() const; // decaying average
double dvariance() const; // decaying variance
double dsd() const; // decaying "standard deviation"
+
+ // Debugging/Printing
+ virtual void dump();
+ virtual void dump_on(outputStream* s);
};
class NumberSeq: public AbsSeq {
@@ -91,6 +95,9 @@
virtual void add(double val);
virtual double maximum() const { return _maximum; }
virtual double last() const { return _last; }
+
+ // Debugging/Printing
+ virtual void dump_on(outputStream* s);
};
class TruncatedSeq: public AbsSeq {
@@ -114,4 +121,7 @@
double oldest() const; // the oldest valid value in the sequence
double predict_next() const; // prediction based on linear regression
+
+ // Debugging/Printing
+ virtual void dump_on(outputStream* s);
};