event: semi-automatic trace duration metric
If the call to Builder.End includes a DurationMetric label, then emit
a Metric measuring the time between the parent Start call and the End.
Also, fix a bug in Builder.Start where the synthesized End event
didn't have the same labels as the Start event.
Change-Id: If5e0598e69628e6300b8590a0c607426237aa2b7
Reviewed-on: https://go-review.googlesource.com/c/exp/+/326673
Trust: Jonathan Amsterdam <jba@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Ian Cottrell <iancottrell@google.com>
diff --git a/event/builder.go b/event/builder.go
index 6966078..f90804f 100644
--- a/event/builder.go
+++ b/event/builder.go
@@ -33,10 +33,11 @@
const preallocateLabels = 6
type builder struct {
- exporter *Exporter
- Event Event
- labels [preallocateLabels]Label
- id uint64
+ exporter *Exporter
+ Event Event
+ labels [preallocateLabels]Label
+ id uint64
+ parentStart time.Time
}
var builderPool = sync.Pool{New: func() interface{} { return &builder{} }}
@@ -54,12 +55,13 @@
var builderID uint64 // atomic
func newBuilder(ctx context.Context) *builder {
- exporter, parent := FromContext(ctx)
+ exporter, parent, parentStart := FromContext(ctx)
if exporter == nil {
return nil
}
b := allocBuilder()
b.exporter = exporter
+ b.parentStart = parentStart
b.Event.Labels = b.labels[:0]
b.Event.Parent = parent
return b
@@ -196,7 +198,7 @@
if b.data.Event.Namespace == "" {
b.data.Event.Namespace = mv.m.Descriptor().Namespace()
}
- b.data.Event.Labels = append(b.data.Event.Labels, MetricVal.Of(mv.v), MetricKey.Of(ValueOf(mv.m)))
+ b.data.Event.Labels = append(b.data.Event.Labels, MetricVal.Of(mv.v), MetricKey.Of(mv.m))
b.data.exporter.prepare(&b.data.Event)
b.data.exporter.handler.Metric(b.ctx, &b.data.Event)
}
@@ -225,6 +227,12 @@
}
checkValid(b.data, b.builderID)
if b.data.exporter.tracingEnabled() {
+ // If there is a DurationMetric label, emit a Metric event
+ // with the time since Start was called.
+ if v, ok := DurationMetric.Find(&b.data.Event); ok {
+ m := v.(*Duration)
+ b.Clone().Metric(m.Record(time.Since(b.data.parentStart)))
+ }
b.data.exporter.mu.Lock()
defer b.data.exporter.mu.Unlock()
b.data.Event.Labels = append(b.data.Event.Labels, End.Value())
@@ -267,18 +275,18 @@
defer b.data.exporter.mu.Unlock()
b.data.exporter.lastEvent++
traceID := b.data.exporter.lastEvent
+ // create the end builder
+ eb := b.Clone()
+ eb.data.Event.Parent = traceID
+
b.data.Event.Labels = append(b.data.Event.Labels, Trace.Of(traceID))
b.data.exporter.prepare(&b.data.Event)
- // create the end builder
- eb := Builder{}
- eb.data = allocBuilder()
- eb.builderID = eb.data.id
- eb.data.exporter = b.data.exporter
- eb.data.Event.Parent = traceID
// and now deliver the start event
b.data.Event.Labels = append(b.data.Event.Labels, Name.Of(name))
- ctx = newContext(ctx, b.data.exporter, traceID)
+ now := time.Now()
+ ctx = newContext(ctx, b.data.exporter, traceID, now)
ctx = b.data.exporter.handler.Start(ctx, &b.data.Event)
+ eb.data.parentStart = now
eb.ctx = ctx
end = eb.End
}
diff --git a/event/builder_test.go b/event/builder_test.go
index ad1185c..5e0174f 100644
--- a/event/builder_test.go
+++ b/event/builder_test.go
@@ -11,6 +11,7 @@
"fmt"
"strings"
"testing"
+ "time"
"github.com/google/go-cmp/cmp"
"golang.org/x/exp/event"
@@ -66,7 +67,7 @@
func TestTraceBuilder(t *testing.T) {
// Verify that the context returned from the handler is also returned from Start,
// and is the context passed to End.
- ctx := event.WithExporter(context.Background(), event.NewExporter(&testTraceHandler{t}, nil))
+ ctx := event.WithExporter(context.Background(), event.NewExporter(&testTraceHandler{t: t}, nil))
ctx, end := event.To(ctx).Start("s")
val := ctx.Value("x")
if val != 1 {
@@ -76,13 +77,10 @@
}
type testTraceHandler struct {
+ event.NopHandler
t *testing.T
}
-func (*testTraceHandler) Log(ctx context.Context, _ *event.Event) {}
-func (*testTraceHandler) Annotate(ctx context.Context, _ *event.Event) {}
-func (*testTraceHandler) Metric(ctx context.Context, _ *event.Event) {}
-
func (*testTraceHandler) Start(ctx context.Context, _ *event.Event) context.Context {
return context.WithValue(ctx, "x", 1)
}
@@ -129,6 +127,48 @@
})
}
+func TestTraceDuration(t *testing.T) {
+ // Verify that a trace can can emit a latency metric.
+ dur := event.NewDuration("test")
+ want := 200 * time.Millisecond
+
+ check := func(t *testing.T, h *testTraceDurationHandler) {
+ if !h.got.HasValue() {
+ t.Fatal("no metric value")
+ }
+ got := h.got.Duration().Round(50 * time.Millisecond)
+ if got != want {
+ t.Fatalf("got %s, want %s", got, want)
+ }
+ }
+
+ t.Run("end function", func(t *testing.T) {
+ h := &testTraceDurationHandler{}
+ ctx := event.WithExporter(context.Background(), event.NewExporter(h, nil))
+ ctx, end := event.To(ctx).With(event.DurationMetric.Of(dur)).Start("s")
+ time.Sleep(want)
+ end()
+ check(t, h)
+ })
+ t.Run("End method", func(t *testing.T) {
+ h := &testTraceDurationHandler{}
+ ctx := event.WithExporter(context.Background(), event.NewExporter(h, nil))
+ ctx, _ = event.To(ctx).Start("s")
+ time.Sleep(want)
+ event.To(ctx).With(event.DurationMetric.Of(dur)).End()
+ check(t, h)
+ })
+}
+
+type testTraceDurationHandler struct {
+ event.NopHandler
+ got event.Value
+}
+
+func (t *testTraceDurationHandler) Metric(ctx context.Context, e *event.Event) {
+ t.got, _ = event.MetricVal.Find(e)
+}
+
func BenchmarkBuildContext(b *testing.B) {
// How long does it take to deliver an event from a nested context?
c := event.NewCounter("c")
diff --git a/event/common.go b/event/common.go
index e9c9704..b7be86c 100644
--- a/event/common.go
+++ b/event/common.go
@@ -4,19 +4,25 @@
package event
-const Message = stringKey("msg")
-const Name = stringKey("name")
-const Trace = traceKey("trace")
-const End = tagKey("end")
-const MetricKey = valueKey("metric")
-const MetricVal = valueKey("metricValue")
-const Error = errorKey("error")
+const (
+ Message = stringKey("msg")
+ Name = stringKey("name")
+ Trace = traceKey("trace")
+ End = tagKey("end")
+ MetricKey = interfaceKey("metric")
+ MetricVal = valueKey("metricValue")
+ DurationMetric = interfaceKey("durationMetric")
+ Error = errorKey("error")
+)
-type stringKey string
-type traceKey string
-type tagKey string
-type valueKey string
-type errorKey string
+type (
+ stringKey string
+ traceKey string
+ tagKey string
+ valueKey string
+ interfaceKey string
+ errorKey string
+)
// Of creates a new message Label.
func (k stringKey) Of(msg string) Label {
@@ -75,6 +81,23 @@
func (k valueKey) Find(ev *Event) (Value, bool) {
return lookupValue(string(k), ev.Labels)
+}
+
+func (k interfaceKey) Of(v interface{}) Label {
+ return Label{Name: string(k), Value: ValueOf(v)}
+}
+
+func (k interfaceKey) Matches(ev *Event) bool {
+ _, found := k.Find(ev)
+ return found
+}
+
+func (k interfaceKey) Find(ev *Event) (interface{}, bool) {
+ v, ok := lookupValue(string(k), ev.Labels)
+ if !ok {
+ return nil, false
+ }
+ return v.Interface(), true
}
diff --git a/event/event.go b/event/event.go
index 221d0ce..18a737d 100644
--- a/event/event.go
+++ b/event/event.go
@@ -42,7 +42,7 @@
// The exporter is called synchronously from the event call site, so it should
// return quickly so as not to hold up user code.
func WithExporter(ctx context.Context, e *Exporter) context.Context {
- return newContext(ctx, e, 0)
+ return newContext(ctx, e, 0, time.Time{})
}
// SetDefaultExporter sets an exporter that is used if no exporter can be
diff --git a/event/export.go b/event/export.go
index 84af70c..7464015 100644
--- a/event/export.go
+++ b/event/export.go
@@ -49,8 +49,9 @@
// contextValue is stored by value in the context to track the exporter and
// current parent event.
type contextValue struct {
- exporter *Exporter
- parent uint64
+ exporter *Exporter
+ parent uint64
+ startTime time.Time // for trace latency
}
var (
@@ -81,16 +82,16 @@
return (*Exporter)(atomic.LoadPointer(&defaultExporter))
}
-func newContext(ctx context.Context, exporter *Exporter, parent uint64) context.Context {
- return context.WithValue(ctx, contextKey, contextValue{exporter: exporter, parent: parent})
+func newContext(ctx context.Context, exporter *Exporter, parent uint64, t time.Time) context.Context {
+ return context.WithValue(ctx, contextKey, contextValue{exporter: exporter, parent: parent, startTime: t})
}
-// FromContext returns the exporter and current trace for the supplied context.
-func FromContext(ctx context.Context) (*Exporter, uint64) {
+// FromContext returns the exporter, parentID and parent start time for the supplied context.
+func FromContext(ctx context.Context) (*Exporter, uint64, time.Time) {
if v, ok := ctx.Value(contextKey).(contextValue); ok {
- return v.exporter, v.parent
+ return v.exporter, v.parent, v.startTime
}
- return getDefaultExporter(), 0
+ return getDefaultExporter(), 0, time.Time{}
}
// prepare events before delivering to the underlying handler.
