Skip to content

Commit

Permalink
runtime, cmd/trace: remove code paths that include v1 tracer
Browse files Browse the repository at this point in the history 
This change makes the new execution tracer described in #60773, the
default tracer. This change attempts to make the smallest amount of
changes for a single CL.

Updates #66703
For #60773

Change-Id: I3742f3419c54f07d7c020ae5e1c18d29d8bcae6d
Reviewed-on: https://go-review.googlesource.com/c/go/+/576256
Reviewed-by: Michael Knyszek <mknyszek@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
  • Loading branch information
@cagedmantis
cagedmantis committed Apr 15, 2024
1 parent 8e987fa commit 2c5849d
Show file tree
Hide file tree
Showing 27 changed files with 68 additions and 3,974 deletions.
357 changes: 0 additions & 357 deletions src/cmd/trace/annotations_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,24 +7,10 @@
package main

import (
"bytes"
"context"
"flag"
"fmt"
"internal/goexperiment"
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
Expand All @@ -51,346 +37,3 @@ func TestOverlappingDuration(t *testing.T) {
}
}
}

// 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()
if goexperiment.ExecTracer2 {
t.Skip("skipping because test programs are covered elsewhere for the new tracer")
}
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))
}
}
Loading

0 comments on commit 2c5849d

Please sign in to comment.