src/runtime/trace/annotation_test.go

   1 // Copyright 2018 The Go Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style
   3 // license that can be found in the LICENSE file.
   4
   5 package trace_test
   6
   7 import (
   8         "bytes"
   9         "context"
  10         "fmt"
  11         "internal/trace"
  12         "reflect"
  13         . "runtime/trace"
  14         "strings"
  15         "sync"
  16         "testing"
  17 )
  18
  19 func BenchmarkStartRegion(b *testing.B) {
  20         b.ReportAllocs()
  21         ctx, task := NewTask(context.Background(), "benchmark")
  22         defer task.End()
  23
  24         b.RunParallel(func(pb *testing.PB) {
  25                 for pb.Next() {
  26                         StartRegion(ctx, "region").End()
  27                 }
  28         })
  29 }
  30
  31 func BenchmarkNewTask(b *testing.B) {
  32         b.ReportAllocs()
  33         pctx, task := NewTask(context.Background(), "benchmark")
  34         defer task.End()
  35
  36         b.RunParallel(func(pb *testing.PB) {
  37                 for pb.Next() {
  38                         _, task := NewTask(pctx, "task")
  39                         task.End()
  40                 }
  41         })
  42 }
  43
  44 func TestUserTaskRegion(t *testing.T) {
  45         if IsEnabled() {
  46                 t.Skip("skipping because -test.trace is set")
  47         }
  48         bgctx, cancel := context.WithCancel(context.Background())
  49         defer cancel()
  50
  51         preExistingRegion := StartRegion(bgctx, "pre-existing region")
  52
  53         buf := new(bytes.Buffer)
  54         if err := Start(buf); err != nil {
  55                 t.Fatalf("failed to start tracing: %v", err)
  56         }
  57
  58         // Beginning of traced execution
  59         var wg sync.WaitGroup
  60         ctx, task := NewTask(bgctx, "task0") // EvUserTaskCreate("task0")
  61         wg.Add(1)
  62         go func() {
  63                 defer wg.Done()
  64                 defer task.End() // EvUserTaskEnd("task0")
  65
  66                 WithRegion(ctx, "region0", func() {
  67                         // EvUserRegionCreate("region0", start)
  68                         WithRegion(ctx, "region1", func() {
  69                                 Log(ctx, "key0", "0123456789abcdef") // EvUserLog("task0", "key0", "0....f")
  70                         })
  71                         // EvUserRegion("region0", end)
  72                 })
  73         }()
  74
  75         wg.Wait()
  76
  77         preExistingRegion.End()
  78         postExistingRegion := StartRegion(bgctx, "post-existing region")
  79
  80         // End of traced execution
  81         Stop()
  82
  83         postExistingRegion.End()
  84
  85         saveTrace(t, buf, "TestUserTaskRegion")
  86         res, err := trace.Parse(buf, "")
  87         if err == trace.ErrTimeOrder {
  88                 // golang.org/issues/16755
  89                 t.Skipf("skipping trace: %v", err)
  90         }
  91         if err != nil {
  92                 t.Fatalf("Parse failed: %v", err)
  93         }
  94
  95         // Check whether we see all user annotation related records in order
  96         type testData struct {
  97                 typ     byte
  98                 strs    []string
  99                 args    []uint64
 100                 setLink bool
 101         }
 102
 103         var got []testData
 104         tasks := map[uint64]string{}
 105         for _, e := range res.Events {
 106                 t.Logf("%s", e)
 107                 switch e.Type {
 108                 case trace.EvUserTaskCreate:
 109                         taskName := e.SArgs[0]
 110                         got = append(got, testData{trace.EvUserTaskCreate, []string{taskName}, nil, e.Link != nil})
 111                         if e.Link != nil && e.Link.Type != trace.EvUserTaskEnd {
 112                                 t.Errorf("Unexpected linked event %q->%q", e, e.Link)
 113                         }
 114                         tasks[e.Args[0]] = taskName
 115                 case trace.EvUserLog:
 116                         key, val := e.SArgs[0], e.SArgs[1]
 117                         taskName := tasks[e.Args[0]]
 118                         got = append(got, testData{trace.EvUserLog, []string{taskName, key, val}, nil, e.Link != nil})
 119                 case trace.EvUserTaskEnd:
 120                         taskName := tasks[e.Args[0]]
 121                         got = append(got, testData{trace.EvUserTaskEnd, []string{taskName}, nil, e.Link != nil})
 122                         if e.Link != nil && e.Link.Type != trace.EvUserTaskCreate {
 123                                 t.Errorf("Unexpected linked event %q->%q", e, e.Link)
 124                         }
 125                 case trace.EvUserRegion:
 126                         taskName := tasks[e.Args[0]]
 127                         regionName := e.SArgs[0]
 128                         got = append(got, testData{trace.EvUserRegion, []string{taskName, regionName}, []uint64{e.Args[1]}, e.Link != nil})
 129                         if e.Link != nil && (e.Link.Type != trace.EvUserRegion || e.Link.SArgs[0] != regionName) {
 130                                 t.Errorf("Unexpected linked event %q->%q", e, e.Link)
 131                         }
 132                 }
 133         }
 134         want := []testData{
 135                 {trace.EvUserTaskCreate, []string{"task0"}, nil, true},
 136                 {trace.EvUserRegion, []string{"task0", "region0"}, []uint64{0}, true},
 137                 {trace.EvUserRegion, []string{"task0", "region1"}, []uint64{0}, true},
 138                 {trace.EvUserLog, []string{"task0", "key0", "0123456789abcdef"}, nil, false},
 139                 {trace.EvUserRegion, []string{"task0", "region1"}, []uint64{1}, false},
 140                 {trace.EvUserRegion, []string{"task0", "region0"}, []uint64{1}, false},
 141                 {trace.EvUserTaskEnd, []string{"task0"}, nil, false},
 142                 //  Currently, pre-existing region is not recorded to avoid allocations.
 143                 //  {trace.EvUserRegion, []string{"", "pre-existing region"}, []uint64{1}, false},
 144                 {trace.EvUserRegion, []string{"", "post-existing region"}, []uint64{0}, false},
 145         }
 146         if !reflect.DeepEqual(got, want) {
 147                 pretty := func(data []testData) string {
 148                         var s strings.Builder
 149                         for _, d := range data {
 150                                 fmt.Fprintf(&s, "\t%+v\n", d)
 151                         }
 152                         return s.String()
 153                 }
 154                 t.Errorf("Got user region related events\n%+v\nwant:\n%+v", pretty(got), pretty(want))
 155         }
 156 }