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