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