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.GOMAXPROCS", 0},
 237                         {"runtime/trace_test.TestTraceSymbolize", 0},
 238                         {"testing.tRunner", 0},
 239                 }},
 240         }
 241         // Stacks for the following events are OS-dependent due to OS-specific code in net package.
 242         if runtime.GOOS != "windows" && runtime.GOOS != "plan9" {
 243                 want = append(want, []eventDesc{
 244                         {trace.EvGoBlockNet, []frame{
 245                                 {"internal/poll.(*FD).Accept", 0},
 246                                 {"net.(*netFD).accept", 0},
 247                                 {"net.(*TCPListener).accept", 0},
 248                                 {"net.(*TCPListener).Accept", 0},
 249                                 {"runtime/trace_test.TestTraceSymbolize.func10", 0},
 250                         }},
 251                         {trace.EvGoSysCall, []frame{
 252                                 {"syscall.read", 0},
 253                                 {"syscall.Read", 0},
 254                                 {"internal/poll.(*FD).Read", 0},
 255                                 {"os.(*File).read", 0},
 256                                 {"os.(*File).Read", 0},
 257                                 {"runtime/trace_test.TestTraceSymbolize.func11", 0},
 258                         }},
 259                 }...)
 260         }
 261         matched := make([]bool, len(want))
 262         for _, ev := range events {
 263         wantLoop:
 264                 for i, w := range want {
 265                         if matched[i] || w.Type != ev.Type || len(w.Stk) != len(ev.Stk) {
 266                                 continue
 267                         }
 268
 269                         for fi, f := range ev.Stk {
 270                                 wf := w.Stk[fi]
 271                                 if wf.Fn != f.Fn || wf.Line != 0 && wf.Line != f.Line {
 272                                         continue wantLoop
 273                                 }
 274                         }
 275                         matched[i] = true
 276                 }
 277         }
 278         for i, w := range want {
 279                 if matched[i] {
 280                         continue
 281                 }
 282                 seen, n := dumpEventStacks(w.Type, events)
 283                 t.Errorf("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
 284                         trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
 285         }
 286 }
 287
 288 func skipTraceSymbolizeTestIfNecessary(t *testing.T) {
 289         testenv.MustHaveGoBuild(t)
 290         if IsEnabled() {
 291                 t.Skip("skipping because -test.trace is set")
 292         }
 293 }
 294
 295 func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
 296         matched := 0
 297         o := new(bytes.Buffer)
 298         tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
 299         for _, ev := range events {
 300                 if ev.Type != typ {
 301                         continue
 302                 }
 303                 matched++
 304                 fmt.Fprintf(tw, "Offset %d\n", ev.Off)
 305                 for _, f := range ev.Stk {
 306                         fname := f.File
 307                         if idx := strings.Index(fname, "/go/src/"); idx > 0 {
 308                                 fname = fname[idx:]
 309                         }
 310                         fmt.Fprintf(tw, "  %v\t%s:%d\n", f.Fn, fname, f.Line)
 311                 }
 312         }
 313         tw.Flush()
 314         return o.Bytes(), matched
 315 }
 316
 317 type frame struct {
 318         Fn   string
 319         Line int
 320 }
 321
 322 func dumpFrames(frames []frame) []byte {
 323         o := new(bytes.Buffer)
 324         tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
 325
 326         for _, f := range frames {
 327                 fmt.Fprintf(tw, "  %v\t :%d\n", f.Fn, f.Line)
 328         }
 329         tw.Flush()
 330         return o.Bytes()
 331 }