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