//go/tracing/loggingtracer/loggingtracer.go: Log span durations.
Change-Id: If411d8fab4e8daa2dd24edaf5702d903272c415b
Reviewed-on: https://skia-review.googlesource.com/c/buildbot/+/610663
Reviewed-by: Joe Gregorio <jcgregorio@google.com>
Auto-Submit: Leandro Lovisolo <lovisolo@google.com>
Commit-Queue: Joe Gregorio <jcgregorio@google.com>
diff --git a/go/tracing/loggingtracer/BUILD.bazel b/go/tracing/loggingtracer/BUILD.bazel
index ec6dc1d..8f2ffdd 100644
--- a/go/tracing/loggingtracer/BUILD.bazel
+++ b/go/tracing/loggingtracer/BUILD.bazel
@@ -7,6 +7,7 @@
importpath = "go.skia.org/infra/go/tracing/loggingtracer",
visibility = ["//visibility:public"],
deps = [
+ "//go/now",
"//go/sklog",
"@io_opencensus_go//trace",
],
@@ -17,6 +18,7 @@
srcs = ["loggingtracer_test.go"],
embed = [":loggingtracer"],
deps = [
+ "//go/now",
"@com_github_stretchr_testify//assert",
"@com_github_stretchr_testify//require",
"@io_opencensus_go//trace",
diff --git a/go/tracing/loggingtracer/loggingtracer.go b/go/tracing/loggingtracer/loggingtracer.go
index 8de37c5..45bae6f 100644
--- a/go/tracing/loggingtracer/loggingtracer.go
+++ b/go/tracing/loggingtracer/loggingtracer.go
@@ -1,6 +1,6 @@
// Package loggingtracer provides a trace.Tracer that wraps trace.DefaultTracer and logs span
-// starts/ends. It is intended for local debugging only, as usage in production might cause noisy
-// and/or verbose logs.
+// starts/ends and durations. It is intended for local debugging only, as usage in production might
+// cause noisy and/or verbose logs.
//
// To use this logger, call Initialize(). To customize the logger function, override Logf.
package loggingtracer
@@ -9,8 +9,10 @@
"context"
"fmt"
"runtime"
+ "time"
"go.opencensus.io/trace"
+ "go.skia.org/infra/go/now"
"go.skia.org/infra/go/sklog"
)
@@ -22,7 +24,7 @@
//
// This is intended for local debugging only. Usage in production might cuase noisy/verbose logs.
func Initialize() {
- trace.DefaultTracer = loggingTracer{actualTracer: trace.DefaultTracer}
+ trace.DefaultTracer = &loggingTracer{actualTracer: trace.DefaultTracer}
}
// getCaller returns the calling file:line via runtime.Caller.
@@ -40,84 +42,103 @@
}
// StartSpan implements the trace.Tracer interface.
-func (t loggingTracer) StartSpan(ctx context.Context, name string, o ...trace.StartOption) (context.Context, *trace.Span) {
+func (t *loggingTracer) StartSpan(ctx context.Context, name string, o ...trace.StartOption) (context.Context, *trace.Span) {
Logf("Starting span: %s [%s]", name, getCaller(3))
ctx, actualSpan := t.actualTracer.StartSpan(ctx, name, o...)
- return ctx, trace.NewSpan(loggingSpan{actualSpan: actualSpan, name: name})
+ return ctx, trace.NewSpan(&loggingSpan{actualSpan: actualSpan, ctx: ctx, name: name, startTime: now.Now(ctx)})
}
// StartSpanWithRemoteParent implements the trace.Tracer interface.
-func (t loggingTracer) StartSpanWithRemoteParent(ctx context.Context, name string, parent trace.SpanContext, o ...trace.StartOption) (context.Context, *trace.Span) {
+func (t *loggingTracer) StartSpanWithRemoteParent(ctx context.Context, name string, parent trace.SpanContext, o ...trace.StartOption) (context.Context, *trace.Span) {
Logf("Starting span with remote parent: %s [%s]", name, getCaller(3))
ctx, actualSpan := t.actualTracer.StartSpanWithRemoteParent(ctx, name, parent, o...)
- return ctx, trace.NewSpan(loggingSpan{actualSpan: actualSpan, name: name})
+ return ctx, trace.NewSpan(&loggingSpan{actualSpan: actualSpan, ctx: ctx, name: name, startTime: now.Now(ctx)})
}
// FromContext implements the trace.Tracer interface.
-func (t loggingTracer) FromContext(ctx context.Context) *trace.Span {
+func (t *loggingTracer) FromContext(ctx context.Context) *trace.Span {
return t.actualTracer.FromContext(ctx)
}
// NewContext implements the trace.Tracer interface.
-func (t loggingTracer) NewContext(parent context.Context, s *trace.Span) context.Context {
+func (t *loggingTracer) NewContext(parent context.Context, s *trace.Span) context.Context {
return t.actualTracer.NewContext(parent, s)
}
var _ trace.Tracer = (*loggingTracer)(nil)
-// loggingSpan is a trace.SpanInterface that wraps a trace.Span and logs the span end.
+// loggingSpan is a trace.SpanInterface that wraps a trace.Span and logs the span end. It also
+// implements the spanCtxGetterSetter interface so we can get and set its context from tests, which
+// is necessary for time traveling.
type loggingSpan struct {
actualSpan *trace.Span
+ ctx context.Context
name string
+ startTime time.Time
}
+// spanCtxGetterSetter allows manipulating the context of a span from tests, which is necessary for
+// time traveling.
+type spanCtxGetterSetter interface {
+ GetCtx() context.Context
+ SetCtx(context.Context)
+}
+
+// GetCtx implements the spanCtxGetterSetter interface.
+func (s *loggingSpan) GetCtx() context.Context { return s.ctx }
+
+// SetCtx implements the spanCtxGetterSetter interface.
+func (s *loggingSpan) SetCtx(ctx context.Context) { s.ctx = ctx }
+
+var _ spanCtxGetterSetter = (*loggingSpan)(nil)
+
// IsRecordingEvents implements the trace.SpanInterface interface.
-func (s loggingSpan) IsRecordingEvents() bool { return s.actualSpan.IsRecordingEvents() }
+func (s *loggingSpan) IsRecordingEvents() bool { return s.actualSpan.IsRecordingEvents() }
// End implements the trace.SpanInterface interface.
-func (s loggingSpan) End() {
- Logf("Ending span: %s [%s]", s.name, getCaller(3))
+func (s *loggingSpan) End() {
+ Logf("Ending span: %s [%s] (%s)", s.name, getCaller(3), now.Now(s.ctx).Sub(s.startTime))
s.actualSpan.End()
}
// SpanContext implements the trace.SpanInterface interface.
-func (s loggingSpan) SpanContext() trace.SpanContext { return s.actualSpan.SpanContext() }
+func (s *loggingSpan) SpanContext() trace.SpanContext { return s.actualSpan.SpanContext() }
// SetName implements the trace.SpanInterface interface.
-func (s loggingSpan) SetName(name string) { s.actualSpan.SetName(name) }
+func (s *loggingSpan) SetName(name string) { s.actualSpan.SetName(name) }
// SetStatus implements the trace.SpanInterface interface.
-func (s loggingSpan) SetStatus(status trace.Status) { s.actualSpan.SetStatus(status) }
+func (s *loggingSpan) SetStatus(status trace.Status) { s.actualSpan.SetStatus(status) }
// AddAttributes implements the trace.SpanInterface interface.
-func (s loggingSpan) AddAttributes(attributes ...trace.Attribute) {
+func (s *loggingSpan) AddAttributes(attributes ...trace.Attribute) {
s.actualSpan.AddAttributes(attributes...)
}
// Annotate implements the trace.SpanInterface interface.
-func (s loggingSpan) Annotate(attributes []trace.Attribute, str string) {
+func (s *loggingSpan) Annotate(attributes []trace.Attribute, str string) {
s.actualSpan.Annotate(attributes, str)
}
// Annotatef implements the trace.SpanInterface interface.
-func (s loggingSpan) Annotatef(attributes []trace.Attribute, format string, a ...interface{}) {
+func (s *loggingSpan) Annotatef(attributes []trace.Attribute, format string, a ...interface{}) {
s.actualSpan.Annotatef(attributes, format, a...)
}
// AddMessageSendEvent implements the trace.SpanInterface interface.
-func (s loggingSpan) AddMessageSendEvent(messageID, uncompressedByteSize, compressedByteSize int64) {
+func (s *loggingSpan) AddMessageSendEvent(messageID, uncompressedByteSize, compressedByteSize int64) {
s.actualSpan.AddMessageSendEvent(messageID, uncompressedByteSize, compressedByteSize)
}
// AddMessageReceiveEvent implements the trace.SpanInterface interface.
-func (s loggingSpan) AddMessageReceiveEvent(messageID, uncompressedByteSize, compressedByteSize int64) {
+func (s *loggingSpan) AddMessageReceiveEvent(messageID, uncompressedByteSize, compressedByteSize int64) {
s.actualSpan.AddMessageReceiveEvent(messageID, uncompressedByteSize, compressedByteSize)
}
// AddLink implements the trace.SpanInterface interface.
-func (s loggingSpan) AddLink(l trace.Link) { s.actualSpan.AddLink(l) }
+func (s *loggingSpan) AddLink(l trace.Link) { s.actualSpan.AddLink(l) }
// String implements the trace.SpanInterface interface.
-func (s loggingSpan) String() string { return s.actualSpan.String() }
+func (s *loggingSpan) String() string { return s.actualSpan.String() }
var _ trace.SpanInterface = (*loggingSpan)(nil)
diff --git a/go/tracing/loggingtracer/loggingtracer_test.go b/go/tracing/loggingtracer/loggingtracer_test.go
index 2ec2b09..23b4161 100644
--- a/go/tracing/loggingtracer/loggingtracer_test.go
+++ b/go/tracing/loggingtracer/loggingtracer_test.go
@@ -5,13 +5,17 @@
"fmt"
"regexp"
"testing"
+ "time"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"go.opencensus.io/trace"
+ "go.skia.org/infra/go/now"
)
func TestLoggingTracer(t *testing.T) {
+ fakeNow := time.Date(2023, time.January, 1, 0, 0, 0, 0, time.UTC)
+
// Initialize logging tracer.
originalTracer := trace.DefaultTracer
Initialize()
@@ -25,27 +29,27 @@
}
defer func() { Logf = originalLogf }()
- ctx := context.Background()
+ ctx := now.TimeTravelingContext(fakeNow)
a(ctx)
// These patterns make this test case fragile (i.e. inserting/deleting lines in this file might
// break this test case), but it is important to test that we are reporting the correct line
// numbers.
expectedLogPatterns := []string{
- `Starting span: a \[.*/loggingtracer_test.go:65]`,
- `Starting span: b \[.*/loggingtracer_test.go:72]`,
- `Starting span: c \[.*/loggingtracer_test.go:79]`,
- `Starting span: d \[.*/loggingtracer_test.go:85]`,
- `Ending span: d \[.*/loggingtracer_test.go:87]`,
- `Ending span: c \[.*/loggingtracer_test.go:82]`,
- `Starting span: c \[.*/loggingtracer_test.go:79]`,
- `Starting span: d \[.*/loggingtracer_test.go:85]`,
- `Ending span: d \[.*/loggingtracer_test.go:87]`,
- `Ending span: c \[.*/loggingtracer_test.go:82]`,
- `Ending span: b \[.*/loggingtracer_test.go:76]`,
- `Starting span: e \[.*/loggingtracer_test.go:90]`,
- `Ending span: e \[.*/loggingtracer_test.go:92]`,
- `Ending span: a \[.*/loggingtracer_test.go:69]`,
+ `^Starting span: a \[.*/loggingtracer_test.go:69]$`,
+ `^Starting span: b \[.*/loggingtracer_test.go:77]$`,
+ `^Starting span: c \[.*/loggingtracer_test.go:85]$`,
+ `^Starting span: d \[.*/loggingtracer_test.go:92]$`,
+ `^Ending span: d \[.*/loggingtracer_test.go:94] \(1s\)$`,
+ `^Ending span: c \[.*/loggingtracer_test.go:88] \(3s\)$`,
+ `^Starting span: c \[.*/loggingtracer_test.go:85]$`,
+ `^Starting span: d \[.*/loggingtracer_test.go:92]$`,
+ `^Ending span: d \[.*/loggingtracer_test.go:94] \(1s\)$`,
+ `^Ending span: c \[.*/loggingtracer_test.go:88] \(3s\)$`,
+ `^Ending span: b \[.*/loggingtracer_test.go:81] \(11s\)$`,
+ `^Starting span: e \[.*/loggingtracer_test.go:98]$`,
+ `^Ending span: e \[.*/loggingtracer_test.go:100] \(500ms\)$`,
+ `^Ending span: a \[.*/loggingtracer_test.go:73] \(21.5s\)$`,
}
require.Len(t, logs, len(expectedLogPatterns))
@@ -61,32 +65,44 @@
}
}
-func a(ctx context.Context) {
+func a(ctx context.Context) context.Context {
ctx, span := trace.StartSpan(ctx, "a")
defer span.End()
- b(ctx)
- e(ctx)
+ ctx = b(ctx)
+ ctx = e(ctx)
+ return fakeSpanDelay(ctx, span, 10*time.Second)
}
-func b(ctx context.Context) {
+func b(ctx context.Context) context.Context {
ctx, span := trace.StartSpan(ctx, "b")
defer span.End()
- c(ctx)
- c(ctx)
+ ctx = c(ctx)
+ ctx = c(ctx)
+ return fakeSpanDelay(ctx, span, 5*time.Second)
}
-func c(ctx context.Context) {
+func c(ctx context.Context) context.Context {
ctx, span := trace.StartSpan(ctx, "c")
defer span.End()
- d(ctx)
+ ctx = d(ctx)
+ return fakeSpanDelay(ctx, span, 2*time.Second)
}
-func d(ctx context.Context) {
+func d(ctx context.Context) context.Context {
ctx, span := trace.StartSpan(ctx, "d")
defer span.End()
+ return fakeSpanDelay(ctx, span, time.Second)
}
-func e(ctx context.Context) {
+func e(ctx context.Context) context.Context {
ctx, span := trace.StartSpan(ctx, "e")
defer span.End()
+ return fakeSpanDelay(ctx, span, 500*time.Millisecond)
+}
+
+func fakeSpanDelay(ctx context.Context, span *trace.Span, duration time.Duration) context.Context {
+ ctxGetterSetter := span.Internal().(spanCtxGetterSetter)
+ ctx = context.WithValue(ctxGetterSetter.GetCtx(), now.ContextKey, now.Now(ctx).Add(duration))
+ ctxGetterSetter.SetCtx(ctx)
+ return ctx
}
