src/runtime/trace/trace_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/trace"
  10         "io"
  11         "net"
  12         "os"
  13         "runtime"
  14         . "runtime/trace"
  15         "sync"
  16         "testing"
  17         "time"
  18 )
  19
  20 func skipTraceTestsIfNeeded(t *testing.T) {
  21         switch runtime.GOOS {
  22         case "solaris":
  23                 t.Skip("skipping: solaris timer can go backwards (https://golang.org/issue/8976)")
  24         case "darwin":
  25                 switch runtime.GOARCH {
  26                 case "arm", "arm64":
  27                         // TODO(rsc): What does this have to do with the trace tests?
  28                         // There is no forking here.
  29                         t.Skipf("skipping on %s/%s, cannot fork", runtime.GOOS, runtime.GOARCH)
  30                 }
  31         }
  32
  33         switch runtime.GOARCH {
  34         case "arm":
  35                 t.Skip("skipping: arm tests fail with 'failed to parse trace' (https://golang.org/issue/9725)")
  36         }
  37 }
  38
  39 func TestTraceStartStop(t *testing.T) {
  40         skipTraceTestsIfNeeded(t)
  41         buf := new(bytes.Buffer)
  42         if err := Start(buf); err != nil {
  43                 t.Fatalf("failed to start tracing: %v", err)
  44         }
  45         Stop()
  46         size := buf.Len()
  47         if size == 0 {
  48                 t.Fatalf("trace is empty")
  49         }
  50         time.Sleep(100 * time.Millisecond)
  51         if size != buf.Len() {
  52                 t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
  53         }
  54 }
  55
  56 func TestTraceDoubleStart(t *testing.T) {
  57         skipTraceTestsIfNeeded(t)
  58         Stop()
  59         buf := new(bytes.Buffer)
  60         if err := Start(buf); err != nil {
  61                 t.Fatalf("failed to start tracing: %v", err)
  62         }
  63         if err := Start(buf); err == nil {
  64                 t.Fatalf("succeed to start tracing second time")
  65         }
  66         Stop()
  67         Stop()
  68 }
  69
  70 func TestTrace(t *testing.T) {
  71         skipTraceTestsIfNeeded(t)
  72         buf := new(bytes.Buffer)
  73         if err := Start(buf); err != nil {
  74                 t.Fatalf("failed to start tracing: %v", err)
  75         }
  76         Stop()
  77         _, err := trace.Parse(buf)
  78         if err != nil {
  79                 t.Fatalf("failed to parse trace: %v", err)
  80         }
  81 }
  82
  83 func parseTrace(r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc, error) {
  84         events, err := trace.Parse(r)
  85         if err != nil {
  86                 return nil, nil, err
  87         }
  88         gs := trace.GoroutineStats(events)
  89         for goid := range gs {
  90                 // We don't do any particular checks on the result at the moment.
  91                 // But still check that RelatedGoroutines does not crash, hang, etc.
  92                 _ = trace.RelatedGoroutines(events, goid)
  93         }
  94         return events, gs, nil
  95 }
  96
  97 func TestTraceStress(t *testing.T) {
  98         skipTraceTestsIfNeeded(t)
  99
 100         var wg sync.WaitGroup
 101         done := make(chan bool)
 102
 103         // Create a goroutine blocked before tracing.
 104         wg.Add(1)
 105         go func() {
 106                 <-done
 107                 wg.Done()
 108         }()
 109
 110         // Create a goroutine blocked in syscall before tracing.
 111         rp, wp, err := os.Pipe()
 112         if err != nil {
 113                 t.Fatalf("failed to create pipe: %v", err)
 114         }
 115         defer func() {
 116                 rp.Close()
 117                 wp.Close()
 118         }()
 119         wg.Add(1)
 120         go func() {
 121                 var tmp [1]byte
 122                 rp.Read(tmp[:])
 123                 <-done
 124                 wg.Done()
 125         }()
 126         time.Sleep(time.Millisecond) // give the goroutine above time to block
 127
 128         buf := new(bytes.Buffer)
 129         if err := Start(buf); err != nil {
 130                 t.Fatalf("failed to start tracing: %v", err)
 131         }
 132
 133         procs := runtime.GOMAXPROCS(10)
 134         time.Sleep(50 * time.Millisecond) // test proc stop/start events
 135
 136         go func() {
 137                 runtime.LockOSThread()
 138                 for {
 139                         select {
 140                         case <-done:
 141                                 return
 142                         default:
 143                                 runtime.Gosched()
 144                         }
 145                 }
 146         }()
 147
 148         runtime.GC()
 149         // Trigger GC from malloc.
 150         for i := 0; i < 1e3; i++ {
 151                 _ = make([]byte, 1<<20)
 152         }
 153
 154         // Create a bunch of busy goroutines to load all Ps.
 155         for p := 0; p < 10; p++ {
 156                 wg.Add(1)
 157                 go func() {
 158                         // Do something useful.
 159                         tmp := make([]byte, 1<<16)
 160                         for i := range tmp {
 161                                 tmp[i]++
 162                         }
 163                         _ = tmp
 164                         <-done
 165                         wg.Done()
 166                 }()
 167         }
 168
 169         // Block in syscall.
 170         wg.Add(1)
 171         go func() {
 172                 var tmp [1]byte
 173                 rp.Read(tmp[:])
 174                 <-done
 175                 wg.Done()
 176         }()
 177
 178         // Test timers.
 179         timerDone := make(chan bool)
 180         go func() {
 181                 time.Sleep(time.Millisecond)
 182                 timerDone <- true
 183         }()
 184         <-timerDone
 185
 186         // A bit of network.
 187         ln, err := net.Listen("tcp", "127.0.0.1:0")
 188         if err != nil {
 189                 t.Fatalf("listen failed: %v", err)
 190         }
 191         defer ln.Close()
 192         go func() {
 193                 c, err := ln.Accept()
 194                 if err != nil {
 195                         return
 196                 }
 197                 time.Sleep(time.Millisecond)
 198                 var buf [1]byte
 199                 c.Write(buf[:])
 200                 c.Close()
 201         }()
 202         c, err := net.Dial("tcp", ln.Addr().String())
 203         if err != nil {
 204                 t.Fatalf("dial failed: %v", err)
 205         }
 206         var tmp [1]byte
 207         c.Read(tmp[:])
 208         c.Close()
 209
 210         go func() {
 211                 runtime.Gosched()
 212                 select {}
 213         }()
 214
 215         // Unblock helper goroutines and wait them to finish.
 216         wp.Write(tmp[:])
 217         wp.Write(tmp[:])
 218         close(done)
 219         wg.Wait()
 220
 221         runtime.GOMAXPROCS(procs)
 222
 223         Stop()
 224         _, _, err = parseTrace(buf)
 225         if err != nil {
 226                 t.Fatalf("failed to parse trace: %v", err)
 227         }
 228 }
 229
 230 // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
 231 // And concurrently with all that start/stop trace 3 times.
 232 func TestTraceStressStartStop(t *testing.T) {
 233         skipTraceTestsIfNeeded(t)
 234
 235         defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
 236         outerDone := make(chan bool)
 237
 238         go func() {
 239                 defer func() {
 240                         outerDone <- true
 241                 }()
 242
 243                 var wg sync.WaitGroup
 244                 done := make(chan bool)
 245
 246                 wg.Add(1)
 247                 go func() {
 248                         <-done
 249                         wg.Done()
 250                 }()
 251
 252                 rp, wp, err := os.Pipe()
 253                 if err != nil {
 254                         t.Fatalf("failed to create pipe: %v", err)
 255                 }
 256                 defer func() {
 257                         rp.Close()
 258                         wp.Close()
 259                 }()
 260                 wg.Add(1)
 261                 go func() {
 262                         var tmp [1]byte
 263                         rp.Read(tmp[:])
 264                         <-done
 265                         wg.Done()
 266                 }()
 267                 time.Sleep(time.Millisecond)
 268
 269                 go func() {
 270                         runtime.LockOSThread()
 271                         for {
 272                                 select {
 273                                 case <-done:
 274                                         return
 275                                 default:
 276                                         runtime.Gosched()
 277                                 }
 278                         }
 279                 }()
 280
 281                 runtime.GC()
 282                 // Trigger GC from malloc.
 283                 for i := 0; i < 1e3; i++ {
 284                         _ = make([]byte, 1<<20)
 285                 }
 286
 287                 // Create a bunch of busy goroutines to load all Ps.
 288                 for p := 0; p < 10; p++ {
 289                         wg.Add(1)
 290                         go func() {
 291                                 // Do something useful.
 292                                 tmp := make([]byte, 1<<16)
 293                                 for i := range tmp {
 294                                         tmp[i]++
 295                                 }
 296                                 _ = tmp
 297                                 <-done
 298                                 wg.Done()
 299                         }()
 300                 }
 301
 302                 // Block in syscall.
 303                 wg.Add(1)
 304                 go func() {
 305                         var tmp [1]byte
 306                         rp.Read(tmp[:])
 307                         <-done
 308                         wg.Done()
 309                 }()
 310
 311                 runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
 312
 313                 // Test timers.
 314                 timerDone := make(chan bool)
 315                 go func() {
 316                         time.Sleep(time.Millisecond)
 317                         timerDone <- true
 318                 }()
 319                 <-timerDone
 320
 321                 // A bit of network.
 322                 ln, err := net.Listen("tcp", "127.0.0.1:0")
 323                 if err != nil {
 324                         t.Fatalf("listen failed: %v", err)
 325                 }
 326                 defer ln.Close()
 327                 go func() {
 328                         c, err := ln.Accept()
 329                         if err != nil {
 330                                 return
 331                         }
 332                         time.Sleep(time.Millisecond)
 333                         var buf [1]byte
 334                         c.Write(buf[:])
 335                         c.Close()
 336                 }()
 337                 c, err := net.Dial("tcp", ln.Addr().String())
 338                 if err != nil {
 339                         t.Fatalf("dial failed: %v", err)
 340                 }
 341                 var tmp [1]byte
 342                 c.Read(tmp[:])
 343                 c.Close()
 344
 345                 go func() {
 346                         runtime.Gosched()
 347                         select {}
 348                 }()
 349
 350                 // Unblock helper goroutines and wait them to finish.
 351                 wp.Write(tmp[:])
 352                 wp.Write(tmp[:])
 353                 close(done)
 354                 wg.Wait()
 355         }()
 356
 357         for i := 0; i < 3; i++ {
 358                 buf := new(bytes.Buffer)
 359                 if err := Start(buf); err != nil {
 360                         t.Fatalf("failed to start tracing: %v", err)
 361                 }
 362                 time.Sleep(time.Millisecond)
 363                 Stop()
 364                 if _, _, err := parseTrace(buf); err != nil {
 365                         t.Fatalf("failed to parse trace: %v", err)
 366                 }
 367         }
 368         <-outerDone
 369 }
 370
 371 func TestTraceFutileWakeup(t *testing.T) {
 372         // The test generates a full-load of futile wakeups on channels,
 373         // and ensures that the trace is consistent after their removal.
 374         skipTraceTestsIfNeeded(t)
 375         if runtime.GOOS == "linux" && runtime.GOARCH == "ppc64le" {
 376                 t.Skip("test is unreliable; issue #10512")
 377         }
 378
 379         buf := new(bytes.Buffer)
 380         if err := Start(buf); err != nil {
 381                 t.Fatalf("failed to start tracing: %v", err)
 382         }
 383
 384         defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
 385         c0 := make(chan int, 1)
 386         c1 := make(chan int, 1)
 387         c2 := make(chan int, 1)
 388         const procs = 2
 389         var done sync.WaitGroup
 390         done.Add(4 * procs)
 391         for p := 0; p < procs; p++ {
 392                 const iters = 1e3
 393                 go func() {
 394                         for i := 0; i < iters; i++ {
 395                                 runtime.Gosched()
 396                                 c0 <- 0
 397                         }
 398                         done.Done()
 399                 }()
 400                 go func() {
 401                         for i := 0; i < iters; i++ {
 402                                 runtime.Gosched()
 403                                 <-c0
 404                         }
 405                         done.Done()
 406                 }()
 407                 go func() {
 408                         for i := 0; i < iters; i++ {
 409                                 runtime.Gosched()
 410                                 select {
 411                                 case c1 <- 0:
 412                                 case c2 <- 0:
 413                                 }
 414                         }
 415                         done.Done()
 416                 }()
 417                 go func() {
 418                         for i := 0; i < iters; i++ {
 419                                 runtime.Gosched()
 420                                 select {
 421                                 case <-c1:
 422                                 case <-c2:
 423                                 }
 424                         }
 425                         done.Done()
 426                 }()
 427         }
 428         done.Wait()
 429
 430         Stop()
 431         events, _, err := parseTrace(buf)
 432         if err != nil {
 433                 t.Fatalf("failed to parse trace: %v", err)
 434         }
 435         // Check that (1) trace does not contain EvFutileWakeup events and
 436         // (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
 437         // (we call runtime.Gosched between all operations, so these would be futile wakeups).
 438         gs := make(map[uint64]int)
 439         for _, ev := range events {
 440                 switch ev.Type {
 441                 case trace.EvFutileWakeup:
 442                         t.Fatalf("found EvFutileWakeup event")
 443                 case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
 444                         if gs[ev.G] == 2 {
 445                                 t.Fatalf("goroutine %v blocked on %v at %v right after start",
 446                                         ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
 447                         }
 448                         if gs[ev.G] == 1 {
 449                                 t.Fatalf("goroutine %v blocked on %v at %v while blocked",
 450                                         ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
 451                         }
 452                         gs[ev.G] = 1
 453                 case trace.EvGoStart:
 454                         if gs[ev.G] == 1 {
 455                                 gs[ev.G] = 2
 456                         }
 457                 default:
 458                         delete(gs, ev.G)
 459                 }
 460         }
 461 }