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