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