wip

pkg/util/metric/timing.go

@@ -53,6 +53,10 @@ func (tm *Timing) lastIdx() int {
 	return len(tm.ents) - 1
 }
 
+type End struct {
+	Event interface{}
+}
+
 // Event records an event to the timing. It returns the duration
 // elapsed since the last Event, and the internal index assigned
 // to the new event (for use in Between). The same event may be
@@ -96,6 +100,38 @@ func (tm *Timing) Duration() time.Duration {
 	return tm.Between(0, last)
 }
 
+func (tm *Timing) Summary() map[interface{}]time.Duration {
+	res := make(map[interface{}]time.Duration)
+	m := map[interface{}]int{} // idx, key is never &End{X}
+	for i := range tm.ents {
+		el := &tm.ents[i]
+		e, ok := el.tr.(*End)
+		if !ok {
+			idx, open := m[el.tr]
+			if open {
+				// Invalid nesting, close current interval and start new one.
+				res[el.tr] += tm.Between(idx, i)
+				// Fall through.
+			}
+			m[el.tr] = i
+			continue
+		}
+		// Closing an existing interval. If it isn't open, that's a programming
+		// error but we'll handle it gracefully by ignoring it.
+		idx, open := m[e]
+		if !open {
+			continue // ignore
+		}
+		res[el.tr] += tm.Between(idx, i)
+		delete(m, el.tr)
+	}
+	for e, idx := range m {
+		// Close any leftover events.
+		res[e] += tm.Between(idx, tm.lastIdx())
+	}
+	return res
+}
+
 // TODO(tbg): provide a method to summarize the timings.
 // This could power a granular per-range breakdown of execution
 // timings via a map[struct{A, B interface{}}ewma.MovingAverage.

pkg/util/metric/timing_test.go

@@ -26,51 +26,48 @@ func TestTiming(t *testing.T) {
 	const (
 		evStart = iota
 		evLeaseStart
-		evLeaseEnd
 		evContentionStart
-		evContentionEnd
-		evSequenceBegin
-		evSequenceEnd
+		evSequenceStart
 		evEvalStart
-		evEvalEnd
 		evReplStart
-		evReplEnd
 	)
-	mc := hlc.NewManualClock(0)
+	mc := hlc.NewManualClock(1)
 	tm := &Timing{Now: func() time.Time {
 		return time.Unix(0, mc.UnixNano())
 	}}
 	r := rand.New(rand.NewSource(123))
+	_ = r
 	tick := func() {
-		nanos := r.Int63n(5000)
+		nanos := r.Int63n(100)
 		mc.Increment(nanos)
 	}
 
 	tm.Event(ctx, evStart)
 	tick()
 	tm.Event(ctx, evLeaseStart)
 	tick()
-	tm.Event(ctx, evLeaseEnd)
+	tm.Event(ctx, &End{evLeaseStart})
 	tick()
-	tm.Event(ctx, evSequenceBegin)
+	tm.Event(ctx, evSequenceStart)
 	tick()
-	tm.Event(ctx, evSequenceEnd)
+	tm.Event(ctx, &End{evSequenceStart})
 	tick()
 	tm.Event(ctx, evContentionStart)
 	tick()
-	tm.Event(ctx, evContentionEnd)
+	tm.Event(ctx, &End{evContentionStart})
 	tick()
-	tm.Event(ctx, evSequenceBegin)
+	tm.Event(ctx, evSequenceStart)
 	tick()
-	tm.Event(ctx, evSequenceEnd)
+	tm.Event(ctx, &End{evSequenceStart})
 	tick()
 	tm.Event(ctx, evEvalStart)
 	tick()
-	tm.Event(ctx, evEvalEnd)
+	tm.Event(ctx, &End{evEvalStart})
 	tick()
 	tm.Event(ctx, evReplStart)
 	tick()
-	tm.Event(ctx, evReplEnd)
+	tm.Event(ctx, &End{evReplStart})
 
-	require.EqualValues(t, mc.UnixNano(), tm.Duration())
+	require.EqualValues(t, mc.UnixNano(), 1+tm.Duration())
+	t.Error(tm.Summary())
 }