6898948: G1: forensic instrumentation for out-of-bounds recent_avg_pause_time_ratio()

Fri, 13 Nov 2009 11:55:26 -0800

author
ysr
date
Fri, 13 Nov 2009 11:55:26 -0800
changeset 1521
89f1b9ae8991
parent 1520
0e2d7ae2bc67
child 1522
23b9a8d315fc

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

src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp file | annotate | diff | comparison | revisions
src/share/vm/utilities/numberSeq.cpp file | annotate | diff | comparison | revisions
src/share/vm/utilities/numberSeq.hpp file | annotate | diff | comparison | revisions
     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  };

mercurial