1 files changed, 392 insertions, 0 deletions
diff --git a/src/cmd/trace/annotations_test.go b/src/cmd/trace/annotations_test.go
new file mode 100644
index 0000000..9c2d027
--- /dev/null
+++ b/src/cmd/trace/annotations_test.go
@@ -0,0 +1,392 @@
+// 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"
+	traceparser "internal/trace"
+	"os"
+	"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.Parse(buf, name+".faketrace")
+	if err == traceparser.ErrTimeOrder {
+		t.Skipf("skipping due to golang.org/issue/16755: %v", err)
+	} else 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.ParseResult, err error) {
+	// swap loader's data.
+	parseTrace() // fool loader.once.
+
+	loader.res = res
+	loader.err = err
+
+	analyzeGoroutines(nil) // fool gsInit once.
+	gs = traceparser.GoroutineStats(res.Events)
+
+}
+
+func saveTrace(buf *bytes.Buffer, name string) {
+	if !*saveTraces {
+		return
+	}
+	if err := os.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
+		panic(fmt.Errorf("failed to write trace file: %v", err))
+	}
+}