1// Copyright 2014 The Go Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style
3// license that can be found in the LICENSE file.
4
5package trace_test
6
7import (
8	"bytes"
9	"fmt"
10	"internal/testenv"
11	"internal/trace"
12	"net"
13	"os"
14	"runtime"
15	. "runtime/trace"
16	"strings"
17	"sync"
18	"testing"
19	"text/tabwriter"
20	"time"
21)
22
23// TestTraceSymbolize tests symbolization and that events has proper stacks.
24// In particular that we strip bottom uninteresting frames like goexit,
25// top uninteresting frames (runtime guts).
26func TestTraceSymbolize(t *testing.T) {
27	skipTraceSymbolizeTestIfNecessary(t)
28
29	buf := new(bytes.Buffer)
30	if err := Start(buf); err != nil {
31		t.Fatalf("failed to start tracing: %v", err)
32	}
33	defer Stop() // in case of early return
34
35	// Now we will do a bunch of things for which we verify stacks later.
36	// It is impossible to ensure that a goroutine has actually blocked
37	// on a channel, in a select or otherwise. So we kick off goroutines
38	// that need to block first in the hope that while we are executing
39	// the rest of the test, they will block.
40	go func() { // func1
41		select {}
42	}()
43	go func() { // func2
44		var c chan int
45		c <- 0
46	}()
47	go func() { // func3
48		var c chan int
49		<-c
50	}()
51	done1 := make(chan bool)
52	go func() { // func4
53		<-done1
54	}()
55	done2 := make(chan bool)
56	go func() { // func5
57		done2 <- true
58	}()
59	c1 := make(chan int)
60	c2 := make(chan int)
61	go func() { // func6
62		select {
63		case <-c1:
64		case <-c2:
65		}
66	}()
67	var mu sync.Mutex
68	mu.Lock()
69	go func() { // func7
70		mu.Lock()
71		mu.Unlock()
72	}()
73	var wg sync.WaitGroup
74	wg.Add(1)
75	go func() { // func8
76		wg.Wait()
77	}()
78	cv := sync.NewCond(&sync.Mutex{})
79	go func() { // func9
80		cv.L.Lock()
81		cv.Wait()
82		cv.L.Unlock()
83	}()
84	ln, err := net.Listen("tcp", "127.0.0.1:0")
85	if err != nil {
86		t.Fatalf("failed to listen: %v", err)
87	}
88	go func() { // func10
89		c, err := ln.Accept()
90		if err != nil {
91			t.Errorf("failed to accept: %v", err)
92			return
93		}
94		c.Close()
95	}()
96	rp, wp, err := os.Pipe()
97	if err != nil {
98		t.Fatalf("failed to create a pipe: %v", err)
99	}
100	defer rp.Close()
101	defer wp.Close()
102	pipeReadDone := make(chan bool)
103	go func() { // func11
104		var data [1]byte
105		rp.Read(data[:])
106		pipeReadDone <- true
107	}()
108
109	time.Sleep(100 * time.Millisecond)
110	runtime.GC()
111	runtime.Gosched()
112	time.Sleep(100 * time.Millisecond) // the last chance for the goroutines above to block
113	done1 <- true
114	<-done2
115	select {
116	case c1 <- 0:
117	case c2 <- 0:
118	}
119	mu.Unlock()
120	wg.Done()
121	cv.Signal()
122	c, err := net.Dial("tcp", ln.Addr().String())
123	if err != nil {
124		t.Fatalf("failed to dial: %v", err)
125	}
126	c.Close()
127	var data [1]byte
128	wp.Write(data[:])
129	<-pipeReadDone
130
131	oldGoMaxProcs := runtime.GOMAXPROCS(0)
132	runtime.GOMAXPROCS(oldGoMaxProcs + 1)
133
134	Stop()
135
136	runtime.GOMAXPROCS(oldGoMaxProcs)
137
138	events, _ := parseTrace(t, buf)
139
140	// Now check that the stacks are correct.
141	type eventDesc struct {
142		Type byte
143		Stk  []frame
144	}
145	want := []eventDesc{
146		{trace.EvGCStart, []frame{
147			{"runtime.GC", 0},
148			{"runtime/trace_test.TestTraceSymbolize", 0},
149			{"testing.tRunner", 0},
150		}},
151		{trace.EvGoStart, []frame{
152			{"runtime/trace_test.TestTraceSymbolize.func1", 0},
153		}},
154		{trace.EvGoSched, []frame{
155			{"runtime/trace_test.TestTraceSymbolize", 111},
156			{"testing.tRunner", 0},
157		}},
158		{trace.EvGoCreate, []frame{
159			{"runtime/trace_test.TestTraceSymbolize", 40},
160			{"testing.tRunner", 0},
161		}},
162		{trace.EvGoStop, []frame{
163			{"runtime.block", 0},
164			{"runtime/trace_test.TestTraceSymbolize.func1", 0},
165		}},
166		{trace.EvGoStop, []frame{
167			{"runtime.chansend1", 0},
168			{"runtime/trace_test.TestTraceSymbolize.func2", 0},
169		}},
170		{trace.EvGoStop, []frame{
171			{"runtime.chanrecv1", 0},
172			{"runtime/trace_test.TestTraceSymbolize.func3", 0},
173		}},
174		{trace.EvGoBlockRecv, []frame{
175			{"runtime.chanrecv1", 0},
176			{"runtime/trace_test.TestTraceSymbolize.func4", 0},
177		}},
178		{trace.EvGoUnblock, []frame{
179			{"runtime.chansend1", 0},
180			{"runtime/trace_test.TestTraceSymbolize", 113},
181			{"testing.tRunner", 0},
182		}},
183		{trace.EvGoBlockSend, []frame{
184			{"runtime.chansend1", 0},
185			{"runtime/trace_test.TestTraceSymbolize.func5", 0},
186		}},
187		{trace.EvGoUnblock, []frame{
188			{"runtime.chanrecv1", 0},
189			{"runtime/trace_test.TestTraceSymbolize", 114},
190			{"testing.tRunner", 0},
191		}},
192		{trace.EvGoBlockSelect, []frame{
193			{"runtime.selectgo", 0},
194			{"runtime/trace_test.TestTraceSymbolize.func6", 0},
195		}},
196		{trace.EvGoUnblock, []frame{
197			{"runtime.selectgo", 0},
198			{"runtime/trace_test.TestTraceSymbolize", 115},
199			{"testing.tRunner", 0},
200		}},
201		{trace.EvGoBlockSync, []frame{
202			{"sync.(*Mutex).Lock", 0},
203			{"runtime/trace_test.TestTraceSymbolize.func7", 0},
204		}},
205		{trace.EvGoUnblock, []frame{
206			{"sync.(*Mutex).Unlock", 0},
207			{"runtime/trace_test.TestTraceSymbolize", 0},
208			{"testing.tRunner", 0},
209		}},
210		{trace.EvGoBlockSync, []frame{
211			{"sync.(*WaitGroup).Wait", 0},
212			{"runtime/trace_test.TestTraceSymbolize.func8", 0},
213		}},
214		{trace.EvGoUnblock, []frame{
215			{"sync.(*WaitGroup).Add", 0},
216			{"sync.(*WaitGroup).Done", 0},
217			{"runtime/trace_test.TestTraceSymbolize", 120},
218			{"testing.tRunner", 0},
219		}},
220		{trace.EvGoBlockCond, []frame{
221			{"sync.(*Cond).Wait", 0},
222			{"runtime/trace_test.TestTraceSymbolize.func9", 0},
223		}},
224		{trace.EvGoUnblock, []frame{
225			{"sync.(*Cond).Signal", 0},
226			{"runtime/trace_test.TestTraceSymbolize", 0},
227			{"testing.tRunner", 0},
228		}},
229		{trace.EvGoSleep, []frame{
230			{"time.Sleep", 0},
231			{"runtime/trace_test.TestTraceSymbolize", 0},
232			{"testing.tRunner", 0},
233		}},
234		{trace.EvGomaxprocs, []frame{
235			{"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
236			{"runtime.startTheWorldGC", 0},
237			{"runtime.GOMAXPROCS", 0},
238			{"runtime/trace_test.TestTraceSymbolize", 0},
239			{"testing.tRunner", 0},
240		}},
241	}
242	// Stacks for the following events are OS-dependent due to OS-specific code in net package.
243	if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
244		want = append(want, []eventDesc{
245			{trace.EvGoBlockNet, []frame{
246				{"internal/poll.(*FD).Accept", 0},
247				{"net.(*netFD).accept", 0},
248				{"net.(*TCPListener).accept", 0},
249				{"net.(*TCPListener).Accept", 0},
250				{"runtime/trace_test.TestTraceSymbolize.func10", 0},
251			}},
252			{trace.EvGoSysCall, []frame{
253				{"syscall.read", 0},
254				{"syscall.Read", 0},
255				{"internal/poll.ignoringEINTRIO", 0},
256				{"internal/poll.(*FD).Read", 0},
257				{"os.(*File).read", 0},
258				{"os.(*File).Read", 0},
259				{"runtime/trace_test.TestTraceSymbolize.func11", 0},
260			}},
261		}...)
262	}
263	matched := make([]bool, len(want))
264	for _, ev := range events {
265	wantLoop:
266		for i, w := range want {
267			if matched[i] || w.Type != ev.Type || len(w.Stk) != len(ev.Stk) {
268				continue
269			}
270
271			for fi, f := range ev.Stk {
272				wf := w.Stk[fi]
273				if wf.Fn != f.Fn || wf.Line != 0 && wf.Line != f.Line {
274					continue wantLoop
275				}
276			}
277			matched[i] = true
278		}
279	}
280	for i, w := range want {
281		if matched[i] {
282			continue
283		}
284		seen, n := dumpEventStacks(w.Type, events)
285		t.Errorf("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
286			trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
287	}
288}
289
290func skipTraceSymbolizeTestIfNecessary(t *testing.T) {
291	testenv.MustHaveGoBuild(t)
292	if IsEnabled() {
293		t.Skip("skipping because -test.trace is set")
294	}
295}
296
297func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
298	matched := 0
299	o := new(bytes.Buffer)
300	tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
301	for _, ev := range events {
302		if ev.Type != typ {
303			continue
304		}
305		matched++
306		fmt.Fprintf(tw, "Offset %d\n", ev.Off)
307		for _, f := range ev.Stk {
308			fname := f.File
309			if idx := strings.Index(fname, "/go/src/"); idx > 0 {
310				fname = fname[idx:]
311			}
312			fmt.Fprintf(tw, "  %v\t%s:%d\n", f.Fn, fname, f.Line)
313		}
314	}
315	tw.Flush()
316	return o.Bytes(), matched
317}
318
319type frame struct {
320	Fn   string
321	Line int
322}
323
324func dumpFrames(frames []frame) []byte {
325	o := new(bytes.Buffer)
326	tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
327
328	for _, f := range frames {
329		fmt.Fprintf(tw, "  %v\t :%d\n", f.Fn, f.Line)
330	}
331	tw.Flush()
332	return o.Bytes()
333}
334