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