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