event: add a namespace to every event
Add a namespace to every event.
It can be set with Builder.Namespace.
By default we use the import path of the package that builds the
event.
The Exporter memoizes the map from pcs to namespaces. This saves both
the time to extract the frame and parse the fully-qualified function
name, and the allocation that is inevitable because
runtime.CallersFrames takes a slice.
This is significantly slower in the Noop cases (see below), so the
user must enable it with an option.
name old time/op new time/op delta
LogEventNoExporter-8 616ns ± 2% 612ns ± 2% -0.67% (p=0.019 n=17+20)
LogEventNoop-8 1.83µs ± 3% 13.51µs ± 4% +638.00% (p=0.000 n=18+19)
LogEventDiscard-8 10.7µs ± 2% 23.7µs ± 2% +121.35% (p=0.000 n=20+17)
LogEventfDiscard-8 16.6µs ± 2% 28.8µs ± 1% +73.47% (p=0.000 n=19+18)
TraceEventNoop-8 41.5µs ± 3% 78.6µs ± 1% +89.63% (p=0.000 n=19+18)
MetricEventNoop-8 16.4µs ± 2% 40.9µs ± 2% +149.97% (p=0.000 n=17+20)
Logrus-8 55.4µs ± 2% 54.3µs ± 3% -1.97% (p=0.000 n=19+17)
Logrusf-8 46.4µs ± 3% 45.1µs ± 1% -2.82% (p=0.000 n=20+18)
Baseline-8 280ns ± 2% 278ns ± 2% -0.72% (p=0.025 n=19+20)
LogStdlib-8 8.54µs ± 1% 8.49µs ± 2% -0.60% (p=0.043 n=18+18)
LogPrintf-8 13.1µs ± 2% 13.0µs ± 2% -0.72% (p=0.010 n=18+18)
LogZap-8 20.4µs ± 3% 20.1µs ± 1% -1.43% (p=0.000 n=20+18)
LogZapf-8 21.7µs ± 3% 21.6µs ± 1% ~ (p=0.797 n=20+19)
LogZerolog-8 7.47µs ± 2% 7.40µs ± 1% -0.87% (p=0.006 n=18+19)
LogZerologf-8 12.5µs ± 3% 12.6µs ± 2% ~ (p=0.171 n=18+19)
Further testing showed that the time is all due to runtime.Callers;
caching the pcs is very effective at eliminating any overhead from
extracting frame information. (Note that TraceEventNoop and
MetricEventNoop are misnamed; they install a printer that writes to
io.Discard.)
Change-Id: I37bb5e6194be6dcaaa471086dcd3d4850bfd531c
Reviewed-on: https://go-review.googlesource.com/c/exp/+/324291
Trust: Jonathan Amsterdam <jba@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Ian Cottrell <iancottrell@google.com>
diff --git a/event/builder.go b/event/builder.go
index cdceb06..7a5f597 100644
--- a/event/builder.go
+++ b/event/builder.go
@@ -96,13 +96,24 @@
return b
}
+func (b Builder) Namespace(ns string) Builder {
+ if b.data != nil {
+ b.data.Event.Namespace = ns
+ }
+ return b
+}
+
// Log is a helper that calls Deliver with LogKind.
func (b Builder) Log(message string) {
if b.data == nil {
return
}
if b.data.exporter.handler != nil {
- b.log(message)
+ b.data.exporter.mu.Lock()
+ defer b.data.exporter.mu.Unlock()
+ b.data.Event.Labels = append(b.data.Event.Labels, Message.Of(message))
+ b.data.exporter.prepare(&b.data.Event)
+ b.data.exporter.handler.Log(b.ctx, &b.data.Event)
}
b.done()
}
@@ -114,19 +125,17 @@
return
}
if b.data.exporter.loggingEnabled() {
- b.log(fmt.Sprintf(template, args...))
+ message := fmt.Sprintf(template, args...)
+ // Duplicate code from Log so Exporter.deliver's invocation of runtime.Callers is correct.
+ b.data.exporter.mu.Lock()
+ defer b.data.exporter.mu.Unlock()
+ b.data.Event.Labels = append(b.data.Event.Labels, Message.Of(message))
+ b.data.exporter.prepare(&b.data.Event)
+ b.data.exporter.handler.Log(b.ctx, &b.data.Event)
}
b.done()
}
-func (b Builder) log(message string) {
- b.data.exporter.mu.Lock()
- defer b.data.exporter.mu.Unlock()
- b.data.Event.Labels = append(b.data.Event.Labels, Message.Of(message))
- b.data.exporter.prepare(&b.data.Event)
- b.data.exporter.handler.Log(b.ctx, &b.data.Event)
-}
-
// Metric is a helper that calls Deliver with MetricKind.
func (b Builder) Metric() {
if b.data == nil {
diff --git a/event/event.go b/event/event.go
index a055ef8..2c59816 100644
--- a/event/event.go
+++ b/event/event.go
@@ -12,9 +12,10 @@
// Event holds the information about an event that occurred.
// It combines the event metadata with the user supplied labels.
type Event struct {
- Parent uint64 // id of the parent event for this event
- At time.Time // time at which the event is delivered to the exporter.
- Labels []Label
+ Parent uint64 // id of the parent event for this event
+ Namespace string // namespace of event; if empty, set by exporter to import path
+ At time.Time // time at which the event is delivered to the exporter.
+ Labels []Label
}
// Handler is a the type for something that handles events as they occur.
diff --git a/event/export.go b/event/export.go
index 117ccf7..85e8729 100644
--- a/event/export.go
+++ b/event/export.go
@@ -8,6 +8,8 @@
import (
"context"
+ "runtime"
+ "strings"
"sync"
"sync/atomic"
"time"
@@ -18,9 +20,10 @@
type Exporter struct {
opts ExporterOptions
- mu sync.Mutex
- handler Handler
- lastEvent uint64
+ mu sync.Mutex
+ handler Handler
+ lastEvent uint64
+ pcToNamespace map[uintptr]string
}
type ExporterOptions struct {
@@ -32,6 +35,10 @@
DisableTracing bool
DisableAnnotations bool
DisableMetrics bool
+
+ // Enable automatically setting the event Namespace to the calling package's
+ // import path.
+ EnableNamespaces bool
}
// contextKey is used as the key for storing a contextValue on the context.
@@ -87,14 +94,63 @@
// The event will be assigned a new ID.
// If the event does not have a timestamp, and the exporter has a Now function
// then the timestamp will be updated.
+// If automatic namespaces are enabled and the event doesn't have a namespace,
+// one based on the caller's import path will be provided.
// prepare must be called with the export mutex held.
func (e *Exporter) prepare(ev *Event) {
if e.opts.Now != nil && ev.At.IsZero() {
ev.At = e.opts.Now()
}
+ if e.opts.EnableNamespaces && ev.Namespace == "" {
+ // Get the pc of the user function that delivered the event.
+ // This is sensitive to the call stack.
+ // 0: runtime.Callers
+ // 1: Exporter.prepare (this function)
+ // 2: Builder.{Start,End,etc.}
+ // 3: user function
+ var pcs [1]uintptr
+ runtime.Callers(3, pcs[:])
+ pc := pcs[0]
+ if pc != 0 {
+ ns, ok := e.pcToNamespace[pc]
+ if !ok {
+ // If we call runtime.CallersFrames(pcs[:1]) in this function, the
+ // compiler will think the pcs array escapes and will allocate.
+ f := callerFrameFunction(pc)
+ ns = namespace(f)
+ if e.pcToNamespace == nil {
+ e.pcToNamespace = map[uintptr]string{}
+ }
+ e.pcToNamespace[pc] = ns
+ }
+ ev.Namespace = ns
+ }
+ }
}
func (e *Exporter) loggingEnabled() bool { return !e.opts.DisableLogging }
func (e *Exporter) annotationsEnabled() bool { return !e.opts.DisableAnnotations }
func (e *Exporter) tracingEnabled() bool { return !e.opts.DisableTracing }
func (e *Exporter) metricsEnabled() bool { return !e.opts.DisableMetrics }
+
+func callerFrameFunction(pc uintptr) string {
+ frame, _ := runtime.CallersFrames([]uintptr{pc}).Next()
+ return frame.Function
+}
+
+func namespace(funcPath string) string {
+ // Function is the fully-qualified function name. The name itself may
+ // have dots (for a closure, for instance), but it can't have slashes.
+ // So the package path ends at the first dot after the last slash.
+ i := strings.LastIndexByte(funcPath, '/')
+ if i < 0 {
+ i = 0
+ }
+ end := strings.IndexByte(funcPath[i:], '.')
+ if end >= 0 {
+ end += i
+ } else {
+ end = len(funcPath)
+ }
+ return funcPath[:end]
+}
diff --git a/event/namespace_test.go b/event/namespace_test.go
new file mode 100644
index 0000000..d3789c9
--- /dev/null
+++ b/event/namespace_test.go
@@ -0,0 +1,101 @@
+// Copyright 2021 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package event_test
+
+import (
+ "context"
+ "runtime"
+ "testing"
+
+ "golang.org/x/exp/event"
+)
+
+const thisImportPath = "golang.org/x/exp/event_test"
+
+func TestNamespace(t *testing.T) {
+ var h nsHandler
+ ctx := event.WithExporter(context.Background(), event.NewExporter(&h, &event.ExporterOptions{EnableNamespaces: true}))
+ event.To(ctx).Log("msg")
+ if got, want := h.ns, thisImportPath; got != want {
+ t.Errorf("got namespace %q, want, %q", got, want)
+ }
+}
+
+type nsHandler struct {
+ ns string
+}
+
+func (h *nsHandler) Log(ctx context.Context, ev *event.Event) {
+ h.event(ctx, ev)
+}
+
+func (h *nsHandler) Metric(ctx context.Context, ev *event.Event) {
+ h.event(ctx, ev)
+}
+
+func (h *nsHandler) Annotate(ctx context.Context, ev *event.Event) {
+ h.event(ctx, ev)
+}
+
+func (h *nsHandler) Start(ctx context.Context, ev *event.Event) context.Context {
+ h.event(ctx, ev)
+ return ctx
+}
+
+func (h *nsHandler) End(ctx context.Context, ev *event.Event) {
+ h.event(ctx, ev)
+}
+
+func (h *nsHandler) event(event context.Context, e *event.Event) {
+ h.ns = e.Namespace
+}
+
+func BenchmarkRuntimeCallers(b *testing.B) {
+ for i := 0; i < b.N; i++ {
+ var pcs [1]uintptr
+ _ = runtime.Callers(2, pcs[:])
+ }
+}
+
+func BenchmarkCallersFrames(b *testing.B) {
+ var pcs [1]uintptr
+ n := runtime.Callers(2, pcs[:])
+ b.ResetTimer()
+ for i := 0; i < b.N; i++ {
+ frames := runtime.CallersFrames(pcs[:n])
+ frame, _ := frames.Next()
+ _ = frame.Function //namespace(frame.Function)
+ }
+}
+
+func TestStablePCs(t *testing.T) {
+ // The pc is stable regardless of the call stack.
+ pc1 := f()
+ pc2 := g()
+ if pc1 != pc2 {
+ t.Fatal("pcs differ")
+ }
+ // We can recover frame information after the function has returned.
+ frames := runtime.CallersFrames([]uintptr{pc1})
+ frame, _ := frames.Next()
+ want := thisImportPath + ".h"
+ if got := frame.Function; got != want {
+ t.Errorf("got %q, want %q", got, want)
+ }
+}
+
+func f() uintptr {
+ return h()
+}
+
+func g() uintptr {
+ return h()
+}
+
+func h() uintptr {
+ var pcs [1]uintptr
+ runtime.Callers(1, pcs[:])
+ return pcs[0]
+}
