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