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.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                                 {"net.(*netFD).accept", 0},
 235                                 {"net.(*TCPListener).accept", 0},
 236                                 {"net.(*TCPListener).Accept", 0},
 237                                 {"runtime/trace_test.TestTraceSymbolize.func10", 86},
 238                         }},
 239                         {trace.EvGoSysCall, []frame{
 240                                 {"syscall.read", 0},
 241                                 {"syscall.Read", 0},
 242                                 {"os.(*File).read", 0},
 243                                 {"os.(*File).Read", 0},
 244                                 {"runtime/trace_test.TestTraceSymbolize.func11", 102},
 245                         }},
 246                 }...)
 247         }
 248         matched := make([]bool, len(want))
 249         for _, ev := range events {
 250         wantLoop:
 251                 for i, w := range want {
 252                         if matched[i] || w.Type != ev.Type || len(w.Stk) != len(ev.Stk) {
 253                                 continue
 254                         }
 255
 256                         for fi, f := range ev.Stk {
 257                                 wf := w.Stk[fi]
 258                                 if wf.Fn != f.Fn || wf.Line != 0 && wf.Line != f.Line {
 259                                         continue wantLoop
 260                                 }
 261                         }
 262                         matched[i] = true
 263                 }
 264         }
 265         for i, m := range matched {
 266                 if m {
 267                         continue
 268                 }
 269                 w := want[i]
 270                 t.Errorf("did not match event %v at %v:%v", trace.EventDescriptions[w.Type].Name, w.Stk[0].Fn, w.Stk[0].Line)
 271                 t.Errorf("seen the following events of this type:")
 272                 for _, ev := range events {
 273                         if ev.Type != w.Type {
 274                                 continue
 275                         }
 276                         for _, f := range ev.Stk {
 277                                 t.Logf("  %v:%v", f.Fn, f.Line)
 278                         }
 279                         t.Logf("---")
 280                 }
 281         }
 282 }