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