runtime/trace: add simple benchmarks for user annotation

Also, avoid Region creation when tracing is disabled.
Unfortunate side-effect of this change is that we no longer trace
pre-existing regions in tracing, but we can add the feature in
the future when we find it useful and justifiable. Until then,
let's avoid the overhead from this low-level api use as much as
possible.

goos: linux
goarch: amd64
pkg: runtime/trace

// Trace disabled
BenchmarkStartRegion-12 2000000000	         0.66 ns/op	       0 B/op	       0 allocs/op
BenchmarkNewTask-12    	30000000	        40.4 ns/op	      56 B/op	       2 allocs/op

// Trace enabled, -trace=/dev/null
BenchmarkStartRegion-12  5000000	       287 ns/op	      32 B/op	       1 allocs/op
BenchmarkNewTask-12    	 5000000	       283 ns/op	      56 B/op	       2 allocs/op

Also, skip other tests if tracing is already enabled.

Change-Id: Id3028d60b5642fcab4b09a74fd7d79361a3861e5
Reviewed-on: https://go-review.googlesource.com/109115
Reviewed-by: Peter Weinberger <pjw@google.com>

diff --git a/src/runtime/trace/annotation.go b/src/runtime/trace/annotation.go
index 0261d1c1628d7bc7c5dc5688b278ffdb9a21dea4..1cf01165cce0bbc329c8fcb3576a39da6c5869cb 100644 (file)
--- a/src/runtime/trace/annotation.go
+++ b/src/runtime/trace/annotation.go
@@ -158,6 +158,9 @@ func WithSpan(ctx context.Context, spanType string, fn func(ctx context.Context)
 //     defer trace.StartRegion(ctx, "myTracedRegion").End()
 //
 func StartRegion(ctx context.Context, regionType string) *Region {
+       if !IsEnabled() {
+               return noopRegion
+       }
        id := fromContext(ctx).id
        userRegion(id, regionStartCode, regionType)
        return &Region{id, regionType}
@@ -175,8 +178,13 @@ type Region struct {
        regionType string
 }
 
+var noopRegion = &Region{}
+
 // End marks the end of the traced code region.
 func (r *Region) End() {
+       if r == noopRegion {
+               return
+       }
        userRegion(r.id, regionEndCode, r.regionType)
 }
 

diff --git a/src/runtime/trace/annotation_test.go b/src/runtime/trace/annotation_test.go
index c20b009daa511ae4a33b33b5bb68b32bf3cf6b26..71abbfcfa631327dbee2ae3a1957472195f10cbc 100644 (file)
--- a/src/runtime/trace/annotation_test.go
+++ b/src/runtime/trace/annotation_test.go
@@ -12,7 +12,35 @@ import (
        "testing"
 )
 
+func BenchmarkStartRegion(b *testing.B) {
+       b.ReportAllocs()
+       ctx, task := NewTask(context.Background(), "benchmark")
+       defer task.End()
+
+       b.RunParallel(func(pb *testing.PB) {
+               for pb.Next() {
+                       StartRegion(ctx, "region").End()
+               }
+       })
+}
+
+func BenchmarkNewTask(b *testing.B) {
+       b.ReportAllocs()
+       pctx, task := NewTask(context.Background(), "benchmark")
+       defer task.End()
+
+       b.RunParallel(func(pb *testing.PB) {
+               for pb.Next() {
+                       _, task := NewTask(pctx, "task")
+                       task.End()
+               }
+       })
+}
+
 func TestUserTaskRegion(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        bgctx, cancel := context.WithCancel(context.Background())
        defer cancel()
 
@@ -107,7 +135,8 @@ func TestUserTaskRegion(t *testing.T) {
                {trace.EvUserRegion, []string{"task0", "region1"}, []uint64{1}, false},
                {trace.EvUserRegion, []string{"task0", "region0"}, []uint64{1}, false},
                {trace.EvUserTaskEnd, []string{"task0"}, nil, false},
-               {trace.EvUserRegion, []string{"", "pre-existing region"}, []uint64{1}, false},
+               //  Currently, pre-existing region is not recorded to avoid allocations.
+               //  {trace.EvUserRegion, []string{"", "pre-existing region"}, []uint64{1}, false},
                {trace.EvUserRegion, []string{"", "post-existing region"}, []uint64{0}, false},
        }
        if !reflect.DeepEqual(got, want) {

diff --git a/src/runtime/trace/trace_stack_test.go b/src/runtime/trace/trace_stack_test.go
index e7b8d5765918e68dcfe8b775b7778d382c3da11e..62c06e67d9d37436ec34c5469f5eb01f6eff63fa 100644 (file)
--- a/src/runtime/trace/trace_stack_test.go
+++ b/src/runtime/trace/trace_stack_test.go
@@ -24,7 +24,7 @@ import (
 // In particular that we strip bottom uninteresting frames like goexit,
 // top uninteresting frames (runtime guts).
 func TestTraceSymbolize(t *testing.T) {
-       testenv.MustHaveGoBuild(t)
+       skipTraceSymbolizeTestIfNecessary(t)
 
        buf := new(bytes.Buffer)
        if err := Start(buf); err != nil {
@@ -285,6 +285,13 @@ func TestTraceSymbolize(t *testing.T) {
        }
 }
 
+func skipTraceSymbolizeTestIfNecessary(t *testing.T) {
+       testenv.MustHaveGoBuild(t)
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
+}
+
 func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
        matched := 0
        o := new(bytes.Buffer)

diff --git a/src/runtime/trace/trace_test.go b/src/runtime/trace/trace_test.go
index 997d486c65ad50ecd92b5f9564da83ead2f7087d..f289bd6f85811a04c5bb21729ba8c7c079e628c9 100644 (file)
--- a/src/runtime/trace/trace_test.go
+++ b/src/runtime/trace/trace_test.go
@@ -31,6 +31,9 @@ func TestEventBatch(t *testing.T) {
        if race.Enabled {
                t.Skip("skipping in race mode")
        }
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        if testing.Short() {
                t.Skip("skipping in short mode")
        }
@@ -81,6 +84,9 @@ func TestEventBatch(t *testing.T) {
 }
 
 func TestTraceStartStop(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        buf := new(bytes.Buffer)
        if err := Start(buf); err != nil {
                t.Fatalf("failed to start tracing: %v", err)
@@ -98,6 +104,9 @@ func TestTraceStartStop(t *testing.T) {
 }
 
 func TestTraceDoubleStart(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        Stop()
        buf := new(bytes.Buffer)
        if err := Start(buf); err != nil {
@@ -111,6 +120,9 @@ func TestTraceDoubleStart(t *testing.T) {
 }
 
 func TestTrace(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        buf := new(bytes.Buffer)
        if err := Start(buf); err != nil {
                t.Fatalf("failed to start tracing: %v", err)
@@ -168,6 +180,9 @@ func testBrokenTimestamps(t *testing.T, data []byte) {
 }
 
 func TestTraceStress(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        var wg sync.WaitGroup
        done := make(chan bool)
 
@@ -307,6 +322,9 @@ func TestTraceStress(t *testing.T) {
 // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
 // And concurrently with all that start/stop trace 3 times.
 func TestTraceStressStartStop(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
        outerDone := make(chan bool)
 
@@ -454,6 +472,9 @@ func TestTraceStressStartStop(t *testing.T) {
 }
 
 func TestTraceFutileWakeup(t *testing.T) {
+       if IsEnabled() {
+               t.Skip("skipping because -test.trace is set")
+       }
        buf := new(bytes.Buffer)
        if err := Start(buf); err != nil {
                t.Fatalf("failed to start tracing: %v", err)