| // 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)) |
| } |
| } |