diff options
Diffstat (limited to 'src/runtime/trace')
| -rw-r--r-- | src/runtime/trace/trace.go | 42 | ||||
| -rw-r--r-- | src/runtime/trace/trace_stack_test.go | 285 | ||||
| -rw-r--r-- | src/runtime/trace/trace_test.go | 461 |
3 files changed, 788 insertions, 0 deletions
diff --git a/src/runtime/trace/trace.go b/src/runtime/trace/trace.go new file mode 100644 index 0000000000..7cbb8a6e82 --- /dev/null +++ b/src/runtime/trace/trace.go @@ -0,0 +1,42 @@ +// Copyright 2015 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 execution tracer. +// The tracer captures a wide range of execution events like goroutine +// creation/blocking/unblocking, syscall enter/exit/block, GC-related events, +// changes of heap size, processor start/stop, etc and writes them to an io.Writer +// in a compact form. A precise nanosecond-precision timestamp and a stack +// trace is captured for most events. A trace can be analyzed later with +// 'go tool trace' command. +package trace + +import ( + "io" + "runtime" +) + +// Start enables tracing for the current program. +// While tracing, the trace will be buffered and written to w. +// Start returns an error if tracing is already enabled. +func Start(w io.Writer) error { + if err := runtime.StartTrace(); err != nil { + return err + } + go func() { + for { + data := runtime.ReadTrace() + if data == nil { + break + } + w.Write(data) + } + }() + return nil +} + +// Stop stops the current tracing, if any. +// Stop only returns after all the writes for the trace have completed. +func Stop() { + runtime.StopTrace() +} diff --git a/src/runtime/trace/trace_stack_test.go b/src/runtime/trace/trace_stack_test.go new file mode 100644 index 0000000000..061274a4f6 --- /dev/null +++ b/src/runtime/trace/trace_stack_test.go @@ -0,0 +1,285 @@ +// 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" + "internal/trace" + "net" + "os" + "runtime" + . "runtime/trace" + "sync" + "testing" + "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) { + skipTraceTestsIfNeeded(t) + if runtime.GOOS == "nacl" { + t.Skip("skipping: nacl tests fail with 'failed to symbolize trace: failed to start addr2line'") + } + buf := new(bytes.Buffer) + if err := Start(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + + // 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() { + select {} + }() + go func() { + var c chan int + c <- 0 + }() + go func() { + var c chan int + <-c + }() + done1 := make(chan bool) + go func() { + <-done1 + }() + done2 := make(chan bool) + go func() { + done2 <- true + }() + c1 := make(chan int) + c2 := make(chan int) + go func() { + select { + case <-c1: + case <-c2: + } + }() + var mu sync.Mutex + mu.Lock() + go func() { + mu.Lock() + mu.Unlock() + }() + var wg sync.WaitGroup + wg.Add(1) + go func() { + wg.Wait() + }() + cv := sync.NewCond(&sync.Mutex{}) + go func() { + cv.L.Lock() + cv.Wait() + cv.L.Unlock() + }() + ln, err := net.Listen("tcp", "localhost:0") + if err != nil { + t.Fatalf("failed to listen: %v", err) + } + go func() { + c, err := ln.Accept() + if err != nil { + t.Fatalf("failed to accept: %v", err) + } + 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() { + var data [1]byte + rp.Read(data[:]) + pipeReadDone <- true + }() + + time.Sleep(time.Millisecond) + runtime.GC() + runtime.Gosched() + time.Sleep(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 + + Stop() + events, _, err := parseTrace(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } + err = trace.Symbolize(events, os.Args[0]) + if err != nil { + t.Fatalf("failed to symbolize trace: %v", err) + } + + // Now check that the stacks are correct. + type frame struct { + Fn string + Line int + } + type eventDesc struct { + Type byte + Stk []frame + } + want := []eventDesc{ + eventDesc{trace.EvGCStart, []frame{ + frame{"runtime.GC", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 106}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoSched, []frame{ + frame{"runtime/trace_test.TestTraceSymbolize", 107}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoCreate, []frame{ + frame{"runtime/trace_test.TestTraceSymbolize", 39}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoStop, []frame{ + frame{"runtime.block", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func1", 38}, + }}, + eventDesc{trace.EvGoStop, []frame{ + frame{"runtime.chansend1", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func2", 42}, + }}, + eventDesc{trace.EvGoStop, []frame{ + frame{"runtime.chanrecv1", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func3", 46}, + }}, + eventDesc{trace.EvGoBlockRecv, []frame{ + frame{"runtime.chanrecv1", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func4", 50}, + }}, + eventDesc{trace.EvGoUnblock, []frame{ + frame{"runtime.chansend1", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 109}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoBlockSend, []frame{ + frame{"runtime.chansend1", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func5", 54}, + }}, + eventDesc{trace.EvGoUnblock, []frame{ + frame{"runtime.chanrecv1", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 110}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoBlockSelect, []frame{ + frame{"runtime.selectgo", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func6", 59}, + }}, + eventDesc{trace.EvGoUnblock, []frame{ + frame{"runtime.selectgo", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 111}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoBlockSync, []frame{ + frame{"sync.(*Mutex).Lock", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func7", 67}, + }}, + eventDesc{trace.EvGoUnblock, []frame{ + frame{"sync.(*Mutex).Unlock", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 115}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoBlockSync, []frame{ + frame{"sync.(*WaitGroup).Wait", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func8", 73}, + }}, + eventDesc{trace.EvGoUnblock, []frame{ + frame{"sync.(*WaitGroup).Add", 0}, + frame{"sync.(*WaitGroup).Done", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 116}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoBlockCond, []frame{ + frame{"sync.(*Cond).Wait", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func9", 78}, + }}, + eventDesc{trace.EvGoUnblock, []frame{ + frame{"sync.(*Cond).Signal", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 117}, + frame{"testing.tRunner", 0}, + }}, + eventDesc{trace.EvGoSleep, []frame{ + frame{"time.Sleep", 0}, + frame{"runtime/trace_test.TestTraceSymbolize", 108}, + frame{"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{ + eventDesc{trace.EvGoBlockNet, []frame{ + frame{"net.(*netFD).accept", 0}, + frame{"net.(*TCPListener).AcceptTCP", 0}, + frame{"net.(*TCPListener).Accept", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func10", 86}, + }}, + eventDesc{trace.EvGoSysCall, []frame{ + frame{"syscall.read", 0}, + frame{"syscall.Read", 0}, + frame{"os.(*File).read", 0}, + frame{"os.(*File).Read", 0}, + frame{"runtime/trace_test.TestTraceSymbolize.func11", 101}, + }}, + }...) + } + 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, m := range matched { + if m { + continue + } + w := want[i] + t.Errorf("did not match event %v at %v:%v", trace.EventDescriptions[w.Type].Name, w.Stk[0].Fn, w.Stk[0].Line) + t.Errorf("seen the following events of this type:") + for _, ev := range events { + if ev.Type != w.Type { + continue + } + for _, f := range ev.Stk { + t.Logf(" %v:%v", f.Fn, f.Line) + } + t.Logf("---") + } + } +} diff --git a/src/runtime/trace/trace_test.go b/src/runtime/trace/trace_test.go new file mode 100644 index 0000000000..e987564d8b --- /dev/null +++ b/src/runtime/trace/trace_test.go @@ -0,0 +1,461 @@ +// 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" + "internal/trace" + "io" + "net" + "os" + "runtime" + . "runtime/trace" + "sync" + "testing" + "time" +) + +func skipTraceTestsIfNeeded(t *testing.T) { + switch runtime.GOOS { + case "solaris": + t.Skip("skipping: solaris timer can go backwards (https://golang.org/issue/8976)") + case "darwin": + switch runtime.GOARCH { + case "arm", "arm64": + // TODO(rsc): What does this have to do with the trace tests? + // There is no forking here. + t.Skipf("skipping on %s/%s, cannot fork", runtime.GOOS, runtime.GOARCH) + } + } + + switch runtime.GOARCH { + case "arm": + t.Skip("skipping: arm tests fail with 'failed to parse trace' (https://golang.org/issue/9725)") + } +} + +func TestTraceStartStop(t *testing.T) { + skipTraceTestsIfNeeded(t) + buf := new(bytes.Buffer) + if err := Start(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + Stop() + size := buf.Len() + if size == 0 { + t.Fatalf("trace is empty") + } + time.Sleep(100 * time.Millisecond) + if size != buf.Len() { + t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len()) + } +} + +func TestTraceDoubleStart(t *testing.T) { + skipTraceTestsIfNeeded(t) + Stop() + buf := new(bytes.Buffer) + if err := Start(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + if err := Start(buf); err == nil { + t.Fatalf("succeed to start tracing second time") + } + Stop() + Stop() +} + +func TestTrace(t *testing.T) { + skipTraceTestsIfNeeded(t) + buf := new(bytes.Buffer) + if err := Start(buf); err != nil { + t.Fatalf("failed to start tracing: %v", err) + } + Stop() + _, err := trace.Parse(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } +} + +func parseTrace(r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc, error) { + events, err := trace.Parse(r) + if err != nil { + return nil, nil, err + } + gs := trace.GoroutineStats(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(events, goid) + } + return events, gs, nil +} + +func TestTraceStress(t *testing.T) { + skipTraceTestsIfNeeded(t) + + 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. + for i := 0; i < 1e3; 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() + _, _, err = parseTrace(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } +} + +// 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) { + skipTraceTestsIfNeeded(t) + + 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.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) + + go func() { + runtime.LockOSThread() + for { + select { + case <-done: + return + default: + runtime.Gosched() + } + } + }() + + runtime.GC() + // Trigger GC from malloc. + for i := 0; i < 1e3; 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.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() + }() + + 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() + if _, _, err := parseTrace(buf); err != nil { + t.Fatalf("failed to parse trace: %v", err) + } + } + <-outerDone +} + +func TestTraceFutileWakeup(t *testing.T) { + // The test generates a full-load of futile wakeups on channels, + // and ensures that the trace is consistent after their removal. + skipTraceTestsIfNeeded(t) + if runtime.GOOS == "linux" && runtime.GOARCH == "ppc64le" { + t.Skip("test is unreliable; issue #10512") + } + + 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() + events, _, err := parseTrace(buf) + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } + // 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) + } + } +} |
