diff options
| author | Dmitry Vyukov <dvyukov@google.com> | 2015-07-22 13:09:26 +0200 |
|---|---|---|
| committer | Russ Cox <rsc@golang.org> | 2015-07-22 15:47:16 +0000 |
| commit | ae1ea2aa94b366107f4f92a591d102fd32ad86ae (patch) | |
| tree | 762c1f7f9399e385088feff953f271f44809ca30 /src/runtime/pprof | |
| parent | 1a99ba55df902a2657d1ccfc52a60024c22dba98 (diff) | |
| download | go-ae1ea2aa94b366107f4f92a591d102fd32ad86ae.tar.xz | |
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 <rsc@golang.org>
Diffstat (limited to 'src/runtime/pprof')
| -rw-r--r-- | src/runtime/pprof/pprof.go | 27 | ||||
| -rw-r--r-- | src/runtime/pprof/trace_stack_test.go | 285 | ||||
| -rw-r--r-- | src/runtime/pprof/trace_test.go | 461 |
3 files changed, 0 insertions, 773 deletions
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) - } - } -} |
