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