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.