src/cmd/trace/annotations_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 //go:build !js
   6
   7 package main
   8
   9 import (
  10         "bytes"
  11         "context"
  12         "flag"
  13         "fmt"
  14         "internal/goexperiment"
  15         traceparser "internal/trace"
  16         "os"
  17         "reflect"
  18         "runtime/debug"
  19         "runtime/trace"
  20         "sort"
  21         "sync"
  22         "testing"
  23         "time"
  24 )
  25
  26 var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
  27
  28 func TestOverlappingDuration(t *testing.T) {
  29         cases := []struct {
  30                 start0, end0, start1, end1 int64
  31                 want                       time.Duration
  32         }{
  33                 {
  34                         1, 10, 11, 20, 0,
  35                 },
  36                 {
  37                         1, 10, 5, 20, 5 * time.Nanosecond,
  38                 },
  39                 {
  40                         1, 10, 2, 8, 6 * time.Nanosecond,
  41                 },
  42         }
  43
  44         for _, tc := range cases {
  45                 s0, e0, s1, e1 := tc.start0, tc.end0, tc.start1, tc.end1
  46                 if got := overlappingDuration(s0, e0, s1, e1); got != tc.want {
  47                         t.Errorf("overlappingDuration(%d, %d, %d, %d)=%v; want %v", s0, e0, s1, e1, got, tc.want)
  48                 }
  49                 if got := overlappingDuration(s1, e1, s0, e0); got != tc.want {
  50                         t.Errorf("overlappingDuration(%d, %d, %d, %d)=%v; want %v", s1, e1, s0, e0, got, tc.want)
  51                 }
  52         }
  53 }
  54
  55 // prog0 starts three goroutines.
  56 //
  57 //      goroutine 1: taskless region
  58 //      goroutine 2: starts task0, do work in task0.region0, starts task1 which ends immediately.
  59 //      goroutine 3: do work in task0.region1 and task0.region2, ends task0
  60 func prog0() {
  61         ctx := context.Background()
  62
  63         var wg sync.WaitGroup
  64
  65         wg.Add(1)
  66         go func() { // goroutine 1
  67                 defer wg.Done()
  68                 trace.WithRegion(ctx, "taskless.region", func() {
  69                         trace.Log(ctx, "key0", "val0")
  70                 })
  71         }()
  72
  73         wg.Add(1)
  74         go func() { // goroutine 2
  75                 defer wg.Done()
  76                 ctx, task := trace.NewTask(ctx, "task0")
  77                 trace.WithRegion(ctx, "task0.region0", func() {
  78                         wg.Add(1)
  79                         go func() { // goroutine 3
  80                                 defer wg.Done()
  81                                 defer task.End()
  82                                 trace.WithRegion(ctx, "task0.region1", func() {
  83                                         trace.WithRegion(ctx, "task0.region2", func() {
  84                                                 trace.Log(ctx, "key2", "val2")
  85                                         })
  86                                         trace.Log(ctx, "key1", "val1")
  87                                 })
  88                         }()
  89                 })
  90                 ctx2, task2 := trace.NewTask(ctx, "task1")
  91                 trace.Log(ctx2, "key3", "val3")
  92                 task2.End()
  93         }()
  94         wg.Wait()
  95 }
  96
  97 func TestAnalyzeAnnotations(t *testing.T) {
  98         // TODO: classify taskless regions
  99
 100         // Run prog0 and capture the execution trace.
 101         if err := traceProgram(t, prog0, "TestAnalyzeAnnotations"); err != nil {
 102                 t.Fatalf("failed to trace the program: %v", err)
 103         }
 104
 105         res, err := analyzeAnnotations()
 106         if err != nil {
 107                 t.Fatalf("failed to analyzeAnnotations: %v", err)
 108         }
 109
 110         // For prog0, we expect
 111         //   - task with name = "task0", with three regions.
 112         //   - task with name = "task1", with no region.
 113         wantTasks := map[string]struct {
 114                 complete   bool
 115                 goroutines int
 116                 regions    []string
 117         }{
 118                 "task0": {
 119                         complete:   true,
 120                         goroutines: 2,
 121                         regions:    []string{"task0.region0", "", "task0.region1", "task0.region2"},
 122                 },
 123                 "task1": {
 124                         complete:   true,
 125                         goroutines: 1,
 126                 },
 127         }
 128
 129         for _, task := range res.tasks {
 130                 want, ok := wantTasks[task.name]
 131                 if !ok {
 132                         t.Errorf("unexpected task: %s", task)
 133                         continue
 134                 }
 135                 if task.complete() != want.complete || len(task.goroutines) != want.goroutines || !reflect.DeepEqual(regionNames(task), want.regions) {
 136                         t.Errorf("got task %v; want %+v", task, want)
 137                 }
 138
 139                 delete(wantTasks, task.name)
 140         }
 141         if len(wantTasks) > 0 {
 142                 t.Errorf("no more tasks; want %+v", wantTasks)
 143         }
 144
 145         wantRegions := []string{
 146                 "", // an auto-created region for the goroutine 3
 147                 "taskless.region",
 148                 "task0.region0",
 149                 "task0.region1",
 150                 "task0.region2",
 151         }
 152         var gotRegions []string
 153         for regionID := range res.regions {
 154                 gotRegions = append(gotRegions, regionID.Type)
 155         }
 156
 157         sort.Strings(wantRegions)
 158         sort.Strings(gotRegions)
 159         if !reflect.DeepEqual(gotRegions, wantRegions) {
 160                 t.Errorf("got regions %q, want regions %q", gotRegions, wantRegions)
 161         }
 162 }
 163
 164 // prog1 creates a task hierarchy consisting of three tasks.
 165 func prog1() {
 166         ctx := context.Background()
 167         ctx1, task1 := trace.NewTask(ctx, "task1")
 168         defer task1.End()
 169         trace.WithRegion(ctx1, "task1.region", func() {
 170                 ctx2, task2 := trace.NewTask(ctx1, "task2")
 171                 defer task2.End()
 172                 trace.WithRegion(ctx2, "task2.region", func() {
 173                         ctx3, task3 := trace.NewTask(ctx2, "task3")
 174                         defer task3.End()
 175                         trace.WithRegion(ctx3, "task3.region", func() {
 176                         })
 177                 })
 178         })
 179 }
 180
 181 func TestAnalyzeAnnotationTaskTree(t *testing.T) {
 182         // Run prog1 and capture the execution trace.
 183         if err := traceProgram(t, prog1, "TestAnalyzeAnnotationTaskTree"); err != nil {
 184                 t.Fatalf("failed to trace the program: %v", err)
 185         }
 186
 187         res, err := analyzeAnnotations()
 188         if err != nil {
 189                 t.Fatalf("failed to analyzeAnnotations: %v", err)
 190         }
 191         tasks := res.tasks
 192
 193         // For prog0, we expect
 194         //   - task with name = "", with taskless.region in regions.
 195         //   - task with name = "task0", with three regions.
 196         wantTasks := map[string]struct {
 197                 parent   string
 198                 children []string
 199                 regions  []string
 200         }{
 201                 "task1": {
 202                         parent:   "",
 203                         children: []string{"task2"},
 204                         regions:  []string{"task1.region"},
 205                 },
 206                 "task2": {
 207                         parent:   "task1",
 208                         children: []string{"task3"},
 209                         regions:  []string{"task2.region"},
 210                 },
 211                 "task3": {
 212                         parent:   "task2",
 213                         children: nil,
 214                         regions:  []string{"task3.region"},
 215                 },
 216         }
 217
 218         for _, task := range tasks {
 219                 want, ok := wantTasks[task.name]
 220                 if !ok {
 221                         t.Errorf("unexpected task: %s", task)
 222                         continue
 223                 }
 224                 delete(wantTasks, task.name)
 225
 226                 if parentName(task) != want.parent ||
 227                         !reflect.DeepEqual(childrenNames(task), want.children) ||
 228                         !reflect.DeepEqual(regionNames(task), want.regions) {
 229                         t.Errorf("got %v; want %+v", task, want)
 230                 }
 231         }
 232
 233         if len(wantTasks) > 0 {
 234                 t.Errorf("no more tasks; want %+v", wantTasks)
 235         }
 236 }
 237
 238 // prog2 starts two tasks; "taskWithGC" that overlaps with GC
 239 // and "taskWithoutGC" that doesn't. In order to run this reliably,
 240 // the caller needs to set up to prevent GC from running automatically.
 241 // prog2 returns the upper-bound gc time that overlaps with the first task.
 242 func prog2() (gcTime time.Duration) {
 243         ch := make(chan bool)
 244         ctx1, task := trace.NewTask(context.Background(), "taskWithGC")
 245         trace.WithRegion(ctx1, "taskWithGC.region1", func() {
 246                 go func() {
 247                         defer trace.StartRegion(ctx1, "taskWithGC.region2").End()
 248                         <-ch
 249                 }()
 250                 s := time.Now()
 251                 debug.FreeOSMemory() // task1 affected by gc
 252                 gcTime = time.Since(s)
 253                 close(ch)
 254         })
 255         task.End()
 256
 257         ctx2, task2 := trace.NewTask(context.Background(), "taskWithoutGC")
 258         trace.WithRegion(ctx2, "taskWithoutGC.region1", func() {
 259                 // do nothing.
 260         })
 261         task2.End()
 262         return gcTime
 263 }
 264
 265 func TestAnalyzeAnnotationGC(t *testing.T) {
 266         err := traceProgram(t, func() {
 267                 oldGC := debug.SetGCPercent(10000) // gc, and effectively disable GC
 268                 defer debug.SetGCPercent(oldGC)
 269                 prog2()
 270         }, "TestAnalyzeAnnotationGC")
 271         if err != nil {
 272                 t.Fatalf("failed to trace the program: %v", err)
 273         }
 274
 275         res, err := analyzeAnnotations()
 276         if err != nil {
 277                 t.Fatalf("failed to analyzeAnnotations: %v", err)
 278         }
 279
 280         // Check collected GC Start events are all sorted and non-overlapping.
 281         lastTS := int64(0)
 282         for i, ev := range res.gcEvents {
 283                 if ev.Type != traceparser.EvGCStart {
 284                         t.Errorf("unwanted event in gcEvents: %v", ev)
 285                 }
 286                 if i > 0 && lastTS > ev.Ts {
 287                         t.Errorf("overlapping GC events:\n%d: %v\n%d: %v", i-1, res.gcEvents[i-1], i, res.gcEvents[i])
 288                 }
 289                 if ev.Link != nil {
 290                         lastTS = ev.Link.Ts
 291                 }
 292         }
 293
 294         // Check whether only taskWithGC reports overlapping duration.
 295         for _, task := range res.tasks {
 296                 got := task.overlappingGCDuration(res.gcEvents)
 297                 switch task.name {
 298                 case "taskWithoutGC":
 299                         if got != 0 {
 300                                 t.Errorf("%s reported %v as overlapping GC time; want 0: %v", task.name, got, task)
 301                         }
 302                 case "taskWithGC":
 303                         upperBound := task.duration()
 304                         // TODO(hyangah): a tighter upper bound is gcTime, but
 305                         // use of it will make the test flaky due to the issue
 306                         // described in golang.org/issue/16755. Tighten the upper
 307                         // bound when the issue with the timestamp computed
 308                         // based on clockticks is resolved.
 309                         if got <= 0 || got > upperBound {
 310                                 t.Errorf("%s reported %v as overlapping GC time; want (0, %v):\n%v", task.name, got, upperBound, task)
 311                                 buf := new(bytes.Buffer)
 312                                 fmt.Fprintln(buf, "GC Events")
 313                                 for _, ev := range res.gcEvents {
 314                                         fmt.Fprintf(buf, " %s -> %s\n", ev, ev.Link)
 315                                 }
 316                                 fmt.Fprintln(buf, "Events in Task")
 317                                 for i, ev := range task.events {
 318                                         fmt.Fprintf(buf, " %d: %s\n", i, ev)
 319                                 }
 320
 321                                 t.Logf("\n%s", buf)
 322                         }
 323                 }
 324         }
 325 }
 326
 327 // traceProgram runs the provided function while tracing is enabled,
 328 // parses the captured trace, and sets the global trace loader to
 329 // point to the parsed trace.
 330 //
 331 // If savetraces flag is set, the captured trace will be saved in the named file.
 332 func traceProgram(t *testing.T, f func(), name string) error {
 333         t.Helper()
 334         if goexperiment.ExecTracer2 {
 335                 t.Skip("skipping because test programs are covered elsewhere for the new tracer")
 336         }
 337         buf := new(bytes.Buffer)
 338         if err := trace.Start(buf); err != nil {
 339                 return err
 340         }
 341         f()
 342         trace.Stop()
 343
 344         saveTrace(buf, name)
 345         res, err := traceparser.Parse(buf, name+".faketrace")
 346         if err == traceparser.ErrTimeOrder {
 347                 t.Skipf("skipping due to golang.org/issue/16755: %v", err)
 348         } else if err != nil {
 349                 return err
 350         }
 351
 352         swapLoaderData(res, err)
 353         return nil
 354 }
 355
 356 func regionNames(task *taskDesc) (ret []string) {
 357         for _, s := range task.regions {
 358                 ret = append(ret, s.Name)
 359         }
 360         return ret
 361 }
 362
 363 func parentName(task *taskDesc) string {
 364         if task.parent != nil {
 365                 return task.parent.name
 366         }
 367         return ""
 368 }
 369
 370 func childrenNames(task *taskDesc) (ret []string) {
 371         for _, s := range task.children {
 372                 ret = append(ret, s.name)
 373         }
 374         return ret
 375 }
 376
 377 func swapLoaderData(res traceparser.ParseResult, err error) {
 378         // swap loader's data.
 379         parseTrace() // fool loader.once.
 380
 381         loader.res = res
 382         loader.err = err
 383
 384         analyzeGoroutines(nil) // fool gsInit once.
 385         gs = traceparser.GoroutineStats(res.Events)
 386
 387 }
 388
 389 func saveTrace(buf *bytes.Buffer, name string) {
 390         if !*saveTraces {
 391                 return
 392         }
 393         if err := os.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
 394                 panic(fmt.Errorf("failed to write trace file: %v", err))
 395         }
 396 }