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.Errorf("failed to accept: %v", err) 89 return 90 } 91 c.Close() 92 }() 93 rp, wp, err := os.Pipe() 94 if err != nil { 95 t.Fatalf("failed to create a pipe: %v", err) 96 } 97 defer rp.Close() 98 defer wp.Close() 99 pipeReadDone := make(chan bool) 100 go func() { 101 var data [1]byte 102 rp.Read(data[:]) 103 pipeReadDone <- true 104 }() 105 106 time.Sleep(100 * time.Millisecond) 107 runtime.GC() 108 runtime.Gosched() 109 time.Sleep(100 * time.Millisecond) // the last chance for the goroutines above to block 110 done1 <- true 111 <-done2 112 select { 113 case c1 <- 0: 114 case c2 <- 0: 115 } 116 mu.Unlock() 117 wg.Done() 118 cv.Signal() 119 c, err := net.Dial("tcp", ln.Addr().String()) 120 if err != nil { 121 t.Fatalf("failed to dial: %v", err) 122 } 123 c.Close() 124 var data [1]byte 125 wp.Write(data[:]) 126 <-pipeReadDone 127 128 Stop() 129 events, _ := parseTrace(t, buf) 130 131 // Now check that the stacks are correct. 132 type frame struct { 133 Fn string 134 Line int 135 } 136 type eventDesc struct { 137 Type byte 138 Stk []frame 139 } 140 want := []eventDesc{ 141 {trace.EvGCStart, []frame{ 142 {"runtime.GC", 0}, 143 {"runtime/trace_test.TestTraceSymbolize", 107}, 144 {"testing.tRunner", 0}, 145 }}, 146 {trace.EvGoStart, []frame{ 147 {"runtime/trace_test.TestTraceSymbolize.func1", 37}, 148 }}, 149 {trace.EvGoSched, []frame{ 150 {"runtime/trace_test.TestTraceSymbolize", 108}, 151 {"testing.tRunner", 0}, 152 }}, 153 {trace.EvGoCreate, []frame{ 154 {"runtime/trace_test.TestTraceSymbolize", 37}, 155 {"testing.tRunner", 0}, 156 }}, 157 {trace.EvGoStop, []frame{ 158 {"runtime.block", 0}, 159 {"runtime/trace_test.TestTraceSymbolize.func1", 38}, 160 }}, 161 {trace.EvGoStop, []frame{ 162 {"runtime.chansend1", 0}, 163 {"runtime/trace_test.TestTraceSymbolize.func2", 42}, 164 }}, 165 {trace.EvGoStop, []frame{ 166 {"runtime.chanrecv1", 0}, 167 {"runtime/trace_test.TestTraceSymbolize.func3", 46}, 168 }}, 169 {trace.EvGoBlockRecv, []frame{ 170 {"runtime.chanrecv1", 0}, 171 {"runtime/trace_test.TestTraceSymbolize.func4", 50}, 172 }}, 173 {trace.EvGoUnblock, []frame{ 174 {"runtime.chansend1", 0}, 175 {"runtime/trace_test.TestTraceSymbolize", 110}, 176 {"testing.tRunner", 0}, 177 }}, 178 {trace.EvGoBlockSend, []frame{ 179 {"runtime.chansend1", 0}, 180 {"runtime/trace_test.TestTraceSymbolize.func5", 54}, 181 }}, 182 {trace.EvGoUnblock, []frame{ 183 {"runtime.chanrecv1", 0}, 184 {"runtime/trace_test.TestTraceSymbolize", 111}, 185 {"testing.tRunner", 0}, 186 }}, 187 {trace.EvGoBlockSelect, []frame{ 188 {"runtime.selectgo", 0}, 189 {"runtime/trace_test.TestTraceSymbolize.func6", 59}, 190 }}, 191 {trace.EvGoUnblock, []frame{ 192 {"runtime.selectgo", 0}, 193 {"runtime/trace_test.TestTraceSymbolize", 112}, 194 {"testing.tRunner", 0}, 195 }}, 196 {trace.EvGoBlockSync, []frame{ 197 {"sync.(*Mutex).Lock", 0}, 198 {"runtime/trace_test.TestTraceSymbolize.func7", 67}, 199 }}, 200 {trace.EvGoUnblock, []frame{ 201 {"sync.(*Mutex).Unlock", 0}, 202 {"runtime/trace_test.TestTraceSymbolize", 116}, 203 {"testing.tRunner", 0}, 204 }}, 205 {trace.EvGoBlockSync, []frame{ 206 {"sync.(*WaitGroup).Wait", 0}, 207 {"runtime/trace_test.TestTraceSymbolize.func8", 73}, 208 }}, 209 {trace.EvGoUnblock, []frame{ 210 {"sync.(*WaitGroup).Add", 0}, 211 {"sync.(*WaitGroup).Done", 0}, 212 {"runtime/trace_test.TestTraceSymbolize", 117}, 213 {"testing.tRunner", 0}, 214 }}, 215 {trace.EvGoBlockCond, []frame{ 216 {"sync.(*Cond).Wait", 0}, 217 {"runtime/trace_test.TestTraceSymbolize.func9", 78}, 218 }}, 219 {trace.EvGoUnblock, []frame{ 220 {"sync.(*Cond).Signal", 0}, 221 {"runtime/trace_test.TestTraceSymbolize", 118}, 222 {"testing.tRunner", 0}, 223 }}, 224 {trace.EvGoSleep, []frame{ 225 {"time.Sleep", 0}, 226 {"runtime/trace_test.TestTraceSymbolize", 109}, 227 {"testing.tRunner", 0}, 228 }}, 229 } 230 // Stacks for the following events are OS-dependent due to OS-specific code in net package. 231 if runtime.GOOS != "windows" && runtime.GOOS != "plan9" { 232 want = append(want, []eventDesc{ 233 {trace.EvGoBlockNet, []frame{ 234 {"internal/poll.(*FD).Accept", 0}, 235 {"net.(*netFD).accept", 0}, 236 {"net.(*TCPListener).accept", 0}, 237 {"net.(*TCPListener).Accept", 0}, 238 {"runtime/trace_test.TestTraceSymbolize.func10", 86}, 239 }}, 240 {trace.EvGoSysCall, []frame{ 241 {"syscall.read", 0}, 242 {"syscall.Read", 0}, 243 {"internal/poll.(*FD).Read", 0}, 244 {"os.(*File).read", 0}, 245 {"os.(*File).Read", 0}, 246 {"runtime/trace_test.TestTraceSymbolize.func11", 102}, 247 }}, 248 }...) 249 } 250 matched := make([]bool, len(want)) 251 for _, ev := range events { 252 wantLoop: 253 for i, w := range want { 254 if matched[i] || w.Type != ev.Type || len(w.Stk) != len(ev.Stk) { 255 continue 256 } 257 258 for fi, f := range ev.Stk { 259 wf := w.Stk[fi] 260 if wf.Fn != f.Fn || wf.Line != 0 && wf.Line != f.Line { 261 continue wantLoop 262 } 263 } 264 matched[i] = true 265 } 266 } 267 for i, m := range matched { 268 if m { 269 continue 270 } 271 w := want[i] 272 t.Errorf("did not match event %v at %v:%v", trace.EventDescriptions[w.Type].Name, w.Stk[0].Fn, w.Stk[0].Line) 273 t.Errorf("seen the following events of this type:") 274 for _, ev := range events { 275 if ev.Type != w.Type { 276 continue 277 } 278 for _, f := range ev.Stk { 279 t.Logf(" %v :: %s:%v", f.Fn, f.File, f.Line) 280 } 281 t.Logf("---") 282 } 283 t.Logf("======") 284 } 285 } 286
