go/src/cmd/trace/annotations_test.go

// Copyright 2018 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

// +build !js

package main

import (
	"bytes"
	"context"
	"flag"
	"fmt"
	"internal/traceparser"
	"io/ioutil"
	"reflect"
	"runtime/debug"
	"runtime/trace"
	"sort"
	"sync"
	"testing"
	"time"
)

var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")

func TestOverlappingDuration(t *testing.T) {
	cases := []struct {
		start0, end0, start1, end1 int64
		want                       time.Duration
	}{
		{
			1, 10, 11, 20, 0,
		},
		{
			1, 10, 5, 20, 5 * time.Nanosecond,
		},
		{
			1, 10, 2, 8, 6 * time.Nanosecond,
		},
	}

	for _, tc := range cases {
		s0, e0, s1, e1 := tc.start0, tc.end0, tc.start1, tc.end1
		if got := overlappingDuration(s0, e0, s1, e1); got != tc.want {
			t.Errorf("overlappingDuration(%d, %d, %d, %d)=%v; want %v", s0, e0, s1, e1, got, tc.want)
		}
		if got := overlappingDuration(s1, e1, s0, e0); got != tc.want {
			t.Errorf("overlappingDuration(%d, %d, %d, %d)=%v; want %v", s1, e1, s0, e0, got, tc.want)
		}
	}
}

// prog0 starts three goroutines.
//
//   goroutine 1: taskless region
//   goroutine 2: starts task0, do work in task0.region0, starts task1 which ends immediately.
//   goroutine 3: do work in task0.region1 and task0.region2, ends task0
func prog0() {
	ctx := context.Background()

	var wg sync.WaitGroup

	wg.Add(1)
	go func() { // goroutine 1
		defer wg.Done()
		trace.WithRegion(ctx, "taskless.region", func() {
			trace.Log(ctx, "key0", "val0")
		})
	}()

	wg.Add(1)
	go func() { // goroutine 2
		defer wg.Done()
		ctx, task := trace.NewTask(ctx, "task0")
		trace.WithRegion(ctx, "task0.region0", func() {
			wg.Add(1)
			go func() { // goroutine 3
				defer wg.Done()
				defer task.End()
				trace.WithRegion(ctx, "task0.region1", func() {
					trace.WithRegion(ctx, "task0.region2", func() {
						trace.Log(ctx, "key2", "val2")
					})
					trace.Log(ctx, "key1", "val1")
				})
			}()
		})
		ctx2, task2 := trace.NewTask(ctx, "task1")
		trace.Log(ctx2, "key3", "val3")
		task2.End()
	}()
	wg.Wait()
}

func TestAnalyzeAnnotations(t *testing.T) {
	// TODO: classify taskless regions

	// Run prog0 and capture the execution trace.
	if err := traceProgram(t, prog0, "TestAnalyzeAnnotations"); err != nil {
		t.Fatalf("failed to trace the program: %v", err)
	}

	res, err := analyzeAnnotations()
	if err != nil {
		t.Fatalf("failed to analyzeAnnotations: %v", err)
	}

	// For prog0, we expect
	//   - task with name = "task0", with three regions.
	//   - task with name = "task1", with no region.
	wantTasks := map[string]struct {
		complete   bool
		goroutines int
		regions    []string
	}{
		"task0": {
			complete:   true,
			goroutines: 2,
			regions:    []string{"task0.region0", "", "task0.region1", "task0.region2"},
		},
		"task1": {
			complete:   true,
			goroutines: 1,
		},
	}

	for _, task := range res.tasks {
		want, ok := wantTasks[task.name]
		if !ok {
			t.Errorf("unexpected task: %s", task)
			continue
		}
		if task.complete() != want.complete || len(task.goroutines) != want.goroutines || !reflect.DeepEqual(regionNames(task), want.regions) {
			t.Errorf("got task %v; want %+v", task, want)
		}

		delete(wantTasks, task.name)
	}
	if len(wantTasks) > 0 {
		t.Errorf("no more tasks; want %+v", wantTasks)
	}

	wantRegions := []string{
		"", // an auto-created region for the goroutine 3
		"taskless.region",
		"task0.region0",
		"task0.region1",
		"task0.region2",
	}
	var gotRegions []string
	for regionID := range res.regions {
		gotRegions = append(gotRegions, regionID.Type)
	}

	sort.Strings(wantRegions)
	sort.Strings(gotRegions)
	if !reflect.DeepEqual(gotRegions, wantRegions) {
		t.Errorf("got regions %q, want regions %q", gotRegions, wantRegions)
	}
}

// prog1 creates a task hierarchy consisting of three tasks.
func prog1() {
	ctx := context.Background()
	ctx1, task1 := trace.NewTask(ctx, "task1")
	defer task1.End()
	trace.WithRegion(ctx1, "task1.region", func() {
		ctx2, task2 := trace.NewTask(ctx1, "task2")
		defer task2.End()
		trace.WithRegion(ctx2, "task2.region", func() {
			ctx3, task3 := trace.NewTask(ctx2, "task3")
			defer task3.End()
			trace.WithRegion(ctx3, "task3.region", func() {
			})
		})
	})
}

func TestAnalyzeAnnotationTaskTree(t *testing.T) {
	// Run prog1 and capture the execution trace.
	if err := traceProgram(t, prog1, "TestAnalyzeAnnotationTaskTree"); err != nil {
		t.Fatalf("failed to trace the program: %v", err)
	}

	res, err := analyzeAnnotations()
	if err != nil {
		t.Fatalf("failed to analyzeAnnotations: %v", err)
	}
	tasks := res.tasks

	// For prog0, we expect
	//   - task with name = "", with taskless.region in regions.
	//   - task with name = "task0", with three regions.
	wantTasks := map[string]struct {
		parent   string
		children []string
		regions  []string
	}{
		"task1": {
			parent:   "",
			children: []string{"task2"},
			regions:  []string{"task1.region"},
		},
		"task2": {
			parent:   "task1",
			children: []string{"task3"},
			regions:  []string{"task2.region"},
		},
		"task3": {
			parent:   "task2",
			children: nil,
			regions:  []string{"task3.region"},
		},
	}

	for _, task := range tasks {
		want, ok := wantTasks[task.name]
		if !ok {
			t.Errorf("unexpected task: %s", task)
			continue
		}
		delete(wantTasks, task.name)

		if parentName(task) != want.parent ||
			!reflect.DeepEqual(childrenNames(task), want.children) ||
			!reflect.DeepEqual(regionNames(task), want.regions) {
			t.Errorf("got %v; want %+v", task, want)
		}
	}

	if len(wantTasks) > 0 {
		t.Errorf("no more tasks; want %+v", wantTasks)
	}
}

// prog2 starts two tasks; "taskWithGC" that overlaps with GC
// and "taskWithoutGC" that doesn't. In order to run this reliably,
// the caller needs to set up to prevent GC from running automatically.
// prog2 returns the upper-bound gc time that overlaps with the first task.
func prog2() (gcTime time.Duration) {
	ch := make(chan bool)
	ctx1, task := trace.NewTask(context.Background(), "taskWithGC")
	trace.WithRegion(ctx1, "taskWithGC.region1", func() {
		go func() {
			defer trace.StartRegion(ctx1, "taskWithGC.region2").End()
			<-ch
		}()
		s := time.Now()
		debug.FreeOSMemory() // task1 affected by gc
		gcTime = time.Since(s)
		close(ch)
	})
	task.End()

	ctx2, task2 := trace.NewTask(context.Background(), "taskWithoutGC")
	trace.WithRegion(ctx2, "taskWithoutGC.region1", func() {
		// do nothing.
	})
	task2.End()
	return gcTime
}

func TestAnalyzeAnnotationGC(t *testing.T) {
	err := traceProgram(t, func() {
		oldGC := debug.SetGCPercent(10000) // gc, and effectively disable GC
		defer debug.SetGCPercent(oldGC)
		prog2()
	}, "TestAnalyzeAnnotationGC")
	if err != nil {
		t.Fatalf("failed to trace the program: %v", err)
	}

	res, err := analyzeAnnotations()
	if err != nil {
		t.Fatalf("failed to analyzeAnnotations: %v", err)
	}

	// Check collected GC Start events are all sorted and non-overlapping.
	lastTS := int64(0)
	for i, ev := range res.gcEvents {
		if ev.Type != traceparser.EvGCStart {
			t.Errorf("unwanted event in gcEvents: %v", ev)
		}
		if i > 0 && lastTS > ev.Ts {
			t.Errorf("overlapping GC events:\n%d: %v\n%d: %v", i-1, res.gcEvents[i-1], i, res.gcEvents[i])
		}
		if ev.Link != nil {
			lastTS = ev.Link.Ts
		}
	}

	// Check whether only taskWithGC reports overlapping duration.
	for _, task := range res.tasks {
		got := task.overlappingGCDuration(res.gcEvents)
		switch task.name {
		case "taskWithoutGC":
			if got != 0 {
				t.Errorf("%s reported %v as overlapping GC time; want 0: %v", task.name, got, task)
			}
		case "taskWithGC":
			upperBound := task.duration()
			// TODO(hyangah): a tighter upper bound is gcTime, but
			// use of it will make the test flaky due to the issue
			// described in golang.org/issue/16755. Tighten the upper
			// bound when the issue with the timestamp computed
			// based on clockticks is resolved.
			if got <= 0 || got > upperBound {
				t.Errorf("%s reported %v as overlapping GC time; want (0, %v):\n%v", task.name, got, upperBound, task)
				buf := new(bytes.Buffer)
				fmt.Fprintln(buf, "GC Events")
				for _, ev := range res.gcEvents {
					fmt.Fprintf(buf, " %s -> %s\n", ev, ev.Link)
				}
				fmt.Fprintln(buf, "Events in Task")
				for i, ev := range task.events {
					fmt.Fprintf(buf, " %d: %s\n", i, ev)
				}

				t.Logf("\n%s", buf)
			}
		}
	}
}

// traceProgram runs the provided function while tracing is enabled,
// parses the captured trace, and sets the global trace loader to
// point to the parsed trace.
//
// If savetraces flag is set, the captured trace will be saved in the named file.
func traceProgram(t *testing.T, f func(), name string) error {
	t.Helper()
	buf := new(bytes.Buffer)
	if err := trace.Start(buf); err != nil {
		return err
	}
	f()
	trace.Stop()

	saveTrace(buf, name)
	res, err := traceparser.ParseBuffer(buf)
	if err != nil {
		return err
	}

	swapLoaderData(res, err)
	return nil
}

func regionNames(task *taskDesc) (ret []string) {
	for _, s := range task.regions {
		ret = append(ret, s.Name)
	}
	return ret
}

func parentName(task *taskDesc) string {
	if task.parent != nil {
		return task.parent.name
	}
	return ""
}

func childrenNames(task *taskDesc) (ret []string) {
	for _, s := range task.children {
		ret = append(ret, s.name)
	}
	return ret
}

func swapLoaderData(res *traceparser.Parsed, err error) {
	// swap loader's data.
	parseTrace() // fool loader.once.

	loader.res = res
	loader.err = err

	analyzeGoroutines(res) // fool gsInit once.
	gs = res.GoroutineStats()

}

func saveTrace(buf *bytes.Buffer, name string) {
	if !*saveTraces {
		return
	}
	if err := ioutil.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
		panic(fmt.Errorf("failed to write trace file: %v", err))
	}
}