From ae1ea2aa94b366107f4f92a591d102fd32ad86ae Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Wed, 22 Jul 2015 13:09:26 +0200 Subject: runtime/trace: add new package Move tracing functions from runtime/pprof to the new runtime/trace package. Fixes #9710 Change-Id: I718bcb2ae3e5959d9f72cab5e6708289e5c8ebd5 Reviewed-on: https://go-review.googlesource.com/12511 Reviewed-by: Russ Cox --- src/runtime/pprof/pprof.go | 27 -- src/runtime/pprof/trace_stack_test.go | 285 --------------------- src/runtime/pprof/trace_test.go | 461 ---------------------------------- src/runtime/trace/trace.go | 42 ++++ src/runtime/trace/trace_stack_test.go | 285 +++++++++++++++++++++ src/runtime/trace/trace_test.go | 461 ++++++++++++++++++++++++++++++++++ 6 files changed, 788 insertions(+), 773 deletions(-) delete mode 100644 src/runtime/pprof/trace_stack_test.go delete mode 100644 src/runtime/pprof/trace_test.go create mode 100644 src/runtime/trace/trace.go create mode 100644 src/runtime/trace/trace_stack_test.go create mode 100644 src/runtime/trace/trace_test.go (limited to 'src/runtime') diff --git a/src/runtime/pprof/pprof.go b/src/runtime/pprof/pprof.go index 43fe6e85a1..7d888e4ab0 100644 --- a/src/runtime/pprof/pprof.go +++ b/src/runtime/pprof/pprof.go @@ -613,33 +613,6 @@ func StopCPUProfile() { <-cpu.done } -// TODO(rsc): Decide if StartTrace belongs in this package. -// See golang.org/issue/9710. -// StartTrace enables tracing for the current process. -// While tracing, the trace will be buffered and written to w. -// StartTrace returns an error if profiling is tracing enabled. -func StartTrace(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 -} - -// StopTrace stops the current tracing, if any. -// StopTrace only returns after all the writes for the trace have completed. -func StopTrace() { - runtime.StopTrace() -} - type byCycles []runtime.BlockProfileRecord func (x byCycles) Len() int { return len(x) } diff --git a/src/runtime/pprof/trace_stack_test.go b/src/runtime/pprof/trace_stack_test.go deleted file mode 100644 index 984879dc92..0000000000 --- a/src/runtime/pprof/trace_stack_test.go +++ /dev/null @@ -1,285 +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 pprof_test - -import ( - "bytes" - "internal/trace" - "net" - "os" - "runtime" - . "runtime/pprof" - "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 := StartTrace(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 - - StopTrace() - 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/pprof_test.TestTraceSymbolize", 106}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoSched, []frame{ - frame{"runtime/pprof_test.TestTraceSymbolize", 107}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoCreate, []frame{ - frame{"runtime/pprof_test.TestTraceSymbolize", 39}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoStop, []frame{ - frame{"runtime.block", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func1", 38}, - }}, - eventDesc{trace.EvGoStop, []frame{ - frame{"runtime.chansend1", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func2", 42}, - }}, - eventDesc{trace.EvGoStop, []frame{ - frame{"runtime.chanrecv1", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func3", 46}, - }}, - eventDesc{trace.EvGoBlockRecv, []frame{ - frame{"runtime.chanrecv1", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func4", 50}, - }}, - eventDesc{trace.EvGoUnblock, []frame{ - frame{"runtime.chansend1", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize", 109}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoBlockSend, []frame{ - frame{"runtime.chansend1", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func5", 54}, - }}, - eventDesc{trace.EvGoUnblock, []frame{ - frame{"runtime.chanrecv1", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize", 110}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoBlockSelect, []frame{ - frame{"runtime.selectgo", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func6", 59}, - }}, - eventDesc{trace.EvGoUnblock, []frame{ - frame{"runtime.selectgo", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize", 111}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoBlockSync, []frame{ - frame{"sync.(*Mutex).Lock", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func7", 67}, - }}, - eventDesc{trace.EvGoUnblock, []frame{ - frame{"sync.(*Mutex).Unlock", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize", 115}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoBlockSync, []frame{ - frame{"sync.(*WaitGroup).Wait", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func8", 73}, - }}, - eventDesc{trace.EvGoUnblock, []frame{ - frame{"sync.(*WaitGroup).Add", 0}, - frame{"sync.(*WaitGroup).Done", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize", 116}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoBlockCond, []frame{ - frame{"sync.(*Cond).Wait", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize.func9", 78}, - }}, - eventDesc{trace.EvGoUnblock, []frame{ - frame{"sync.(*Cond).Signal", 0}, - frame{"runtime/pprof_test.TestTraceSymbolize", 117}, - frame{"testing.tRunner", 0}, - }}, - eventDesc{trace.EvGoSleep, []frame{ - frame{"time.Sleep", 0}, - frame{"runtime/pprof_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/pprof_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/pprof_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/pprof/trace_test.go b/src/runtime/pprof/trace_test.go deleted file mode 100644 index ec88516cc1..0000000000 --- a/src/runtime/pprof/trace_test.go +++ /dev/null @@ -1,461 +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 pprof_test - -import ( - "bytes" - "internal/trace" - "io" - "net" - "os" - "runtime" - . "runtime/pprof" - "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 := StartTrace(buf); err != nil { - t.Fatalf("failed to start tracing: %v", err) - } - StopTrace() - 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) - StopTrace() - buf := new(bytes.Buffer) - if err := StartTrace(buf); err != nil { - t.Fatalf("failed to start tracing: %v", err) - } - if err := StartTrace(buf); err == nil { - t.Fatalf("succeed to start tracing second time") - } - StopTrace() - StopTrace() -} - -func TestTrace(t *testing.T) { - skipTraceTestsIfNeeded(t) - buf := new(bytes.Buffer) - if err := StartTrace(buf); err != nil { - t.Fatalf("failed to start tracing: %v", err) - } - StopTrace() - _, 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 := StartTrace(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) - - StopTrace() - _, _, 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 := StartTrace(buf); err != nil { - t.Fatalf("failed to start tracing: %v", err) - } - time.Sleep(time.Millisecond) - StopTrace() - 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 := StartTrace(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() - - StopTrace() - 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) - } - } -} 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) + } + } +} -- cgit v1.3