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