Fixed quantization and made monotic time reversal not panic

Changed quantization to use monotonic clock readings.

Stopping panicing when monotonic clock readings go backwards because
https://github.com/kubernetes/kubernetes/issues/96459 reported it
happening.

Re-organized sampleAndWaterMarkHistograms::innerSet to `defer` the
Unlock call, because that is the preferred pattern.

Kubernetes-commit: 0809220fd04d26892f0fcfd3bf54cc4baeda22da
This commit is contained in:
Mike Spreitzer 2020-11-12 15:17:07 -05:00 committed by Kubernetes Publisher
parent ecc0608a45
commit 70bbff23ac
1 changed files with 37 additions and 18 deletions

View File

@ -64,13 +64,16 @@ func (spg SampleAndWaterMarkPairGenerator) metrics() Registerables {
// SampleAndWaterMarkObserverGenerator creates TimedObservers that // SampleAndWaterMarkObserverGenerator creates TimedObservers that
// populate histograms of samples and low- and high-water-marks. The // populate histograms of samples and low- and high-water-marks. The
// generator has a samplePeriod, and the histograms get an observation // generator has a samplePeriod, and the histograms get an observation
// every samplePeriod. // every samplePeriod. The sampling windows are quantized based on
// the monotonic rather than wall-clock times. The `t0` field is
// there so to provide a baseline for monotonic clock differences.
type SampleAndWaterMarkObserverGenerator struct { type SampleAndWaterMarkObserverGenerator struct {
*sampleAndWaterMarkObserverGenerator *sampleAndWaterMarkObserverGenerator
} }
type sampleAndWaterMarkObserverGenerator struct { type sampleAndWaterMarkObserverGenerator struct {
clock clock.PassiveClock clock clock.PassiveClock
t0 time.Time
samplePeriod time.Duration samplePeriod time.Duration
samples *compbasemetrics.HistogramVec samples *compbasemetrics.HistogramVec
waterMarks *compbasemetrics.HistogramVec waterMarks *compbasemetrics.HistogramVec
@ -83,6 +86,7 @@ func NewSampleAndWaterMarkHistogramsGenerator(clock clock.PassiveClock, samplePe
return SampleAndWaterMarkObserverGenerator{ return SampleAndWaterMarkObserverGenerator{
&sampleAndWaterMarkObserverGenerator{ &sampleAndWaterMarkObserverGenerator{
clock: clock, clock: clock,
t0: clock.Now(),
samplePeriod: samplePeriod, samplePeriod: samplePeriod,
samples: compbasemetrics.NewHistogramVec(sampleOpts, labelNames), samples: compbasemetrics.NewHistogramVec(sampleOpts, labelNames),
waterMarks: compbasemetrics.NewHistogramVec(waterMarkOpts, append([]string{labelNameMark}, labelNames...)), waterMarks: compbasemetrics.NewHistogramVec(waterMarkOpts, append([]string{labelNameMark}, labelNames...)),
@ -90,7 +94,7 @@ func NewSampleAndWaterMarkHistogramsGenerator(clock clock.PassiveClock, samplePe
} }
func (swg *sampleAndWaterMarkObserverGenerator) quantize(when time.Time) int64 { func (swg *sampleAndWaterMarkObserverGenerator) quantize(when time.Time) int64 {
return when.UnixNano() / int64(swg.samplePeriod) return int64(when.Sub(swg.t0) / swg.samplePeriod)
} }
// Generate makes a new TimedObserver // Generate makes a new TimedObserver
@ -156,31 +160,46 @@ func (saw *sampleAndWaterMarkHistograms) SetX1(x1 float64) {
} }
func (saw *sampleAndWaterMarkHistograms) innerSet(updateXOrX1 func()) { func (saw *sampleAndWaterMarkHistograms) innerSet(updateXOrX1 func()) {
saw.Lock() var when time.Time
when := saw.clock.Now() var whenInt int64
whenInt := saw.quantize(when) var acc sampleAndWaterMarkAccumulator
acc := saw.sampleAndWaterMarkAccumulator var wellOrdered bool
wellOrdered := !when.Before(acc.lastSet) func() {
if wellOrdered { saw.Lock()
defer saw.Unlock()
when = saw.clock.Now()
whenInt = saw.quantize(when)
acc = saw.sampleAndWaterMarkAccumulator
wellOrdered = !when.Before(acc.lastSet)
updateXOrX1() updateXOrX1()
saw.relX = saw.x / saw.x1 saw.relX = saw.x / saw.x1
if acc.lastSetInt < whenInt { if wellOrdered {
saw.loRelX, saw.hiRelX = acc.relX, acc.relX if acc.lastSetInt < whenInt {
saw.lastSetInt = whenInt saw.loRelX, saw.hiRelX = acc.relX, acc.relX
saw.lastSetInt = whenInt
}
saw.lastSet = when
} }
// `wellOrdered` should always be true because we are using
// monotonic clock readings and they never go backwards. Yet
// very small backwards steps (under 1 microsecond) have been
// observed
// (https://github.com/kubernetes/kubernetes/issues/96459).
// In the backwards case, treat the current reading as if it
// had occurred at time `saw.lastSet` and log an error. It
// would be wrong to update `saw.lastSet` in this case because
// that plants a time bomb for future updates to
// `saw.lastSetInt`.
if saw.relX < saw.loRelX { if saw.relX < saw.loRelX {
saw.loRelX = saw.relX saw.loRelX = saw.relX
} else if saw.relX > saw.hiRelX { } else if saw.relX > saw.hiRelX {
saw.hiRelX = saw.relX saw.hiRelX = saw.relX
} }
saw.lastSet = when }()
}
saw.Unlock()
if !wellOrdered { if !wellOrdered {
lastSetS := acc.lastSet.Format(time.RFC3339Nano) lastSetS := acc.lastSet.String()
whenS := when.Format(time.RFC3339Nano) whenS := when.String()
klog.Fatalf("Time went backwards from %s to %s for labelValues=%#+v", lastSetS, whenS, saw.labelValues) klog.Errorf("Time went backwards from %s to %s for labelValues=%#+v", lastSetS, whenS, saw.labelValues)
panic(append([]string{lastSetS, whenS}, saw.labelValues...))
} }
for acc.lastSetInt < whenInt { for acc.lastSetInt < whenInt {
saw.samples.WithLabelValues(saw.labelValues...).Observe(acc.relX) saw.samples.WithLabelValues(saw.labelValues...).Observe(acc.relX)