src/runtime/trace/trace_stack_test.go

// 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/testenv"
	"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) {
	testenv.MustHaveGoBuild(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() {
		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", "127.0.0.1:0")
	if err != nil {
		t.Fatalf("failed to listen: %v", err)
	}
	go func() {
		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() {
		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

	Stop()
	events, _ := parseTrace(t, buf)

	// Now check that the stacks are correct.
	type frame struct {
		Fn   string
		Line int
	}
	type eventDesc struct {
		Type byte
		Stk  []frame
	}
	want := []eventDesc{
		{trace.EvGCStart, []frame{
			{"runtime.GC", 0},
			{"runtime/trace_test.TestTraceSymbolize", 107},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoStart, []frame{
			{"runtime/trace_test.TestTraceSymbolize.func1", 37},
		}},
		{trace.EvGoSched, []frame{
			{"runtime/trace_test.TestTraceSymbolize", 108},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoCreate, []frame{
			{"runtime/trace_test.TestTraceSymbolize", 37},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoStop, []frame{
			{"runtime.block", 0},
			{"runtime/trace_test.TestTraceSymbolize.func1", 38},
		}},
		{trace.EvGoStop, []frame{
			{"runtime.chansend1", 0},
			{"runtime/trace_test.TestTraceSymbolize.func2", 42},
		}},
		{trace.EvGoStop, []frame{
			{"runtime.chanrecv1", 0},
			{"runtime/trace_test.TestTraceSymbolize.func3", 46},
		}},
		{trace.EvGoBlockRecv, []frame{
			{"runtime.chanrecv1", 0},
			{"runtime/trace_test.TestTraceSymbolize.func4", 50},
		}},
		{trace.EvGoUnblock, []frame{
			{"runtime.chansend1", 0},
			{"runtime/trace_test.TestTraceSymbolize", 110},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoBlockSend, []frame{
			{"runtime.chansend1", 0},
			{"runtime/trace_test.TestTraceSymbolize.func5", 54},
		}},
		{trace.EvGoUnblock, []frame{
			{"runtime.chanrecv1", 0},
			{"runtime/trace_test.TestTraceSymbolize", 111},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoBlockSelect, []frame{
			{"runtime.selectgo", 0},
			{"runtime/trace_test.TestTraceSymbolize.func6", 59},
		}},
		{trace.EvGoUnblock, []frame{
			{"runtime.selectgo", 0},
			{"runtime/trace_test.TestTraceSymbolize", 112},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoBlockSync, []frame{
			{"sync.(*Mutex).Lock", 0},
			{"runtime/trace_test.TestTraceSymbolize.func7", 67},
		}},
		{trace.EvGoUnblock, []frame{
			{"sync.(*Mutex).Unlock", 0},
			{"runtime/trace_test.TestTraceSymbolize", 116},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoBlockSync, []frame{
			{"sync.(*WaitGroup).Wait", 0},
			{"runtime/trace_test.TestTraceSymbolize.func8", 73},
		}},
		{trace.EvGoUnblock, []frame{
			{"sync.(*WaitGroup).Add", 0},
			{"sync.(*WaitGroup).Done", 0},
			{"runtime/trace_test.TestTraceSymbolize", 117},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoBlockCond, []frame{
			{"sync.(*Cond).Wait", 0},
			{"runtime/trace_test.TestTraceSymbolize.func9", 78},
		}},
		{trace.EvGoUnblock, []frame{
			{"sync.(*Cond).Signal", 0},
			{"runtime/trace_test.TestTraceSymbolize", 118},
			{"testing.tRunner", 0},
		}},
		{trace.EvGoSleep, []frame{
			{"time.Sleep", 0},
			{"runtime/trace_test.TestTraceSymbolize", 109},
			{"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", 86},
			}},
			{trace.EvGoSysCall, []frame{
				{"syscall.read", 0},
				{"syscall.Read", 0},
				{"internal/poll.(*FD).Read", 0},
				{"os.(*File).read", 0},
				{"os.(*File).Read", 0},
				{"runtime/trace_test.TestTraceSymbolize.func11", 102},
			}},
		}...)
	}
	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 :: %s:%v", f.Fn, f.File, f.Line)
			}
			t.Logf("---")
		}
		t.Logf("======")
	}
}