src/runtime/trace/trace_stack_test.go

   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
 133         // Now check that the stacks are correct.
 134         type frame struct {
 135                 Fn   string
 136                 Line int
 137         }
 138         type eventDesc struct {
 139                 Type byte
 140                 Stk  []frame
 141         }
 142         want := []eventDesc{
 143                 {trace.EvGCStart, []frame{
 144                         {"runtime.GC", 0},
 145                         {"runtime/trace_test.TestTraceSymbolize", 106},
 146                         {"testing.tRunner", 0},
 147                 }},
 148                 {trace.EvGoStart, []frame{
 149                         {"runtime/trace_test.TestTraceSymbolize.func1", 37},
 150                 }},
 151                 {trace.EvGoSched, []frame{
 152                         {"runtime/trace_test.TestTraceSymbolize", 107},
 153                         {"testing.tRunner", 0},
 154                 }},
 155                 {trace.EvGoCreate, []frame{
 156                         {"runtime/trace_test.TestTraceSymbolize", 39},
 157                         {"testing.tRunner", 0},
 158                 }},
 159                 {trace.EvGoStop, []frame{
 160                         {"runtime.block", 0},
 161                         {"runtime/trace_test.TestTraceSymbolize.func1", 38},
 162                 }},
 163                 {trace.EvGoStop, []frame{
 164                         {"runtime.chansend1", 0},
 165                         {"runtime/trace_test.TestTraceSymbolize.func2", 42},
 166                 }},
 167                 {trace.EvGoStop, []frame{
 168                         {"runtime.chanrecv1", 0},
 169                         {"runtime/trace_test.TestTraceSymbolize.func3", 46},
 170                 }},
 171                 {trace.EvGoBlockRecv, []frame{
 172                         {"runtime.chanrecv1", 0},
 173                         {"runtime/trace_test.TestTraceSymbolize.func4", 50},
 174                 }},
 175                 {trace.EvGoUnblock, []frame{
 176                         {"runtime.chansend1", 0},
 177                         {"runtime/trace_test.TestTraceSymbolize", 109},
 178                         {"testing.tRunner", 0},
 179                 }},
 180                 {trace.EvGoBlockSend, []frame{
 181                         {"runtime.chansend1", 0},
 182                         {"runtime/trace_test.TestTraceSymbolize.func5", 54},
 183                 }},
 184                 {trace.EvGoUnblock, []frame{
 185                         {"runtime.chanrecv1", 0},
 186                         {"runtime/trace_test.TestTraceSymbolize", 110},
 187                         {"testing.tRunner", 0},
 188                 }},
 189                 {trace.EvGoBlockSelect, []frame{
 190                         {"runtime.selectgo", 0},
 191                         {"runtime/trace_test.TestTraceSymbolize.func6", 59},
 192                 }},
 193                 {trace.EvGoUnblock, []frame{
 194                         {"runtime.selectgo", 0},
 195                         {"runtime/trace_test.TestTraceSymbolize", 111},
 196                         {"testing.tRunner", 0},
 197                 }},
 198                 {trace.EvGoBlockSync, []frame{
 199                         {"sync.(*Mutex).Lock", 0},
 200                         {"runtime/trace_test.TestTraceSymbolize.func7", 67},
 201                 }},
 202                 {trace.EvGoUnblock, []frame{
 203                         {"sync.(*Mutex).Unlock", 0},
 204                         {"runtime/trace_test.TestTraceSymbolize", 115},
 205                         {"testing.tRunner", 0},
 206                 }},
 207                 {trace.EvGoBlockSync, []frame{
 208                         {"sync.(*WaitGroup).Wait", 0},
 209                         {"runtime/trace_test.TestTraceSymbolize.func8", 73},
 210                 }},
 211                 {trace.EvGoUnblock, []frame{
 212                         {"sync.(*WaitGroup).Add", 0},
 213                         {"sync.(*WaitGroup).Done", 0},
 214                         {"runtime/trace_test.TestTraceSymbolize", 116},
 215                         {"testing.tRunner", 0},
 216                 }},
 217                 {trace.EvGoBlockCond, []frame{
 218                         {"sync.(*Cond).Wait", 0},
 219                         {"runtime/trace_test.TestTraceSymbolize.func9", 78},
 220                 }},
 221                 {trace.EvGoUnblock, []frame{
 222                         {"sync.(*Cond).Signal", 0},
 223                         {"runtime/trace_test.TestTraceSymbolize", 117},
 224                         {"testing.tRunner", 0},
 225                 }},
 226                 {trace.EvGoSleep, []frame{
 227                         {"time.Sleep", 0},
 228                         {"runtime/trace_test.TestTraceSymbolize", 108},
 229                         {"testing.tRunner", 0},
 230                 }},
 231         }
 232         // Stacks for the following events are OS-dependent due to OS-specific code in net package.
 233         if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
 234                 want = append(want, []eventDesc{
 235                         {trace.EvGoBlockNet, []frame{
 236                                 {"net.(*netFD).accept", 0},
 237                                 {"net.(*TCPListener).accept", 0},
 238                                 {"net.(*TCPListener).Accept", 0},
 239                                 {"runtime/trace_test.TestTraceSymbolize.func10", 86},
 240                         }},
 241                         {trace.EvGoSysCall, []frame{
 242                                 {"syscall.read", 0},
 243                                 {"syscall.Read", 0},
 244                                 {"os.(*File).read", 0},
 245                                 {"os.(*File).Read", 0},
 246                                 {"runtime/trace_test.TestTraceSymbolize.func11", 101},
 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:%v", f.Fn, f.Line)
 280                         }
 281                         t.Logf("---")
 282                 }
 283         }
 284 }