annotations_test.go

Documentation: cmd/trace

     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  }
   397
View as plain text