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         "context"
  10         "flag"
  11         "fmt"
  12         "internal/goexperiment"
  13         "internal/profile"
  14         "internal/race"
  15         "internal/trace"
  16         "io"
  17         "net"
  18         "os"
  19         "runtime"
  20         "runtime/pprof"
  21         . "runtime/trace"
  22         "strconv"
  23         "strings"
  24         "sync"
  25         "testing"
  26         "time"
  27 )
  28
  29 var (
  30         saveTraces = flag.Bool("savetraces", false, "save traces collected by tests")
  31 )
  32
  33 // TestEventBatch tests Flush calls that happen during Start
  34 // don't produce corrupted traces.
  35 func TestEventBatch(t *testing.T) {
  36         if race.Enabled {
  37                 t.Skip("skipping in race mode")
  38         }
  39         if IsEnabled() {
  40                 t.Skip("skipping because -test.trace is set")
  41         }
  42         if testing.Short() {
  43                 t.Skip("skipping in short mode")
  44         }
  45         if goexperiment.ExecTracer2 {
  46                 t.Skip("skipping because this test is incompatible with the new tracer")
  47         }
  48         // During Start, bunch of records are written to reflect the current
  49         // snapshot of the program, including state of each goroutines.
  50         // And some string constants are written to the trace to aid trace
  51         // parsing. This test checks Flush of the buffer occurred during
  52         // this process doesn't cause corrupted traces.
  53         // When a Flush is called during Start is complicated
  54         // so we test with a range of number of goroutines hoping that one
  55         // of them triggers Flush.
  56         // This range was chosen to fill up a ~64KB buffer with traceEvGoCreate
  57         // and traceEvGoWaiting events (12~13bytes per goroutine).
  58         for g := 4950; g < 5050; g++ {
  59                 n := g
  60                 t.Run("G="+strconv.Itoa(n), func(t *testing.T) {
  61                         var wg sync.WaitGroup
  62                         wg.Add(n)
  63
  64                         in := make(chan bool, 1000)
  65                         for i := 0; i < n; i++ {
  66                                 go func() {
  67                                         <-in
  68                                         wg.Done()
  69                                 }()
  70                         }
  71                         buf := new(bytes.Buffer)
  72                         if err := Start(buf); err != nil {
  73                                 t.Fatalf("failed to start tracing: %v", err)
  74                         }
  75
  76                         for i := 0; i < n; i++ {
  77                                 in <- true
  78                         }
  79                         wg.Wait()
  80                         Stop()
  81
  82                         _, err := trace.Parse(buf, "")
  83                         if err == trace.ErrTimeOrder {
  84                                 t.Skipf("skipping trace: %v", err)
  85                         }
  86
  87                         if err != nil {
  88                                 t.Fatalf("failed to parse trace: %v", err)
  89                         }
  90                 })
  91         }
  92 }
  93
  94 func TestTraceStartStop(t *testing.T) {
  95         if IsEnabled() {
  96                 t.Skip("skipping because -test.trace is set")
  97         }
  98         buf := new(bytes.Buffer)
  99         if err := Start(buf); err != nil {
 100                 t.Fatalf("failed to start tracing: %v", err)
 101         }
 102         Stop()
 103         size := buf.Len()
 104         if size == 0 {
 105                 t.Fatalf("trace is empty")
 106         }
 107         time.Sleep(100 * time.Millisecond)
 108         if size != buf.Len() {
 109                 t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
 110         }
 111         saveTrace(t, buf, "TestTraceStartStop")
 112 }
 113
 114 func TestTraceDoubleStart(t *testing.T) {
 115         if IsEnabled() {
 116                 t.Skip("skipping because -test.trace is set")
 117         }
 118         Stop()
 119         buf := new(bytes.Buffer)
 120         if err := Start(buf); err != nil {
 121                 t.Fatalf("failed to start tracing: %v", err)
 122         }
 123         if err := Start(buf); err == nil {
 124                 t.Fatalf("succeed to start tracing second time")
 125         }
 126         Stop()
 127         Stop()
 128 }
 129
 130 func TestTrace(t *testing.T) {
 131         if IsEnabled() {
 132                 t.Skip("skipping because -test.trace is set")
 133         }
 134         if goexperiment.ExecTracer2 {
 135                 // An equivalent test exists in internal/trace/v2.
 136                 t.Skip("skipping because this test is incompatible with the new tracer")
 137         }
 138         buf := new(bytes.Buffer)
 139         if err := Start(buf); err != nil {
 140                 t.Fatalf("failed to start tracing: %v", err)
 141         }
 142         Stop()
 143         saveTrace(t, buf, "TestTrace")
 144         _, err := trace.Parse(buf, "")
 145         if err == trace.ErrTimeOrder {
 146                 t.Skipf("skipping trace: %v", err)
 147         }
 148         if err != nil {
 149                 t.Fatalf("failed to parse trace: %v", err)
 150         }
 151 }
 152
 153 func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
 154         res, err := trace.Parse(r, "")
 155         if err == trace.ErrTimeOrder {
 156                 t.Skipf("skipping trace: %v", err)
 157         }
 158         if err != nil {
 159                 t.Fatalf("failed to parse trace: %v", err)
 160         }
 161         gs := trace.GoroutineStats(res.Events)
 162         for goid := range gs {
 163                 // We don't do any particular checks on the result at the moment.
 164                 // But still check that RelatedGoroutines does not crash, hang, etc.
 165                 _ = trace.RelatedGoroutines(res.Events, goid)
 166         }
 167         return res.Events, gs
 168 }
 169
 170 func testBrokenTimestamps(t *testing.T, data []byte) {
 171         // On some processors cputicks (used to generate trace timestamps)
 172         // produce non-monotonic timestamps. It is important that the parser
 173         // distinguishes logically inconsistent traces (e.g. missing, excessive
 174         // or misordered events) from broken timestamps. The former is a bug
 175         // in tracer, the latter is a machine issue.
 176         // So now that we have a consistent trace, test that (1) parser does
 177         // not return a logical error in case of broken timestamps
 178         // and (2) broken timestamps are eventually detected and reported.
 179         trace.BreakTimestampsForTesting = true
 180         defer func() {
 181                 trace.BreakTimestampsForTesting = false
 182         }()
 183         for i := 0; i < 1e4; i++ {
 184                 _, err := trace.Parse(bytes.NewReader(data), "")
 185                 if err == trace.ErrTimeOrder {
 186                         return
 187                 }
 188                 if err != nil {
 189                         t.Fatalf("failed to parse trace: %v", err)
 190                 }
 191         }
 192 }
 193
 194 func TestTraceStress(t *testing.T) {
 195         switch runtime.GOOS {
 196         case "js", "wasip1":
 197                 t.Skip("no os.Pipe on " + runtime.GOOS)
 198         }
 199         if IsEnabled() {
 200                 t.Skip("skipping because -test.trace is set")
 201         }
 202         if testing.Short() {
 203                 t.Skip("skipping in -short mode")
 204         }
 205         if goexperiment.ExecTracer2 {
 206                 // An equivalent test exists in internal/trace/v2.
 207                 t.Skip("skipping because this test is incompatible with the new tracer")
 208         }
 209
 210         var wg sync.WaitGroup
 211         done := make(chan bool)
 212
 213         // Create a goroutine blocked before tracing.
 214         wg.Add(1)
 215         go func() {
 216                 <-done
 217                 wg.Done()
 218         }()
 219
 220         // Create a goroutine blocked in syscall before tracing.
 221         rp, wp, err := os.Pipe()
 222         if err != nil {
 223                 t.Fatalf("failed to create pipe: %v", err)
 224         }
 225         defer func() {
 226                 rp.Close()
 227                 wp.Close()
 228         }()
 229         wg.Add(1)
 230         go func() {
 231                 var tmp [1]byte
 232                 rp.Read(tmp[:])
 233                 <-done
 234                 wg.Done()
 235         }()
 236         time.Sleep(time.Millisecond) // give the goroutine above time to block
 237
 238         buf := new(bytes.Buffer)
 239         if err := Start(buf); err != nil {
 240                 t.Fatalf("failed to start tracing: %v", err)
 241         }
 242
 243         procs := runtime.GOMAXPROCS(10)
 244         time.Sleep(50 * time.Millisecond) // test proc stop/start events
 245
 246         go func() {
 247                 runtime.LockOSThread()
 248                 for {
 249                         select {
 250                         case <-done:
 251                                 return
 252                         default:
 253                                 runtime.Gosched()
 254                         }
 255                 }
 256         }()
 257
 258         runtime.GC()
 259         // Trigger GC from malloc.
 260         n := int(1e3)
 261         if isMemoryConstrained() {
 262                 // Reduce allocation to avoid running out of
 263                 // memory on the builder - see issue/12032.
 264                 n = 512
 265         }
 266         for i := 0; i < n; i++ {
 267                 _ = make([]byte, 1<<20)
 268         }
 269
 270         // Create a bunch of busy goroutines to load all Ps.
 271         for p := 0; p < 10; p++ {
 272                 wg.Add(1)
 273                 go func() {
 274                         // Do something useful.
 275                         tmp := make([]byte, 1<<16)
 276                         for i := range tmp {
 277                                 tmp[i]++
 278                         }
 279                         _ = tmp
 280                         <-done
 281                         wg.Done()
 282                 }()
 283         }
 284
 285         // Block in syscall.
 286         wg.Add(1)
 287         go func() {
 288                 var tmp [1]byte
 289                 rp.Read(tmp[:])
 290                 <-done
 291                 wg.Done()
 292         }()
 293
 294         // Test timers.
 295         timerDone := make(chan bool)
 296         go func() {
 297                 time.Sleep(time.Millisecond)
 298                 timerDone <- true
 299         }()
 300         <-timerDone
 301
 302         // A bit of network.
 303         ln, err := net.Listen("tcp", "127.0.0.1:0")
 304         if err != nil {
 305                 t.Fatalf("listen failed: %v", err)
 306         }
 307         defer ln.Close()
 308         go func() {
 309                 c, err := ln.Accept()
 310                 if err != nil {
 311                         return
 312                 }
 313                 time.Sleep(time.Millisecond)
 314                 var buf [1]byte
 315                 c.Write(buf[:])
 316                 c.Close()
 317         }()
 318         c, err := net.Dial("tcp", ln.Addr().String())
 319         if err != nil {
 320                 t.Fatalf("dial failed: %v", err)
 321         }
 322         var tmp [1]byte
 323         c.Read(tmp[:])
 324         c.Close()
 325
 326         go func() {
 327                 runtime.Gosched()
 328                 select {}
 329         }()
 330
 331         // Unblock helper goroutines and wait them to finish.
 332         wp.Write(tmp[:])
 333         wp.Write(tmp[:])
 334         close(done)
 335         wg.Wait()
 336
 337         runtime.GOMAXPROCS(procs)
 338
 339         Stop()
 340         saveTrace(t, buf, "TestTraceStress")
 341         trace := buf.Bytes()
 342         parseTrace(t, buf)
 343         testBrokenTimestamps(t, trace)
 344 }
 345
 346 // isMemoryConstrained reports whether the current machine is likely
 347 // to be memory constrained.
 348 // This was originally for the openbsd/arm builder (Issue 12032).
 349 // TODO: move this to testenv? Make this look at memory? Look at GO_BUILDER_NAME?
 350 func isMemoryConstrained() bool {
 351         if runtime.GOOS == "plan9" {
 352                 return true
 353         }
 354         switch runtime.GOARCH {
 355         case "arm", "mips", "mipsle":
 356                 return true
 357         }
 358         return false
 359 }
 360
 361 // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine.
 362 // And concurrently with all that start/stop trace 3 times.
 363 func TestTraceStressStartStop(t *testing.T) {
 364         switch runtime.GOOS {
 365         case "js", "wasip1":
 366                 t.Skip("no os.Pipe on " + runtime.GOOS)
 367         }
 368         if IsEnabled() {
 369                 t.Skip("skipping because -test.trace is set")
 370         }
 371         if goexperiment.ExecTracer2 {
 372                 // An equivalent test exists in internal/trace/v2.
 373                 t.Skip("skipping because this test is incompatible with the new tracer")
 374         }
 375         defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
 376         outerDone := make(chan bool)
 377
 378         go func() {
 379                 defer func() {
 380                         outerDone <- true
 381                 }()
 382
 383                 var wg sync.WaitGroup
 384                 done := make(chan bool)
 385
 386                 wg.Add(1)
 387                 go func() {
 388                         <-done
 389                         wg.Done()
 390                 }()
 391
 392                 rp, wp, err := os.Pipe()
 393                 if err != nil {
 394                         t.Errorf("failed to create pipe: %v", err)
 395                         return
 396                 }
 397                 defer func() {
 398                         rp.Close()
 399                         wp.Close()
 400                 }()
 401                 wg.Add(1)
 402                 go func() {
 403                         var tmp [1]byte
 404                         rp.Read(tmp[:])
 405                         <-done
 406                         wg.Done()
 407                 }()
 408                 time.Sleep(time.Millisecond)
 409
 410                 go func() {
 411                         runtime.LockOSThread()
 412                         for {
 413                                 select {
 414                                 case <-done:
 415                                         return
 416                                 default:
 417                                         runtime.Gosched()
 418                                 }
 419                         }
 420                 }()
 421
 422                 runtime.GC()
 423                 // Trigger GC from malloc.
 424                 n := int(1e3)
 425                 if isMemoryConstrained() {
 426                         // Reduce allocation to avoid running out of
 427                         // memory on the builder.
 428                         n = 512
 429                 }
 430                 for i := 0; i < n; i++ {
 431                         _ = make([]byte, 1<<20)
 432                 }
 433
 434                 // Create a bunch of busy goroutines to load all Ps.
 435                 for p := 0; p < 10; p++ {
 436                         wg.Add(1)
 437                         go func() {
 438                                 // Do something useful.
 439                                 tmp := make([]byte, 1<<16)
 440                                 for i := range tmp {
 441                                         tmp[i]++
 442                                 }
 443                                 _ = tmp
 444                                 <-done
 445                                 wg.Done()
 446                         }()
 447                 }
 448
 449                 // Block in syscall.
 450                 wg.Add(1)
 451                 go func() {
 452                         var tmp [1]byte
 453                         rp.Read(tmp[:])
 454                         <-done
 455                         wg.Done()
 456                 }()
 457
 458                 runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))
 459
 460                 // Test timers.
 461                 timerDone := make(chan bool)
 462                 go func() {
 463                         time.Sleep(time.Millisecond)
 464                         timerDone <- true
 465                 }()
 466                 <-timerDone
 467
 468                 // A bit of network.
 469                 ln, err := net.Listen("tcp", "127.0.0.1:0")
 470                 if err != nil {
 471                         t.Errorf("listen failed: %v", err)
 472                         return
 473                 }
 474                 defer ln.Close()
 475                 go func() {
 476                         c, err := ln.Accept()
 477                         if err != nil {
 478                                 return
 479                         }
 480                         time.Sleep(time.Millisecond)
 481                         var buf [1]byte
 482                         c.Write(buf[:])
 483                         c.Close()
 484                 }()
 485                 c, err := net.Dial("tcp", ln.Addr().String())
 486                 if err != nil {
 487                         t.Errorf("dial failed: %v", err)
 488                         return
 489                 }
 490                 var tmp [1]byte
 491                 c.Read(tmp[:])
 492                 c.Close()
 493
 494                 go func() {
 495                         runtime.Gosched()
 496                         select {}
 497                 }()
 498
 499                 // Unblock helper goroutines and wait them to finish.
 500                 wp.Write(tmp[:])
 501                 wp.Write(tmp[:])
 502                 close(done)
 503                 wg.Wait()
 504         }()
 505
 506         for i := 0; i < 3; i++ {
 507                 buf := new(bytes.Buffer)
 508                 if err := Start(buf); err != nil {
 509                         t.Fatalf("failed to start tracing: %v", err)
 510                 }
 511                 time.Sleep(time.Millisecond)
 512                 Stop()
 513                 saveTrace(t, buf, "TestTraceStressStartStop")
 514                 trace := buf.Bytes()
 515                 parseTrace(t, buf)
 516                 testBrokenTimestamps(t, trace)
 517         }
 518         <-outerDone
 519 }
 520
 521 func TestTraceFutileWakeup(t *testing.T) {
 522         if IsEnabled() {
 523                 t.Skip("skipping because -test.trace is set")
 524         }
 525         if goexperiment.ExecTracer2 {
 526                 t.Skip("skipping because this test is incompatible with the new tracer")
 527         }
 528         buf := new(bytes.Buffer)
 529         if err := Start(buf); err != nil {
 530                 t.Fatalf("failed to start tracing: %v", err)
 531         }
 532
 533         defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(8))
 534         c0 := make(chan int, 1)
 535         c1 := make(chan int, 1)
 536         c2 := make(chan int, 1)
 537         const procs = 2
 538         var done sync.WaitGroup
 539         done.Add(4 * procs)
 540         for p := 0; p < procs; p++ {
 541                 const iters = 1e3
 542                 go func() {
 543                         for i := 0; i < iters; i++ {
 544                                 runtime.Gosched()
 545                                 c0 <- 0
 546                         }
 547                         done.Done()
 548                 }()
 549                 go func() {
 550                         for i := 0; i < iters; i++ {
 551                                 runtime.Gosched()
 552                                 <-c0
 553                         }
 554                         done.Done()
 555                 }()
 556                 go func() {
 557                         for i := 0; i < iters; i++ {
 558                                 runtime.Gosched()
 559                                 select {
 560                                 case c1 <- 0:
 561                                 case c2 <- 0:
 562                                 }
 563                         }
 564                         done.Done()
 565                 }()
 566                 go func() {
 567                         for i := 0; i < iters; i++ {
 568                                 runtime.Gosched()
 569                                 select {
 570                                 case <-c1:
 571                                 case <-c2:
 572                                 }
 573                         }
 574                         done.Done()
 575                 }()
 576         }
 577         done.Wait()
 578
 579         Stop()
 580         saveTrace(t, buf, "TestTraceFutileWakeup")
 581         events, _ := parseTrace(t, buf)
 582         // Check that (1) trace does not contain EvFutileWakeup events and
 583         // (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events
 584         // (we call runtime.Gosched between all operations, so these would be futile wakeups).
 585         gs := make(map[uint64]int)
 586         for _, ev := range events {
 587                 switch ev.Type {
 588                 case trace.EvFutileWakeup:
 589                         t.Fatalf("found EvFutileWakeup event")
 590                 case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect:
 591                         if gs[ev.G] == 2 {
 592                                 t.Fatalf("goroutine %v blocked on %v at %v right after start",
 593                                         ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
 594                         }
 595                         if gs[ev.G] == 1 {
 596                                 t.Fatalf("goroutine %v blocked on %v at %v while blocked",
 597                                         ev.G, trace.EventDescriptions[ev.Type].Name, ev.Ts)
 598                         }
 599                         gs[ev.G] = 1
 600                 case trace.EvGoStart:
 601                         if gs[ev.G] == 1 {
 602                                 gs[ev.G] = 2
 603                         }
 604                 default:
 605                         delete(gs, ev.G)
 606                 }
 607         }
 608 }
 609
 610 func TestTraceCPUProfile(t *testing.T) {
 611         if IsEnabled() {
 612                 t.Skip("skipping because -test.trace is set")
 613         }
 614         if goexperiment.ExecTracer2 {
 615                 // An equivalent test exists in internal/trace/v2.
 616                 t.Skip("skipping because this test is incompatible with the new tracer")
 617         }
 618
 619         cpuBuf := new(bytes.Buffer)
 620         if err := pprof.StartCPUProfile(cpuBuf); err != nil {
 621                 t.Skipf("failed to start CPU profile: %v", err)
 622         }
 623
 624         buf := new(bytes.Buffer)
 625         if err := Start(buf); err != nil {
 626                 t.Fatalf("failed to start tracing: %v", err)
 627         }
 628
 629         dur := 100 * time.Millisecond
 630         func() {
 631                 // Create a region in the execution trace. Set and clear goroutine
 632                 // labels fully within that region, so we know that any CPU profile
 633                 // sample with the label must also be eligible for inclusion in the
 634                 // execution trace.
 635                 ctx := context.Background()
 636                 defer StartRegion(ctx, "cpuHogger").End()
 637                 pprof.Do(ctx, pprof.Labels("tracing", "on"), func(ctx context.Context) {
 638                         cpuHogger(cpuHog1, &salt1, dur)
 639                 })
 640                 // Be sure the execution trace's view, when filtered to this goroutine
 641                 // via the explicit goroutine ID in each event, gets many more samples
 642                 // than the CPU profiler when filtered to this goroutine via labels.
 643                 cpuHogger(cpuHog1, &salt1, dur)
 644         }()
 645
 646         Stop()
 647         pprof.StopCPUProfile()
 648         saveTrace(t, buf, "TestTraceCPUProfile")
 649
 650         prof, err := profile.Parse(cpuBuf)
 651         if err != nil {
 652                 t.Fatalf("failed to parse CPU profile: %v", err)
 653         }
 654         // Examine the CPU profiler's view. Filter it to only include samples from
 655         // the single test goroutine. Use labels to execute that filter: they should
 656         // apply to all work done while that goroutine is getg().m.curg, and they
 657         // should apply to no other goroutines.
 658         pprofSamples := 0
 659         pprofStacks := make(map[string]int)
 660         for _, s := range prof.Sample {
 661                 if s.Label["tracing"] != nil {
 662                         var fns []string
 663                         var leaf string
 664                         for _, loc := range s.Location {
 665                                 for _, line := range loc.Line {
 666                                         fns = append(fns, fmt.Sprintf("%s:%d", line.Function.Name, line.Line))
 667                                         leaf = line.Function.Name
 668                                 }
 669                         }
 670                         // runtime.sigprof synthesizes call stacks when "normal traceback is
 671                         // impossible or has failed", using particular placeholder functions
 672                         // to represent common failure cases. Look for those functions in
 673                         // the leaf position as a sign that the call stack and its
 674                         // symbolization are more complex than this test can handle.
 675                         //
 676                         // TODO: Make the symbolization done by the execution tracer and CPU
 677                         // profiler match up even in these harder cases. See #53378.
 678                         switch leaf {
 679                         case "runtime._System", "runtime._GC", "runtime._ExternalCode", "runtime._VDSO":
 680                                 continue
 681                         }
 682                         stack := strings.Join(fns, " ")
 683                         samples := int(s.Value[0])
 684                         pprofSamples += samples
 685                         pprofStacks[stack] += samples
 686                 }
 687         }
 688         if pprofSamples == 0 {
 689                 t.Skipf("CPU profile did not include any samples while tracing was active\n%s", prof)
 690         }
 691
 692         // Examine the execution tracer's view of the CPU profile samples. Filter it
 693         // to only include samples from the single test goroutine. Use the goroutine
 694         // ID that was recorded in the events: that should reflect getg().m.curg,
 695         // same as the profiler's labels (even when the M is using its g0 stack).
 696         totalTraceSamples := 0
 697         traceSamples := 0
 698         traceStacks := make(map[string]int)
 699         events, _ := parseTrace(t, buf)
 700         var hogRegion *trace.Event
 701         for _, ev := range events {
 702                 if ev.Type == trace.EvUserRegion && ev.Args[1] == 0 && ev.SArgs[0] == "cpuHogger" {
 703                         // mode "0" indicates region start
 704                         hogRegion = ev
 705                 }
 706         }
 707         if hogRegion == nil {
 708                 t.Fatalf("execution trace did not identify cpuHogger goroutine")
 709         } else if hogRegion.Link == nil {
 710                 t.Fatalf("execution trace did not close cpuHogger region")
 711         }
 712         for _, ev := range events {
 713                 if ev.Type == trace.EvCPUSample {
 714                         totalTraceSamples++
 715                         if ev.G == hogRegion.G {
 716                                 traceSamples++
 717                                 var fns []string
 718                                 for _, frame := range ev.Stk {
 719                                         if frame.Fn != "runtime.goexit" {
 720                                                 fns = append(fns, fmt.Sprintf("%s:%d", frame.Fn, frame.Line))
 721                                         }
 722                                 }
 723                                 stack := strings.Join(fns, " ")
 724                                 traceStacks[stack]++
 725                         }
 726                 }
 727         }
 728
 729         // The execution trace may drop CPU profile samples if the profiling buffer
 730         // overflows. Based on the size of profBufWordCount, that takes a bit over
 731         // 1900 CPU samples or 19 thread-seconds at a 100 Hz sample rate. If we've
 732         // hit that case, then we definitely have at least one full buffer's worth
 733         // of CPU samples, so we'll call that success.
 734         overflowed := totalTraceSamples >= 1900
 735         if traceSamples < pprofSamples {
 736                 t.Logf("execution trace did not include all CPU profile samples; %d in profile, %d in trace", pprofSamples, traceSamples)
 737                 if !overflowed {
 738                         t.Fail()
 739                 }
 740         }
 741
 742         for stack, traceSamples := range traceStacks {
 743                 pprofSamples := pprofStacks[stack]
 744                 delete(pprofStacks, stack)
 745                 if traceSamples < pprofSamples {
 746                         t.Logf("execution trace did not include all CPU profile samples for stack %q; %d in profile, %d in trace",
 747                                 stack, pprofSamples, traceSamples)
 748                         if !overflowed {
 749                                 t.Fail()
 750                         }
 751                 }
 752         }
 753         for stack, pprofSamples := range pprofStacks {
 754                 t.Logf("CPU profile included %d samples at stack %q not present in execution trace", pprofSamples, stack)
 755                 if !overflowed {
 756                         t.Fail()
 757                 }
 758         }
 759
 760         if t.Failed() {
 761                 t.Logf("execution trace CPU samples:")
 762                 for stack, samples := range traceStacks {
 763                         t.Logf("%d: %q", samples, stack)
 764                 }
 765                 t.Logf("CPU profile:\n%v", prof)
 766         }
 767 }
 768
 769 func cpuHogger(f func(x int) int, y *int, dur time.Duration) {
 770         // We only need to get one 100 Hz clock tick, so we've got
 771         // a large safety buffer.
 772         // But do at least 500 iterations (which should take about 100ms),
 773         // otherwise TestCPUProfileMultithreaded can fail if only one
 774         // thread is scheduled during the testing period.
 775         t0 := time.Now()
 776         accum := *y
 777         for i := 0; i < 500 || time.Since(t0) < dur; i++ {
 778                 accum = f(accum)
 779         }
 780         *y = accum
 781 }
 782
 783 var (
 784         salt1 = 0
 785 )
 786
 787 // The actual CPU hogging function.
 788 // Must not call other functions nor access heap/globals in the loop,
 789 // otherwise under race detector the samples will be in the race runtime.
 790 func cpuHog1(x int) int {
 791         return cpuHog0(x, 1e5)
 792 }
 793
 794 func cpuHog0(x, n int) int {
 795         foo := x
 796         for i := 0; i < n; i++ {
 797                 if i%1000 == 0 {
 798                         // Spend time in mcall, stored as gp.m.curg, with g0 running
 799                         runtime.Gosched()
 800                 }
 801                 if foo > 0 {
 802                         foo *= foo
 803                 } else {
 804                         foo *= foo + 1
 805                 }
 806         }
 807         return foo
 808 }
 809
 810 func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
 811         if !*saveTraces {
 812                 return
 813         }
 814         if err := os.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
 815                 t.Errorf("failed to write trace file: %s", err)
 816         }
 817 }