Stowage/go
2
0
Fork 0
mirror of https://github.com/golang/go.git synced 2025-12-08 06:10:04 +00:00
Code Issues Projects Releases Packages Wiki Activity

runtime, cmd/trace: remove code paths that include v1 tracer

Browse source 
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>
This commit is contained in:
Carlos Amedee 2024-04-02 18:16:07 -04:00
parent 8e987fadb5
commit 2c5849dc40
27 changed files with 68 additions and 3974 deletions
Download patch file Download diff file Expand all files Collapse all files

357
src/cmd/trace/annotations_test.go
View file

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

92
src/cmd/trace/trace_test.go
View file

@ -7,16 +7,12 @@
package main
import (
"context"
"internal/trace"
"internal/trace/traceviewer"
"internal/trace/traceviewer/format"
"io"
rtrace "runtime/trace"
"strings"
"sync"
"testing"
"time"
)
// stacks is a fake stack map populated for test.
@ -180,91 +176,3 @@ func TestPreemptedMarkAssist(t *testing.T) {
t.Errorf("Got %v MARK ASSIST events, want %v", marks, 2)
}
}
func TestFoo(t *testing.T) {
prog0 := func() {
ctx, task := rtrace.NewTask(context.Background(), "ohHappyDay")
rtrace.Log(ctx, "", "log before task ends")
task.End()
rtrace.Log(ctx, "", "log after task ends") // log after task ends
}
if err := traceProgram(t, prog0, "TestFoo"); err != nil {
t.Fatalf("failed to trace the program: %v", err)
}
res, err := parseTrace()
if err != nil {
t.Fatalf("failed to parse the trace: %v", err)
}
annotRes, _ := analyzeAnnotations()
var task *taskDesc
for _, t := range annotRes.tasks {
if t.name == "ohHappyDay" {
task = t
break
}
}
if task == nil {
t.Fatal("failed to locate expected task event")
}
params := &traceParams{
parsed: res,
mode: traceviewer.ModeTaskOriented,
startTime: task.firstTimestamp() - 1,
endTime: task.lastTimestamp() + 1,
tasks: []*taskDesc{task},
}
c := traceviewer.ViewerDataTraceConsumer(io.Discard, 0, 1<<63-1)
var logBeforeTaskEnd, logAfterTaskEnd bool
c.ConsumeViewerEvent = func(ev *format.Event, _ bool) {
if ev.Name == "log before task ends" {
logBeforeTaskEnd = true
}
if ev.Name == "log after task ends" {
logAfterTaskEnd = true
}
}
if err := generateTrace(params, c); err != nil {
t.Fatalf("generateTrace failed: %v", err)
}
if !logBeforeTaskEnd {
t.Error("failed to find 'log before task ends'")
}
if !logAfterTaskEnd {
t.Error("failed to find 'log after task ends'")
}
}
func TestDirectSemaphoreHandoff(t *testing.T) {
prog0 := func() {
var mu sync.Mutex
var wg sync.WaitGroup
mu.Lock()
// This is modeled after src/sync/mutex_test.go to trigger Mutex
// starvation mode, in which the goroutine that calls Unlock hands off
// both the semaphore and its remaining time slice. See issue 36186.
for i := 0; i < 2; i++ {
wg.Add(1)
go func() {
defer wg.Done()
for i := 0; i < 100; i++ {
mu.Lock()
time.Sleep(100 * time.Microsecond)
mu.Unlock()
}
}()
}
mu.Unlock()
wg.Wait()
}
if err := traceProgram(t, prog0, "TestDirectSemaphoreHandoff"); err != nil {
t.Fatalf("failed to trace the program: %v", err)
}
_, err := parseTrace()
if err != nil {
t.Fatalf("failed to parse the trace: %v", err)
}
}

108
src/cmd/trace/trace_unix_test.go
View file

@ -1,108 +0,0 @@
// Copyright 2017 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.
//go:build darwin || dragonfly || freebsd || linux || netbsd || openbsd || solaris
package main
import (
"bytes"
"internal/goexperiment"
traceparser "internal/trace"
"internal/trace/traceviewer"
"internal/trace/traceviewer/format"
"io"
"runtime"
"runtime/trace"
"sync"
"syscall"
"testing"
"time"
)
// TestGoroutineInSyscall tests threads for timer goroutines
// that preexisted when the tracing started were not counted
// as threads in syscall. See golang.org/issues/22574.
func TestGoroutineInSyscall(t *testing.T) {
if goexperiment.ExecTracer2 {
t.Skip("skipping because this test is obsolete and incompatible with the new tracer")
}
// Start one goroutine blocked in syscall.
//
// TODO: syscall.Pipe used to cause the goroutine to
// remain blocked in syscall is not portable. Replace
// it with a more portable way so this test can run
// on non-unix architecture e.g. Windows.
var p [2]int
if err := syscall.Pipe(p[:]); err != nil {
t.Fatalf("failed to create pipe: %v", err)
}
var wg sync.WaitGroup
defer func() {
syscall.Write(p[1], []byte("a"))
wg.Wait()
syscall.Close(p[0])
syscall.Close(p[1])
}()
wg.Add(1)
go func() {
var tmp [1]byte
syscall.Read(p[0], tmp[:])
wg.Done()
}()
// Start multiple timer goroutines.
allTimers := make([]*time.Timer, 2*runtime.GOMAXPROCS(0))
defer func() {
for _, timer := range allTimers {
timer.Stop()
}
}()
var timerSetup sync.WaitGroup
for i := range allTimers {
timerSetup.Add(1)
go func(i int) {
defer timerSetup.Done()
allTimers[i] = time.AfterFunc(time.Hour, nil)
}(i)
}
timerSetup.Wait()
// Collect and parse trace.
buf := new(bytes.Buffer)
if err := trace.Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
trace.Stop()
res, err := traceparser.Parse(buf, "")
if err == traceparser.ErrTimeOrder {
t.Skipf("skipping due to golang.org/issue/16755 (timestamps are unreliable): %v", err)
} else if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
// Check only one thread for the pipe read goroutine is
// considered in-syscall.
c := traceviewer.ViewerDataTraceConsumer(io.Discard, 0, 1<<63-1)
c.ConsumeViewerEvent = func(ev *format.Event, _ bool) {
if ev.Name == "Threads" {
arg := ev.Arg.(*format.ThreadCountersArg)
if arg.InSyscall > 1 {
t.Errorf("%d threads in syscall at time %v; want less than 1 thread in syscall", arg.InSyscall, ev.Time)
}
}
}
param := &traceParams{
parsed: res,
endTime: int64(1<<63 - 1),
}
if err := generateTrace(param, c); err != nil {
t.Fatalf("failed to generate ViewerData: %v", err)
}
}

2
src/cmd/trace/v2/testdata/mktests.go vendored
View file

@ -21,8 +21,6 @@ func main() {
// Create command.
var trace, stderr bytes.Buffer
cmd := exec.Command("go", "run", "./testprog/main.go")
// TODO(mknyszek): Remove if goexperiment.Exectracer2 becomes the default.
cmd.Env = append(os.Environ(), "GOEXPERIMENT=exectracer2")
cmd.Stdout = &trace
cmd.Stderr = &stderr

2
src/internal/trace/v2/testdata/mktests.go vendored
View file

@ -122,8 +122,6 @@ func (ctx *context) runTestProg(progPath string) error {
// Create command.
var trace, stderr bytes.Buffer
cmd := exec.Command("go", "run", progPath)
// TODO(mknyszek): Remove if goexperiment.Exectracer2 becomes the default.
cmd.Env = append(os.Environ(), "GOEXPERIMENT=exectracer2")
cmd.Stdout = &trace
cmd.Stderr = &stderr

2
src/internal/trace/v2/trace_test.go
View file

@ -551,7 +551,7 @@ func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace
cmd.Args = append(cmd.Args, "-race")
}
cmd.Args = append(cmd.Args, testPath)
cmd.Env = append(os.Environ(), "GOEXPERIMENT=exectracer2", "GOEXPERIMENT=rangefunc")
cmd.Env = append(os.Environ(), "GOEXPERIMENT=rangefunc")
// Add a stack ownership check. This is cheap enough for testing.
godebug := "tracecheckstackownership=1"
if stress {

39
src/runtime/crash_cgo_test.go
View file

@ -8,7 +8,6 @@ package runtime_test
import (
"fmt"
"internal/goexperiment"
"internal/goos"
"internal/platform"
"internal/testenv"
@ -780,44 +779,6 @@ func TestCgoTracebackGoroutineProfile(t *testing.T) {
}
}
func TestCgoTraceParser(t *testing.T) {
// Test issue 29707.
switch runtime.GOOS {
case "plan9", "windows":
t.Skipf("no pthreads on %s", runtime.GOOS)
}
if goexperiment.ExecTracer2 {
t.Skip("skipping test that is covered elsewhere for the new execution tracer")
}
output := runTestProg(t, "testprogcgo", "CgoTraceParser")
want := "OK\n"
ErrTimeOrder := "ErrTimeOrder\n"
if output == ErrTimeOrder {
t.Skipf("skipping due to golang.org/issue/16755: %v", output)
} else if output != want {
t.Fatalf("want %s, got %s\n", want, output)
}
}
func TestCgoTraceParserWithOneProc(t *testing.T) {
// Test issue 29707.
switch runtime.GOOS {
case "plan9", "windows":
t.Skipf("no pthreads on %s", runtime.GOOS)
}
if goexperiment.ExecTracer2 {
t.Skip("skipping test that is covered elsewhere for the new execution tracer")
}
output := runTestProg(t, "testprogcgo", "CgoTraceParser", "GOMAXPROCS=1")
want := "OK\n"
ErrTimeOrder := "ErrTimeOrder\n"
if output == ErrTimeOrder {
t.Skipf("skipping due to golang.org/issue/16755: %v", output)
} else if output != want {
t.Fatalf("GOMAXPROCS=1, want %s, got %s\n", want, output)
}
}
func TestCgoSigfwd(t *testing.T) {
t.Parallel()
if !goos.IsUnix {

5
src/runtime/crash_test.go
View file

@ -10,7 +10,6 @@ import (
"errors"
"flag"
"fmt"
"internal/goexperiment"
"internal/testenv"
tracev2 "internal/trace/v2"
"io"
@ -890,10 +889,6 @@ func init() {
}
func TestCrashWhileTracing(t *testing.T) {
if !goexperiment.ExecTracer2 {
t.Skip("skipping because this test is incompatible with the legacy tracer")
}
testenv.MustHaveExec(t)
cmd := testenv.CleanCmdEnv(testenv.Command(t, os.Args[0]))

25
src/runtime/mgcmark.go
View file

@ -9,7 +9,6 @@ package runtime
import (
"internal/abi"
"internal/goarch"
"internal/goexperiment"
"internal/runtime/atomic"
"runtime/internal/sys"
"unsafe"
@ -415,15 +414,9 @@ func gcAssistAlloc(gp *g) {
// This extremely verbose boolean indicates whether we've
// entered mark assist from the perspective of the tracer.
//
// In the old tracer, this is just before we call gcAssistAlloc1
// *and* tracing is enabled. Because the old tracer doesn't
// do any extra tracking, we need to be careful to not emit an
// "end" event if there was no corresponding "begin" for the
// mark assist.
//
// In the new tracer, this is just before we call gcAssistAlloc1
// In the tracer, this is just before we call gcAssistAlloc1
// *regardless* of whether tracing is enabled. This is because
// the new tracer allows for tracing to begin (and advance
// the tracer allows for tracing to begin (and advance
// generations) in the middle of a GC mark phase, so we need to
// record some state so that the tracer can pick it up to ensure
// a consistent trace result.
@ -519,18 +512,6 @@ retry:
if !enteredMarkAssistForTracing {
trace := traceAcquire()
if trace.ok() {
if !goexperiment.ExecTracer2 {
// In the old tracer, enter mark assist tracing only
// if we actually traced an event. Otherwise a goroutine
// waking up from mark assist post-GC might end up
// writing a stray "end" event.
//
// This means inMarkAssist will not be meaningful
// in the old tracer; that's OK, it's unused.
//
// See the comment on enteredMarkAssistForTracing.
enteredMarkAssistForTracing = true
}
trace.GCMarkAssistStart()
// Set this *after* we trace the start, otherwise we may
// emit an in-progress event for an assist we're about to start.
@ -539,7 +520,6 @@ retry:
} else {
gp.inMarkAssist = true
}
if goexperiment.ExecTracer2 {
// In the new tracer, set enter mark assist tracing if we
// ever pass this point, because we must manage inMarkAssist
// correctly.
@ -547,7 +527,6 @@ retry:
// See the comment on enteredMarkAssistForTracing.
enteredMarkAssistForTracing = true
}
}
// Perform assist work
systemstack(func() {

96
src/runtime/proc.go
View file

@ -8,7 +8,6 @@ import (
"internal/abi"
"internal/cpu"
"internal/goarch"
"internal/goexperiment"
"internal/goos"
"internal/runtime/atomic"
"runtime/internal/sys"
@ -1489,7 +1488,6 @@ func stopTheWorldWithSema(reason stwReason) worldStop {
s := pp.status
if s == _Psyscall && atomic.Cas(&pp.status, s, _Pgcstop) {
if trace.ok() {
trace.GoSysBlock(pp)
trace.ProcSteal(pp, false)
}
pp.syscalltick++
@ -1998,7 +1996,6 @@ func forEachPInternal(fn func(*p)) {
if s == _Psyscall && p2.runSafePointFn == 1 && atomic.Cas(&p2.status, s, _Pidle) {
if trace.ok() {
// It's important that we traceRelease before we call handoffp, which may also traceAcquire.
trace.GoSysBlock(p2)
trace.ProcSteal(p2, false)
traceRelease(trace)
}
@ -2259,12 +2256,12 @@ func needm(signal bool) {
minit()
// Emit a trace event for this dead -> syscall transition,
// but only in the new tracer and only if we're not in a signal handler.
// but only if we're not in a signal handler.
//
// N.B. the tracer can run on a bare M just fine, we just have
// to make sure to do this before setg(nil) and unminit.
var trace traceLocker
if goexperiment.ExecTracer2 && !signal {
if !signal {
trace = traceAcquire()
}
@ -2272,7 +2269,7 @@ func needm(signal bool) {
casgstatus(mp.curg, _Gdead, _Gsyscall)
sched.ngsys.Add(-1)
if goexperiment.ExecTracer2 && !signal {
if !signal {
if trace.ok() {
trace.GoCreateSyscall(mp.curg)
traceRelease(trace)
@ -2398,13 +2395,12 @@ func dropm() {
// with no pointer manipulation.
mp := getg().m
// Emit a trace event for this syscall -> dead transition,
// but only in the new tracer.
// Emit a trace event for this syscall -> dead transition.
//
// N.B. the tracer can run on a bare M just fine, we just have
// to make sure to do this before setg(nil) and unminit.
var trace traceLocker
if goexperiment.ExecTracer2 && !mp.isExtraInSig {
if !mp.isExtraInSig {
trace = traceAcquire()
}
@ -2413,14 +2409,13 @@ func dropm() {
mp.curg.preemptStop = false
sched.ngsys.Add(1)
if goexperiment.ExecTracer2 && !mp.isExtraInSig {
if !mp.isExtraInSig {
if trace.ok() {
trace.GoDestroySyscall()
traceRelease(trace)
}
}
if goexperiment.ExecTracer2 {
// Trash syscalltick so that it doesn't line up with mp.old.syscalltick anymore.
//
// In the new tracer, we model needm and dropm and a goroutine being created and
@ -2435,7 +2430,6 @@ func dropm() {
// the syscall exit code expects as possible. Setting to zero is risky because
// syscalltick could already be zero (and in fact, is initialized to zero).
mp.syscalltick--
}
// Reset trace state unconditionally. This goroutine is being 'destroyed'
// from the perspective of the tracer.
@ -2444,10 +2438,7 @@ func dropm() {
// Flush all the M's buffers. This is necessary because the M might
// be used on a different thread with a different procid, so we have
// to make sure we don't write into the same buffer.
//
// N.B. traceThreadDestroy is a no-op in the old tracer, so avoid the
// unnecessary acquire/release of the lock.
if goexperiment.ExecTracer2 && (traceEnabled() || traceShuttingDown()) {
if traceEnabled() || traceShuttingDown() {
// Acquire sched.lock across thread destruction. One of the invariants of the tracer
// is that a thread cannot disappear from the tracer's view (allm or freem) without
// it noticing, so it requires that sched.lock be held over traceThreadDestroy.
@ -3154,11 +3145,6 @@ func execute(gp *g, inheritTime bool) {
trace := traceAcquire()
if trace.ok() {
// GoSysExit has to happen when we have a P, but before GoStart.
// So we emit it here.
if !goexperiment.ExecTracer2 && gp.syscallsp != 0 {
trace.GoSysExit(true)
}
trace.GoStart()
traceRelease(trace)
}
@ -4298,19 +4284,6 @@ func save(pc, sp uintptr) {
// must always point to a valid stack frame. entersyscall below is the normal
// entry point for syscalls, which obtains the SP and PC from the caller.
//
// Syscall tracing (old tracer):
// At the start of a syscall we emit traceGoSysCall to capture the stack trace.
// If the syscall does not block, that is it, we do not emit any other events.
// If the syscall blocks (that is, P is retaken), retaker emits traceGoSysBlock;
// when syscall returns we emit traceGoSysExit and when the goroutine starts running
// (potentially instantly, if exitsyscallfast returns true) we emit traceGoStart.
// To ensure that traceGoSysExit is emitted strictly after traceGoSysBlock,
// we remember current value of syscalltick in m (gp.m.syscalltick = gp.m.p.ptr().syscalltick),
// whoever emits traceGoSysBlock increments p.syscalltick afterwards;
// and we wait for the increment before emitting traceGoSysExit.
// Note that the increment is done even if tracing is not enabled,
// because tracing can be enabled in the middle of syscall. We don't want the wait to hang.
//
//go:nosplit
func reentersyscall(pc, sp uintptr) {
trace := traceAcquire()
@ -4407,7 +4380,6 @@ func entersyscall_gcwait() {
trace := traceAcquire()
if sched.stopwait > 0 && atomic.Cas(&pp.status, _Psyscall, _Pgcstop) {
if trace.ok() {
if goexperiment.ExecTracer2 {
// This is a steal in the new tracer. While it's very likely
// that we were the ones to put this P into _Psyscall, between
// then and now it's totally possible it had been stolen and
@ -4418,10 +4390,6 @@ func entersyscall_gcwait() {
// gp.m.syscalltick == pp.syscalltick, since then we know we never
// lost the P.
trace.ProcSteal(pp, true)
} else {
trace.GoSysBlock(pp)
trace.ProcStop(pp)
}
traceRelease(trace)
}
pp.gcStopTime = nanotime()
@ -4482,7 +4450,6 @@ func entersyscallblock_handoff() {
trace := traceAcquire()
if trace.ok() {
trace.GoSysCall()
trace.GoSysBlock(getg().m.p.ptr())
traceRelease(trace)
}
handoffp(releasep())
@ -4526,13 +4493,11 @@ func exitsyscall() {
if trace.ok() {
lostP := oldp != gp.m.p.ptr() || gp.m.syscalltick != gp.m.p.ptr().syscalltick
systemstack(func() {
if goexperiment.ExecTracer2 {
// Write out syscall exit eagerly in the experiment.
// Write out syscall exit eagerly.
//
// It's important that we write this *after* we know whether we
// lost our P or not (determined by exitsyscallfast).
trace.GoSysExit(lostP)
}
if lostP {
// We lost the P at some point, even though we got it back here.
// Trace that we're starting again, because there was a traceGoSysBlock
@ -4571,17 +4536,6 @@ func exitsyscall() {
return
}
if !goexperiment.ExecTracer2 {
// In the old tracer, because we don't have a P we can't
// actually record the true time we exited the syscall.
// Record it.
trace := traceAcquire()
if trace.ok() {
trace.RecordSyscallExitedTime(gp, oldp)
traceRelease(trace)
}
}
gp.m.locks--
// Call the scheduler.
@ -4600,8 +4554,6 @@ func exitsyscall() {
//go:nosplit
func exitsyscallfast(oldp *p) bool {
gp := getg()
// Freezetheworld sets stopwait but does not retake P's.
if sched.stopwait == freezeStopWait {
return false
@ -4627,22 +4579,6 @@ func exitsyscallfast(oldp *p) bool {
var ok bool
systemstack(func() {
ok = exitsyscallfast_pidle()
if ok && !goexperiment.ExecTracer2 {
trace := traceAcquire()
if trace.ok() {
if oldp != nil {
// Wait till traceGoSysBlock event is emitted.
// This ensures consistency of the trace (the goroutine is started after it is blocked).
for oldp.syscalltick == gp.m.syscalltick {
osyield()
}
}
// In the experiment, we write this in exitsyscall.
// Don't write it here unless the experiment is off.
trace.GoSysExit(true)
traceRelease(trace)
}
}
})
if ok {
return true
@ -4664,17 +4600,10 @@ func exitsyscallfast_reacquired(trace traceLocker) {
// traceGoSysBlock for this syscall was already emitted,
// but here we effectively retake the p from the new syscall running on the same p.
systemstack(func() {
if goexperiment.ExecTracer2 {
// In the experiment, we're stealing the P. It's treated
// We're stealing the P. It's treated
// as if it temporarily stopped running. Then, start running.
trace.ProcSteal(gp.m.p.ptr(), true)
trace.ProcStart()
} else {
// Denote blocking of the new syscall.
trace.GoSysBlock(gp.m.p.ptr())
// Denote completion of the current syscall.
trace.GoSysExit(true)
}
})
}
gp.m.p.ptr().syscalltick++
@ -4704,22 +4633,18 @@ func exitsyscallfast_pidle() bool {
//go:nowritebarrierrec
func exitsyscall0(gp *g) {
var trace traceLocker
if goexperiment.ExecTracer2 {
traceExitingSyscall()
trace = traceAcquire()
}
casgstatus(gp, _Gsyscall, _Grunnable)
if goexperiment.ExecTracer2 {
traceExitedSyscall()
if trace.ok() {
// Write out syscall exit eagerly in the experiment.
// Write out syscall exit eagerly.
//
// It's important that we write this *after* we know whether we
// lost our P or not (determined by exitsyscallfast).
trace.GoSysExit(true)
traceRelease(trace)
}
}
dropg()
lock(&sched.lock)
var pp *p
@ -6158,7 +6083,6 @@ func retake(now int64) uint32 {
trace := traceAcquire()
if atomic.Cas(&pp.status, s, _Pidle) {
if trace.ok() {
trace.GoSysBlock(pp)
trace.ProcSteal(pp, false)
traceRelease(trace)
}

11
src/runtime/sizeof_test.go
View file

@ -5,7 +5,6 @@
package runtime_test
import (
"internal/goexperiment"
"reflect"
"runtime"
"testing"
@ -16,20 +15,12 @@ import (
func TestSizeof(t *testing.T) {
const _64bit = unsafe.Sizeof(uintptr(0)) == 8
g32bit := uintptr(264)
if goexperiment.ExecTracer2 {
// gTraceState changed from 2 uint64, 1 pointer, 1 bool to 2 uint64, 3 uint32.
// On 32-bit, that's one extra word.
g32bit += 4
}
var tests = []struct {
val any // type as a value
_32bit uintptr // size on 32bit platforms
_64bit uintptr // size on 64bit platforms
}{
{runtime.G{}, g32bit, 432}, // g, but exported for testing
{runtime.G{}, 268, 432}, // g, but exported for testing
{runtime.Sudog{}, 56, 88}, // sudog, but exported for testing
}

1936
src/runtime/trace.go
View file

File diff suppressed because it is too large Load diff

125
src/runtime/trace/annotation_test.go
View file

@ -5,15 +5,8 @@
package trace_test
import (
"bytes"
"context"
"fmt"
"internal/goexperiment"
"internal/trace"
"reflect"
. "runtime/trace"
"strings"
"sync"
"testing"
)
@ -41,121 +34,3 @@ func BenchmarkNewTask(b *testing.B) {
}
})
}
func TestUserTaskRegion(t *testing.T) {
if goexperiment.ExecTracer2 {
// An equivalent test exists in internal/trace/v2.
t.Skip("skipping because this test is incompatible with the new tracer")
}
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
bgctx, cancel := context.WithCancel(context.Background())
defer cancel()
preExistingRegion := StartRegion(bgctx, "pre-existing region")
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
// Beginning of traced execution
var wg sync.WaitGroup
ctx, task := NewTask(bgctx, "task0") // EvUserTaskCreate("task0")
wg.Add(1)
go func() {
defer wg.Done()
defer task.End() // EvUserTaskEnd("task0")
WithRegion(ctx, "region0", func() {
// EvUserRegionCreate("region0", start)
WithRegion(ctx, "region1", func() {
Log(ctx, "key0", "0123456789abcdef") // EvUserLog("task0", "key0", "0....f")
})
// EvUserRegion("region0", end)
})
}()
wg.Wait()
preExistingRegion.End()
postExistingRegion := StartRegion(bgctx, "post-existing region")
// End of traced execution
Stop()
postExistingRegion.End()
saveTrace(t, buf, "TestUserTaskRegion")
res, err := trace.Parse(buf, "")
if err == trace.ErrTimeOrder {
// golang.org/issues/16755
t.Skipf("skipping trace: %v", err)
}
if err != nil {
t.Fatalf("Parse failed: %v", err)
}
// Check whether we see all user annotation related records in order
type testData struct {
typ byte
strs []string
args []uint64
setLink bool
}
var got []testData
tasks := map[uint64]string{}
for _, e := range res.Events {
t.Logf("%s", e)
switch e.Type {
case trace.EvUserTaskCreate:
taskName := e.SArgs[0]
got = append(got, testData{trace.EvUserTaskCreate, []string{taskName}, nil, e.Link != nil})
if e.Link != nil && e.Link.Type != trace.EvUserTaskEnd {
t.Errorf("Unexpected linked event %q->%q", e, e.Link)
}
tasks[e.Args[0]] = taskName
case trace.EvUserLog:
key, val := e.SArgs[0], e.SArgs[1]
taskName := tasks[e.Args[0]]
got = append(got, testData{trace.EvUserLog, []string{taskName, key, val}, nil, e.Link != nil})
case trace.EvUserTaskEnd:
taskName := tasks[e.Args[0]]
got = append(got, testData{trace.EvUserTaskEnd, []string{taskName}, nil, e.Link != nil})
if e.Link != nil && e.Link.Type != trace.EvUserTaskCreate {
t.Errorf("Unexpected linked event %q->%q", e, e.Link)
}
case trace.EvUserRegion:
taskName := tasks[e.Args[0]]
regionName := e.SArgs[0]
got = append(got, testData{trace.EvUserRegion, []string{taskName, regionName}, []uint64{e.Args[1]}, e.Link != nil})
if e.Link != nil && (e.Link.Type != trace.EvUserRegion || e.Link.SArgs[0] != regionName) {
t.Errorf("Unexpected linked event %q->%q", e, e.Link)
}
}
}
want := []testData{
{trace.EvUserTaskCreate, []string{"task0"}, nil, true},
{trace.EvUserRegion, []string{"task0", "region0"}, []uint64{0}, true},
{trace.EvUserRegion, []string{"task0", "region1"}, []uint64{0}, true},
{trace.EvUserLog, []string{"task0", "key0", "0123456789abcdef"}, nil, false},
{trace.EvUserRegion, []string{"task0", "region1"}, []uint64{1}, false},
{trace.EvUserRegion, []string{"task0", "region0"}, []uint64{1}, false},
{trace.EvUserTaskEnd, []string{"task0"}, nil, false},
// Currently, pre-existing region is not recorded to avoid allocations.
// {trace.EvUserRegion, []string{"", "pre-existing region"}, []uint64{1}, false},
{trace.EvUserRegion, []string{"", "post-existing region"}, []uint64{0}, false},
}
if !reflect.DeepEqual(got, want) {
pretty := func(data []testData) string {
var s strings.Builder
for _, d := range data {
fmt.Fprintf(&s, "\t%+v\n", d)
}
return s.String()
}
t.Errorf("Got user region related events\n%+v\nwant:\n%+v", pretty(got), pretty(want))
}
}

338
src/runtime/trace/trace_stack_test.go
View file

@ -1,338 +0,0 @@
// Copyright 2014 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.
package trace_test
import (
"bytes"
"fmt"
"internal/goexperiment"
"internal/testenv"
"internal/trace"
"net"
"os"
"runtime"
. "runtime/trace"
"strings"
"sync"
"testing"
"text/tabwriter"
"time"
)
// TestTraceSymbolize tests symbolization and that events has proper stacks.
// In particular that we strip bottom uninteresting frames like goexit,
// top uninteresting frames (runtime guts).
func TestTraceSymbolize(t *testing.T) {
skipTraceSymbolizeTestIfNecessary(t)
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
defer Stop() // in case of early return
// Now we will do a bunch of things for which we verify stacks later.
// It is impossible to ensure that a goroutine has actually blocked
// on a channel, in a select or otherwise. So we kick off goroutines
// that need to block first in the hope that while we are executing
// the rest of the test, they will block.
go func() { // func1
select {}
}()
go func() { // func2
var c chan int
c <- 0
}()
go func() { // func3
var c chan int
<-c
}()
done1 := make(chan bool)
go func() { // func4
<-done1
}()
done2 := make(chan bool)
go func() { // func5
done2 <- true
}()
c1 := make(chan int)
c2 := make(chan int)
go func() { // func6
select {
case <-c1:
case <-c2:
}
}()
var mu sync.Mutex
mu.Lock()
go func() { // func7
mu.Lock()
mu.Unlock()
}()
var wg sync.WaitGroup
wg.Add(1)
go func() { // func8
wg.Wait()
}()
cv := sync.NewCond(&sync.Mutex{})
go func() { // func9
cv.L.Lock()
cv.Wait()
cv.L.Unlock()
}()
ln, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil {
t.Fatalf("failed to listen: %v", err)
}
go func() { // func10
c, err := ln.Accept()
if err != nil {
t.Errorf("failed to accept: %v", err)
return
}
c.Close()
}()
rp, wp, err := os.Pipe()
if err != nil {
t.Fatalf("failed to create a pipe: %v", err)
}
defer rp.Close()
defer wp.Close()
pipeReadDone := make(chan bool)
go func() { // func11
var data [1]byte
rp.Read(data[:])
pipeReadDone <- true
}()
time.Sleep(100 * time.Millisecond)
runtime.GC()
runtime.Gosched()
time.Sleep(100 * time.Millisecond) // the last chance for the goroutines above to block
done1 <- true
<-done2
select {
case c1 <- 0:
case c2 <- 0:
}
mu.Unlock()
wg.Done()
cv.Signal()
c, err := net.Dial("tcp", ln.Addr().String())
if err != nil {
t.Fatalf("failed to dial: %v", err)
}
c.Close()
var data [1]byte
wp.Write(data[:])
<-pipeReadDone
oldGoMaxProcs := runtime.GOMAXPROCS(0)
runtime.GOMAXPROCS(oldGoMaxProcs + 1)
Stop()
runtime.GOMAXPROCS(oldGoMaxProcs)
events, _ := parseTrace(t, buf)
// Now check that the stacks are correct.
type eventDesc struct {
Type byte
Stk []frame
}
want := []eventDesc{
{trace.EvGCStart, []frame{
{"runtime.GC", 0},
{"runtime/trace_test.TestTraceSymbolize", 0},
{"testing.tRunner", 0},
}},
{trace.EvGoStart, []frame{
{"runtime/trace_test.TestTraceSymbolize.func1", 0},
}},
{trace.EvGoSched, []frame{
{"runtime/trace_test.TestTraceSymbolize", 112},
{"testing.tRunner", 0},
}},
{trace.EvGoCreate, []frame{
{"runtime/trace_test.TestTraceSymbolize", 41},
{"testing.tRunner", 0},
}},
{trace.EvGoStop, []frame{
{"runtime.block", 0},
{"runtime/trace_test.TestTraceSymbolize.func1", 0},
}},
{trace.EvGoStop, []frame{
{"runtime.chansend1", 0},
{"runtime/trace_test.TestTraceSymbolize.func2", 0},
}},
{trace.EvGoStop, []frame{
{"runtime.chanrecv1", 0},
{"runtime/trace_test.TestTraceSymbolize.func3", 0},
}},
{trace.EvGoBlockRecv, []frame{
{"runtime.chanrecv1", 0},
{"runtime/trace_test.TestTraceSymbolize.func4", 0},
}},
{trace.EvGoUnblock, []frame{
{"runtime.chansend1", 0},
{"runtime/trace_test.TestTraceSymbolize", 114},
{"testing.tRunner", 0},
}},
{trace.EvGoBlockSend, []frame{
{"runtime.chansend1", 0},
{"runtime/trace_test.TestTraceSymbolize.func5", 0},
}},
{trace.EvGoUnblock, []frame{
{"runtime.chanrecv1", 0},
{"runtime/trace_test.TestTraceSymbolize", 115},
{"testing.tRunner", 0},
}},
{trace.EvGoBlockSelect, []frame{
{"runtime.selectgo", 0},
{"runtime/trace_test.TestTraceSymbolize.func6", 0},
}},
{trace.EvGoUnblock, []frame{
{"runtime.selectgo", 0},
{"runtime/trace_test.TestTraceSymbolize", 116},
{"testing.tRunner", 0},
}},
{trace.EvGoBlockSync, []frame{
{"sync.(*Mutex).Lock", 0},
{"runtime/trace_test.TestTraceSymbolize.func7", 0},
}},
{trace.EvGoUnblock, []frame{
{"sync.(*Mutex).Unlock", 0},
{"runtime/trace_test.TestTraceSymbolize", 0},
{"testing.tRunner", 0},
}},
{trace.EvGoBlockSync, []frame{
{"sync.(*WaitGroup).Wait", 0},
{"runtime/trace_test.TestTraceSymbolize.func8", 0},
}},
{trace.EvGoUnblock, []frame{
{"sync.(*WaitGroup).Add", 0},
{"sync.(*WaitGroup).Done", 0},
{"runtime/trace_test.TestTraceSymbolize", 121},
{"testing.tRunner", 0},
}},
{trace.EvGoBlockCond, []frame{
{"sync.(*Cond).Wait", 0},
{"runtime/trace_test.TestTraceSymbolize.func9", 0},
}},
{trace.EvGoUnblock, []frame{
{"sync.(*Cond).Signal", 0},
{"runtime/trace_test.TestTraceSymbolize", 0},
{"testing.tRunner", 0},
}},
{trace.EvGoSleep, []frame{
{"time.Sleep", 0},
{"runtime/trace_test.TestTraceSymbolize", 0},
{"testing.tRunner", 0},
}},
{trace.EvGomaxprocs, []frame{
{"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
{"runtime.startTheWorldGC", 0},
{"runtime.GOMAXPROCS", 0},
{"runtime/trace_test.TestTraceSymbolize", 0},
{"testing.tRunner", 0},
}},
}
// Stacks for the following events are OS-dependent due to OS-specific code in net package.
if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
want = append(want, []eventDesc{
{trace.EvGoBlockNet, []frame{
{"internal/poll.(*FD).Accept", 0},
{"net.(*netFD).accept", 0},
{"net.(*TCPListener).accept", 0},
{"net.(*TCPListener).Accept", 0},
{"runtime/trace_test.TestTraceSymbolize.func10", 0},
}},
{trace.EvGoSysCall, []frame{
{"syscall.read", 0},
{"syscall.Read", 0},
{"internal/poll.ignoringEINTRIO", 0},
{"internal/poll.(*FD).Read", 0},
{"os.(*File).read", 0},
{"os.(*File).Read", 0},
{"runtime/trace_test.TestTraceSymbolize.func11", 0},
}},
}...)
}
matched := make([]bool, len(want))
for _, ev := range events {
wantLoop:
for i, w := range want {
if matched[i] || w.Type != ev.Type || len(w.Stk) != len(ev.Stk) {
continue
}
for fi, f := range ev.Stk {
wf := w.Stk[fi]
if wf.Fn != f.Fn || wf.Line != 0 && wf.Line != f.Line {
continue wantLoop
}
}
matched[i] = true
}
}
for i, w := range want {
if matched[i] {
continue
}
seen, n := dumpEventStacks(w.Type, events)
t.Errorf("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
}
}
func skipTraceSymbolizeTestIfNecessary(t *testing.T) {
testenv.MustHaveGoBuild(t)
if goexperiment.ExecTracer2 {
// An equivalent test exists in internal/trace/v2.
t.Skip("skipping because this test is incompatible with the new tracer")
}
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
}
func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
matched := 0
o := new(bytes.Buffer)
tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
for _, ev := range events {
if ev.Type != typ {
continue
}
matched++
fmt.Fprintf(tw, "Offset %d\n", ev.Off)
for _, f := range ev.Stk {
fname := f.File
if idx := strings.Index(fname, "/go/src/"); idx > 0 {
fname = fname[idx:]
}
fmt.Fprintf(tw, " %v\t%s:%d\n", f.Fn, fname, f.Line)
}
}
tw.Flush()
return o.Bytes(), matched
}
type frame struct {
Fn string
Line int
}
func dumpFrames(frames []frame) []byte {
o := new(bytes.Buffer)
tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
for _, f := range frames {
fmt.Fprintf(tw, " %v\t :%d\n", f.Fn, f.Line)
}
tw.Flush()
return o.Bytes()
}

758
src/runtime/trace/trace_test.go
View file

@ -6,90 +6,14 @@ package trace_test
import (
"bytes"
"context"
"flag"
"fmt"
"internal/goexperiment"
"internal/profile"
"internal/race"
"internal/trace"
"io"
"net"
"os"
"runtime"
"runtime/pprof"
. "runtime/trace"
"strconv"
"strings"
"sync"
"testing"
"time"
)
var (
saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
)
// TestEventBatch tests Flush calls that happen during Start
// don't produce corrupted traces.
func TestEventBatch(t *testing.T) {
if race.Enabled {
t.Skip("skipping in race mode")
}
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
if testing.Short() {
t.Skip("skipping in short mode")
}
if goexperiment.ExecTracer2 {
t.Skip("skipping because this test is incompatible with the new tracer")
}
// During Start, bunch of records are written to reflect the current
// snapshot of the program, including state of each goroutines.
// And some string constants are written to the trace to aid trace
// parsing. This test checks Flush of the buffer occurred during
// this process doesn't cause corrupted traces.
// When a Flush is called during Start is complicated
// so we test with a range of number of goroutines hoping that one
// of them triggers Flush.
// This range was chosen to fill up a ~64KB buffer with traceEvGoCreate
// and traceEvGoWaiting events (12~13bytes per goroutine).
for g := 4950; g < 5050; g++ {
n := g
t.Run("G="+strconv.Itoa(n), func(t *testing.T) {
var wg sync.WaitGroup
wg.Add(n)
in := make(chan bool, 1000)
for i := 0; i < n; i++ {
go func() {
<-in
wg.Done()
}()
}
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
for i := 0; i < n; i++ {
in <- true
}
wg.Wait()
Stop()
_, err := trace.Parse(buf, "")
if err == trace.ErrTimeOrder {
t.Skipf("skipping trace: %v", err)
}
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
})
}
}
var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
func TestTraceStartStop(t *testing.T) {
if IsEnabled() {
@ -127,686 +51,6 @@ func TestTraceDoubleStart(t *testing.T) {
Stop()
}
func TestTrace(t *testing.T) {
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
if goexperiment.ExecTracer2 {
// An equivalent test exists in internal/trace/v2.
t.Skip("skipping because this test is incompatible with the new tracer")
}
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
Stop()
saveTrace(t, buf, "TestTrace")
_, err := trace.Parse(buf, "")
if err == trace.ErrTimeOrder {
t.Skipf("skipping trace: %v", err)
}
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
}
func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
res, err := trace.Parse(r, "")
if err == trace.ErrTimeOrder {
t.Skipf("skipping trace: %v", err)
}
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
gs := trace.GoroutineStats(res.Events)
for goid := range gs {
// We don't do any particular checks on the result at the moment.
// But still check that RelatedGoroutines does not crash, hang, etc.
_ = trace.RelatedGoroutines(res.Events, goid)
}
return res.Events, gs
}
func testBrokenTimestamps(t *testing.T, data []byte) {
// On some processors cputicks (used to generate trace timestamps)
// produce non-monotonic timestamps. It is important that the parser
// distinguishes logically inconsistent traces (e.g. missing, excessive
// or misordered events) from broken timestamps. The former is a bug
// in tracer, the latter is a machine issue.
// So now that we have a consistent trace, test that (1) parser does
// not return a logical error in case of broken timestamps
// and (2) broken timestamps are eventually detected and reported.
trace.BreakTimestampsForTesting = true
defer func() {
trace.BreakTimestampsForTesting = false
}()
for i := 0; i < 1e4; i++ {
_, err := trace.Parse(bytes.NewReader(data), "")
if err == trace.ErrTimeOrder {
return
}
if err != nil {
t.Fatalf("failed to parse trace: %v", err)
}
}
}
func TestTraceStress(t *testing.T) {
switch runtime.GOOS {
case "js", "wasip1":
t.Skip("no os.Pipe on " + runtime.GOOS)
}
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
if testing.Short() {
t.Skip("skipping in -short mode")
}
if goexperiment.ExecTracer2 {
// An equivalent test exists in internal/trace/v2.
t.Skip("skipping because this test is incompatible with the new tracer")
}
var wg sync.WaitGroup
done := make(chan bool)
// Create a goroutine blocked before tracing.
wg.Add(1)
go func() {
<-done
wg.Done()
}()
// Create a goroutine blocked in syscall before tracing.
rp, wp, err := os.Pipe()
if err != nil {
t.Fatalf("failed to create pipe: %v", err)
}
defer func() {
rp.Close()
wp.Close()
}()
wg.Add(1)
go func() {
var tmp [1]byte
rp.Read(tmp[:])
<-done
wg.Done()
}()
time.Sleep(time.Millisecond) // give the goroutine above time to block
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
procs := runtime.GOMAXPROCS(10)
time.Sleep(50 * time.Millisecond) // test proc stop/start events
go func() {
runtime.LockOSThread()
for {
select {
case <-done:
return
default:
runtime.Gosched()
}
}
}()
runtime.GC()
// Trigger GC from malloc.
n := int(1e3)
if isMemoryConstrained() {
// Reduce allocation to avoid running out of
// memory on the builder - see issue/12032.
n = 512
}
for i := 0; i < n; i++ {
_ = make([]byte, 1<<20)
}
// Create a bunch of busy goroutines to load all Ps.
for p := 0; p < 10; p++ {
wg.Add(1)
go func() {
// Do something useful.
tmp := make([]byte, 1<<16)
for i := range tmp {
tmp[i]++
}
_ = tmp
<-done
wg.Done()
}()
}
// Block in syscall.
wg.Add(1)
go func() {
var tmp [1]byte
rp.Read(tmp[:])
<-done
wg.Done()
}()
// Test timers.
timerDone := make(chan bool)
go func() {
time.Sleep(time.Millisecond)
timerDone <- true
}()
<-timerDone
// A bit of network.
ln, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil {
t.Fatalf("listen failed: %v", err)
}
defer ln.Close()
go func() {
c, err := ln.Accept()
if err != nil {
return
}
time.Sleep(time.Millisecond)
var buf [1]byte
c.Write(buf[:])
c.Close()
}()
c, err := net.Dial("tcp", ln.Addr().String())
if err != nil {
t.Fatalf("dial failed: %v", err)
}
var tmp [1]byte
c.Read(tmp[:])
c.Close()
go func() {
runtime.Gosched()
select {}
}()
// Unblock helper goroutines and wait them to finish.
wp.Write(tmp[:])
wp.Write(tmp[:])
close(done)
wg.Wait()
runtime.GOMAXPROCS(procs)
Stop()
saveTrace(t, buf, "TestTraceStress")
trace := buf.Bytes()
parseTrace(t, buf)
testBrokenTimestamps(t, trace)
}
// isMemoryConstrained reports whether the current machine is likely
// to be memory constrained.
// This was originally for the openbsd/arm builder (Issue 12032).
// TODO: move this to testenv? Make this look at memory? Look at GO_BUILDER_NAME?
func isMemoryConstrained() bool {
if runtime.GOOS == "plan9" {
return true
}
switch runtime.GOARCH {
case "arm", "mips", "mipsle":
return true
}
return false
}
// Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
// And concurrently with all that start/stop trace 3 times.
func TestTraceStressStartStop(t *testing.T) {
switch runtime.GOOS {
case "js", "wasip1":
t.Skip("no os.Pipe on " + runtime.GOOS)
}
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
if goexperiment.ExecTracer2 {
// An equivalent test exists in internal/trace/v2.
t.Skip("skipping because this test is incompatible with the new tracer")
}
defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
outerDone := make(chan bool)
go func() {
defer func() {
outerDone <- true
}()
var wg sync.WaitGroup
done := make(chan bool)
wg.Add(1)
go func() {
<-done
wg.Done()
}()
rp, wp, err := os.Pipe()
if err != nil {
t.Errorf("failed to create pipe: %v", err)
return
}
defer func() {
rp.Close()
wp.Close()
}()
wg.Add(1)
go func() {
var tmp [1]byte
rp.Read(tmp[:])
<-done
wg.Done()
}()
time.Sleep(time.Millisecond)
go func() {
runtime.LockOSThread()
for {
select {
case <-done:
return
default:
runtime.Gosched()
}
}
}()
runtime.GC()
// Trigger GC from malloc.
n := int(1e3)
if isMemoryConstrained() {
// Reduce allocation to avoid running out of
// memory on the builder.
n = 512
}
for i := 0; i < n; i++ {
_ = make([]byte, 1<<20)
}
// Create a bunch of busy goroutines to load all Ps.
for p := 0; p < 10; p++ {
wg.Add(1)
go func() {
// Do something useful.
tmp := make([]byte, 1<<16)
for i := range tmp {
tmp[i]++
}
_ = tmp
<-done
wg.Done()
}()
}
// Block in syscall.
wg.Add(1)
go func() {
var tmp [1]byte
rp.Read(tmp[:])
<-done
wg.Done()
}()
runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
// Test timers.
timerDone := make(chan bool)
go func() {
time.Sleep(time.Millisecond)
timerDone <- true
}()
<-timerDone
// A bit of network.
ln, err := net.Listen("tcp", "127.0.0.1:0")
if err != nil {
t.Errorf("listen failed: %v", err)
return
}
defer ln.Close()
go func() {
c, err := ln.Accept()
if err != nil {
return
}
time.Sleep(time.Millisecond)
var buf [1]byte
c.Write(buf[:])
c.Close()
}()
c, err := net.Dial("tcp", ln.Addr().String())
if err != nil {
t.Errorf("dial failed: %v", err)
return
}
var tmp [1]byte
c.Read(tmp[:])
c.Close()
go func() {
runtime.Gosched()
select {}
}()
// Unblock helper goroutines and wait them to finish.
wp.Write(tmp[:])
wp.Write(tmp[:])
close(done)
wg.Wait()
}()
for i := 0; i < 3; i++ {
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
time.Sleep(time.Millisecond)
Stop()
saveTrace(t, buf, "TestTraceStressStartStop")
trace := buf.Bytes()
parseTrace(t, buf)
testBrokenTimestamps(t, trace)
}
<-outerDone
}
func TestTraceFutileWakeup(t *testing.T) {
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
if goexperiment.ExecTracer2 {
t.Skip("skipping because this test is incompatible with the new tracer")
}
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
c0 := make(chan int, 1)
c1 := make(chan int, 1)
c2 := make(chan int, 1)
const procs = 2
var done sync.WaitGroup
done.Add(4 * procs)
for p := 0; p < procs; p++ {
const iters = 1e3
go func() {
for i := 0; i < iters; i++ {
runtime.Gosched()
c0 <- 0
}
done.Done()
}()
go func() {
for i := 0; i < iters; i++ {
runtime.Gosched()
<-c0
}
done.Done()
}()
go func() {
for i := 0; i < iters; i++ {
runtime.Gosched()
select {
case c1 <- 0:
case c2 <- 0:
}
}
done.Done()
}()
go func() {
for i := 0; i < iters; i++ {
runtime.Gosched()
select {
case <-c1:
case <-c2:
}
}
done.Done()
}()
}
done.Wait()
Stop()
saveTrace(t, buf, "TestTraceFutileWakeup")
events, _ := parseTrace(t, buf)
// Check that (1) trace does not contain EvFutileWakeup events and
// (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
// (we call runtime.Gosched between all operations, so these would be futile wakeups).
gs := make(map[uint64]int)
for _, ev := range events {
switch ev.Type {
case trace.EvFutileWakeup:
t.Fatalf("found EvFutileWakeup event")
case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
if gs[ev.G] == 2 {
t.Fatalf("goroutine %v blocked on %v at %v right after start",
ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
}
if gs[ev.G] == 1 {
t.Fatalf("goroutine %v blocked on %v at %v while blocked",
ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
}
gs[ev.G] = 1
case trace.EvGoStart:
if gs[ev.G] == 1 {
gs[ev.G] = 2
}
default:
delete(gs, ev.G)
}
}
}
func TestTraceCPUProfile(t *testing.T) {
if IsEnabled() {
t.Skip("skipping because -test.trace is set")
}
if goexperiment.ExecTracer2 {
// An equivalent test exists in internal/trace/v2.
t.Skip("skipping because this test is incompatible with the new tracer")
}
cpuBuf := new(bytes.Buffer)
if err := pprof.StartCPUProfile(cpuBuf); err != nil {
t.Skipf("failed to start CPU profile: %v", err)
}
buf := new(bytes.Buffer)
if err := Start(buf); err != nil {
t.Fatalf("failed to start tracing: %v", err)
}
dur := 100 * time.Millisecond
func() {
// Create a region in the execution trace. Set and clear goroutine
// labels fully within that region, so we know that any CPU profile
// sample with the label must also be eligible for inclusion in the
// execution trace.
ctx := context.Background()
defer StartRegion(ctx, "cpuHogger").End()
pprof.Do(ctx, pprof.Labels("tracing", "on"), func(ctx context.Context) {
cpuHogger(cpuHog1, &salt1, dur)
})
// Be sure the execution trace's view, when filtered to this goroutine
// via the explicit goroutine ID in each event, gets many more samples
// than the CPU profiler when filtered to this goroutine via labels.
cpuHogger(cpuHog1, &salt1, dur)
}()
Stop()
pprof.StopCPUProfile()
saveTrace(t, buf, "TestTraceCPUProfile")
prof, err := profile.Parse(cpuBuf)
if err != nil {
t.Fatalf("failed to parse CPU profile: %v", err)
}
// Examine the CPU profiler's view. Filter it to only include samples from
// the single test goroutine. Use labels to execute that filter: they should
// apply to all work done while that goroutine is getg().m.curg, and they
// should apply to no other goroutines.
pprofSamples := 0
pprofStacks := make(map[string]int)
for _, s := range prof.Sample {
if s.Label["tracing"] != nil {
var fns []string
var leaf string
for _, loc := range s.Location {
for _, line := range loc.Line {
fns = append(fns, fmt.Sprintf("%s:%d", line.Function.Name, line.Line))
leaf = line.Function.Name
}
}
// runtime.sigprof synthesizes call stacks when "normal traceback is
// impossible or has failed", using particular placeholder functions
// to represent common failure cases. Look for those functions in
// the leaf position as a sign that the call stack and its
// symbolization are more complex than this test can handle.
//
// TODO: Make the symbolization done by the execution tracer and CPU
// profiler match up even in these harder cases. See #53378.
switch leaf {
case "runtime._System", "runtime._GC", "runtime._ExternalCode", "runtime._VDSO":
continue
}
stack := strings.Join(fns, " ")
samples := int(s.Value[0])
pprofSamples += samples
pprofStacks[stack] += samples
}
}
if pprofSamples == 0 {
t.Skipf("CPU profile did not include any samples while tracing was active\n%s", prof)
}
// Examine the execution tracer's view of the CPU profile samples. Filter it
// to only include samples from the single test goroutine. Use the goroutine
// ID that was recorded in the events: that should reflect getg().m.curg,
// same as the profiler's labels (even when the M is using its g0 stack).
totalTraceSamples := 0
traceSamples := 0
traceStacks := make(map[string]int)
events, _ := parseTrace(t, buf)
var hogRegion *trace.Event
for _, ev := range events {
if ev.Type == trace.EvUserRegion && ev.Args[1] == 0 && ev.SArgs[0] == "cpuHogger" {
// mode "0" indicates region start
hogRegion = ev
}
}
if hogRegion == nil {
t.Fatalf("execution trace did not identify cpuHogger goroutine")
} else if hogRegion.Link == nil {
t.Fatalf("execution trace did not close cpuHogger region")
}
for _, ev := range events {
if ev.Type == trace.EvCPUSample {
totalTraceSamples++
if ev.G == hogRegion.G {
traceSamples++
var fns []string
for _, frame := range ev.Stk {
if frame.Fn != "runtime.goexit" {
fns = append(fns, fmt.Sprintf("%s:%d", frame.Fn, frame.Line))
}
}
stack := strings.Join(fns, " ")
traceStacks[stack]++
}
}
}
// The execution trace may drop CPU profile samples if the profiling buffer
// overflows. Based on the size of profBufWordCount, that takes a bit over
// 1900 CPU samples or 19 thread-seconds at a 100 Hz sample rate. If we've
// hit that case, then we definitely have at least one full buffer's worth
// of CPU samples, so we'll call that success.
overflowed := totalTraceSamples >= 1900
if traceSamples < pprofSamples {
t.Logf("execution trace did not include all CPU profile samples; %d in profile, %d in trace", pprofSamples, traceSamples)
if !overflowed {
t.Fail()
}
}
for stack, traceSamples := range traceStacks {
pprofSamples := pprofStacks[stack]
delete(pprofStacks, stack)
if traceSamples < pprofSamples {
t.Logf("execution trace did not include all CPU profile samples for stack %q; %d in profile, %d in trace",
stack, pprofSamples, traceSamples)
if !overflowed {
t.Fail()
}
}
}
for stack, pprofSamples := range pprofStacks {
t.Logf("CPU profile included %d samples at stack %q not present in execution trace", pprofSamples, stack)
if !overflowed {
t.Fail()
}
}
if t.Failed() {
t.Logf("execution trace CPU samples:")
for stack, samples := range traceStacks {
t.Logf("%d: %q", samples, stack)
}
t.Logf("CPU profile:\n%v", prof)
}
}
func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
// We only need to get one 100 Hz clock tick, so we've got
// a large safety buffer.
// But do at least 500 iterations (which should take about 100ms),
// otherwise TestCPUProfileMultithreaded can fail if only one
// thread is scheduled during the testing period.
t0 := time.Now()
accum := *y
for i := 0; i < 500 || time.Since(t0) < dur; i++ {
accum = f(accum)
}
*y = accum
}
var (
salt1 = 0
)
// The actual CPU hogging function.
// Must not call other functions nor access heap/globals in the loop,
// otherwise under race detector the samples will be in the race runtime.
func cpuHog1(x int) int {
return cpuHog0(x, 1e5)
}
func cpuHog0(x, n int) int {
foo := x
for i := 0; i < n; i++ {
if i%1000 == 0 {
// Spend time in mcall, stored as gp.m.curg, with g0 running
runtime.Gosched()
}
if foo > 0 {
foo *= foo
} else {
foo *= foo + 1
}
}
return foo
}
func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
if !*saveTraces {
return

2
src/runtime/trace2.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Go execution tracer.
// The tracer captures a wide range of execution events like goroutine
// creation/blocking/unblocking, syscall enter/exit/block, GC-related events,

2
src/runtime/trace2buf.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Trace buffer management.
package runtime

2
src/runtime/trace2cpu.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// CPU profile -> trace
package runtime

2
src/runtime/trace2event.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Trace event writing API for trace2runtime.go.
package runtime

2
src/runtime/trace2map.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Simple append-only thread-safe hash map for tracing.
// Provides a mapping between variable-length data and a
// unique ID. Subsequent puts of the same data will return

2
src/runtime/trace2region.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Simple not-in-heap bump-pointer traceRegion allocator.
package runtime

6
src/runtime/trace2runtime.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Runtime -> tracer API.
package runtime
@ -562,10 +560,6 @@ func (tl traceLocker) ProcSteal(pp *p, inSyscall bool) {
w.commit(traceEvProcSteal, traceArg(pp.id), pp.trace.nextSeq(tl.gen), traceArg(mStolenFrom))
}
// GoSysBlock is a no-op in the new tracer.
func (tl traceLocker) GoSysBlock(pp *p) {
}
// HeapAlloc emits a HeapAlloc event.
func (tl traceLocker) HeapAlloc(live uint64) {
tl.eventWriter(traceGoRunning, traceProcRunning).commit(traceEvHeapAlloc, traceArg(live))

2
src/runtime/trace2stack.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Trace stack table and acquisition.
package runtime

2
src/runtime/trace2status.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Trace goroutine and P status management.
package runtime

2
src/runtime/trace2string.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Trace string management.
package runtime

2
src/runtime/trace2time.go
View file

@ -2,8 +2,6 @@
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
//go:build goexperiment.exectracer2
// Trace time and clock.
package runtime

14
src/runtime/trace_cgo_test.go
View file

@ -9,7 +9,6 @@ package runtime_test
import (
"bytes"
"fmt"
"internal/goexperiment"
"internal/testenv"
"internal/trace"
tracev2 "internal/trace/v2"
@ -60,7 +59,6 @@ func TestTraceUnwindCGO(t *testing.T) {
if err != nil {
t.Fatalf("failed to read trace: %s", err)
}
if goexperiment.ExecTracer2 {
for category := range logs {
event := mustFindLogV2(t, bytes.NewReader(traceData), category)
if wantEvent := logsV2[category]; wantEvent == nil {
@ -69,18 +67,6 @@ func TestTraceUnwindCGO(t *testing.T) {
t.Errorf("%q: got stack:\n%s\nwant stack:\n%s\n", category, got, want)
}
}
} else {
events := parseTrace(t, bytes.NewReader(traceData))
for category := range logs {
event := mustFindLog(t, events, category)
if wantEvent := logs[category]; wantEvent == nil {
logs[category] = event
} else if got, want := dumpStack(event), dumpStack(wantEvent); got != want {
t.Errorf("%q: got stack:\n%s\nwant stack:\n%s\n", category, got, want)
}
}
}
}
}