| // 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 TestTraceStartStop(t *testing.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) { |
| 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) { |
| 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 == 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, error) { |
| events, err := trace.Parse(r) |
| if err == trace.ErrTimeOrder { |
| t.Skipf("skipping trace: %v", err) |
| } |
| 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) { |
| 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 runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" { |
| // 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() |
| _, _, err = parseTrace(t, 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) { |
| 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. |
| n := int(1e3) |
| if runtime.GOOS == "openbsd" && runtime.GOARCH == "arm" { |
| // 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() |
| }() |
| |
| 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(t, buf); err != nil { |
| t.Fatalf("failed to parse trace: %v", err) |
| } |
| } |
| <-outerDone |
| } |
| |
| func TestTraceFutileWakeup(t *testing.T) { |
| 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(t, 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) |
| } |
| } |
| } |