libgo/go/runtime/pprof/pprof_test.go

   1 // Copyright 2011 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 // +build !nacl
   6
   7 package pprof_test
   8
   9 import (
  10         "bytes"
  11         "fmt"
  12         "internal/testenv"
  13         "math/big"
  14         "os"
  15         "os/exec"
  16         "regexp"
  17         "runtime"
  18         . "runtime/pprof"
  19         "strings"
  20         "sync"
  21         "testing"
  22         "time"
  23         "unsafe"
  24 )
  25
  26 func cpuHogger(f func(), dur time.Duration) {
  27         // We only need to get one 100 Hz clock tick, so we've got
  28         // a large safety buffer.
  29         // But do at least 500 iterations (which should take about 100ms),
  30         // otherwise TestCPUProfileMultithreaded can fail if only one
  31         // thread is scheduled during the testing period.
  32         t0 := time.Now()
  33         for i := 0; i < 500 || time.Since(t0) < dur; i++ {
  34                 f()
  35         }
  36 }
  37
  38 var (
  39         salt1 = 0
  40         salt2 = 0
  41 )
  42
  43 // The actual CPU hogging function.
  44 // Must not call other functions nor access heap/globals in the loop,
  45 // otherwise under race detector the samples will be in the race runtime.
  46 func cpuHog1() {
  47         foo := salt1
  48         for i := 0; i < 1e5; i++ {
  49                 if foo > 0 {
  50                         foo *= foo
  51                 } else {
  52                         foo *= foo + 1
  53                 }
  54         }
  55         salt1 = foo
  56 }
  57
  58 func cpuHog2() {
  59         foo := salt2
  60         for i := 0; i < 1e5; i++ {
  61                 if foo > 0 {
  62                         foo *= foo
  63                 } else {
  64                         foo *= foo + 2
  65                 }
  66         }
  67         salt2 = foo
  68 }
  69
  70 func TestCPUProfile(t *testing.T) {
  71         testCPUProfile(t, []string{"pprof_test.cpuHog1"}, func(dur time.Duration) {
  72                 cpuHogger(cpuHog1, dur)
  73         })
  74 }
  75
  76 func TestCPUProfileMultithreaded(t *testing.T) {
  77         defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
  78         testCPUProfile(t, []string{"pprof_test.cpuHog1", "pprof_test.cpuHog2"}, func(dur time.Duration) {
  79                 c := make(chan int)
  80                 go func() {
  81                         cpuHogger(cpuHog1, dur)
  82                         c <- 1
  83                 }()
  84                 cpuHogger(cpuHog2, dur)
  85                 <-c
  86         })
  87 }
  88
  89 func parseProfile(t *testing.T, bytes []byte, f func(uintptr, []uintptr)) {
  90         // Convert []byte to []uintptr.
  91         l := len(bytes) / int(unsafe.Sizeof(uintptr(0)))
  92         val := *(*[]uintptr)(unsafe.Pointer(&bytes))
  93         val = val[:l]
  94
  95         // 5 for the header, 3 for the trailer.
  96         if l < 5+3 {
  97                 t.Logf("profile too short: %#x", val)
  98                 if badOS[runtime.GOOS] {
  99                         t.Skipf("ignoring failure on %s; see golang.org/issue/13841", runtime.GOOS)
 100                         return
 101                 }
 102                 t.FailNow()
 103         }
 104
 105         hd, val, tl := val[:5], val[5:l-3], val[l-3:]
 106         if hd[0] != 0 || hd[1] != 3 || hd[2] != 0 || hd[3] != 1e6/100 || hd[4] != 0 {
 107                 t.Fatalf("unexpected header %#x", hd)
 108         }
 109
 110         if tl[0] != 0 || tl[1] != 1 || tl[2] != 0 {
 111                 t.Fatalf("malformed end-of-data marker %#x", tl)
 112         }
 113
 114         for len(val) > 0 {
 115                 if len(val) < 2 || val[0] < 1 || val[1] < 1 || uintptr(len(val)) < 2+val[1] {
 116                         t.Fatalf("malformed profile.  leftover: %#x", val)
 117                 }
 118                 f(val[0], val[2:2+val[1]])
 119                 val = val[2+val[1]:]
 120         }
 121 }
 122
 123 func testCPUProfile(t *testing.T, need []string, f func(dur time.Duration)) {
 124         switch runtime.GOOS {
 125         case "darwin":
 126                 switch runtime.GOARCH {
 127                 case "arm", "arm64":
 128                         // nothing
 129                 default:
 130                         out, err := exec.Command("uname", "-a").CombinedOutput()
 131                         if err != nil {
 132                                 t.Fatal(err)
 133                         }
 134                         vers := string(out)
 135                         t.Logf("uname -a: %v", vers)
 136                 }
 137         case "plan9":
 138                 t.Skip("skipping on plan9")
 139         }
 140
 141         const maxDuration = 5 * time.Second
 142         // If we're running a long test, start with a long duration
 143         // because some of the tests (e.g., TestStackBarrierProfiling)
 144         // are trying to make sure something *doesn't* happen.
 145         duration := 5 * time.Second
 146         if testing.Short() {
 147                 duration = 200 * time.Millisecond
 148         }
 149
 150         // Profiling tests are inherently flaky, especially on a
 151         // loaded system, such as when this test is running with
 152         // several others under go test std. If a test fails in a way
 153         // that could mean it just didn't run long enough, try with a
 154         // longer duration.
 155         for duration <= maxDuration {
 156                 var prof bytes.Buffer
 157                 if err := StartCPUProfile(&prof); err != nil {
 158                         t.Fatal(err)
 159                 }
 160                 f(duration)
 161                 StopCPUProfile()
 162
 163                 if profileOk(t, need, prof, duration) {
 164                         return
 165                 }
 166
 167                 duration *= 2
 168                 if duration <= maxDuration {
 169                         t.Logf("retrying with %s duration", duration)
 170                 }
 171         }
 172
 173         if badOS[runtime.GOOS] {
 174                 t.Skipf("ignoring failure on %s; see golang.org/issue/13841", runtime.GOOS)
 175                 return
 176         }
 177         // Ignore the failure if the tests are running in a QEMU-based emulator,
 178         // QEMU is not perfect at emulating everything.
 179         // IN_QEMU environmental variable is set by some of the Go builders.
 180         // IN_QEMU=1 indicates that the tests are running in QEMU. See issue 9605.
 181         if os.Getenv("IN_QEMU") == "1" {
 182                 t.Skip("ignore the failure in QEMU; see golang.org/issue/9605")
 183                 return
 184         }
 185         t.FailNow()
 186 }
 187
 188 func profileOk(t *testing.T, need []string, prof bytes.Buffer, duration time.Duration) (ok bool) {
 189         ok = true
 190
 191         // Check that profile is well formed and contains need.
 192         have := make([]uintptr, len(need))
 193         var samples uintptr
 194         parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) {
 195                 samples += count
 196                 for _, pc := range stk {
 197                         f := runtime.FuncForPC(pc)
 198                         if f == nil {
 199                                 continue
 200                         }
 201                         t.Log(f.Name(), count)
 202                         for i, name := range need {
 203                                 if strings.Contains(f.Name(), name) {
 204                                         have[i] += count
 205                                 }
 206                         }
 207                         if strings.Contains(f.Name(), "stackBarrier") {
 208                                 // The runtime should have unwound this.
 209                                 t.Fatalf("profile includes stackBarrier")
 210                         }
 211                 }
 212         })
 213         t.Logf("total %d CPU profile samples collected", samples)
 214
 215         if samples < 10 && runtime.GOOS == "windows" {
 216                 // On some windows machines we end up with
 217                 // not enough samples due to coarse timer
 218                 // resolution. Let it go.
 219                 t.Log("too few samples on Windows (golang.org/issue/10842)")
 220                 return false
 221         }
 222
 223         // Check that we got a reasonable number of samples.
 224         if ideal := uintptr(duration * 100 / time.Second); samples == 0 || samples < ideal/4 {
 225                 t.Logf("too few samples; got %d, want at least %d, ideally %d", samples, ideal/4, ideal)
 226                 ok = false
 227         }
 228
 229         if len(need) == 0 {
 230                 return ok
 231         }
 232
 233         var total uintptr
 234         for i, name := range need {
 235                 total += have[i]
 236                 t.Logf("%s: %d\n", name, have[i])
 237         }
 238         if total == 0 {
 239                 t.Logf("no samples in expected functions")
 240                 ok = false
 241         }
 242         // We'd like to check a reasonable minimum, like
 243         // total / len(have) / smallconstant, but this test is
 244         // pretty flaky (see bug 7095).  So we'll just test to
 245         // make sure we got at least one sample.
 246         min := uintptr(1)
 247         for i, name := range need {
 248                 if have[i] < min {
 249                         t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
 250                         ok = false
 251                 }
 252         }
 253         return ok
 254 }
 255
 256 // Fork can hang if preempted with signals frequently enough (see issue 5517).
 257 // Ensure that we do not do this.
 258 func TestCPUProfileWithFork(t *testing.T) {
 259         testenv.MustHaveExec(t)
 260
 261         heap := 1 << 30
 262         if runtime.GOOS == "android" {
 263                 // Use smaller size for Android to avoid crash.
 264                 heap = 100 << 20
 265         }
 266         if testing.Short() {
 267                 heap = 100 << 20
 268         }
 269         // This makes fork slower.
 270         garbage := make([]byte, heap)
 271         // Need to touch the slice, otherwise it won't be paged in.
 272         done := make(chan bool)
 273         go func() {
 274                 for i := range garbage {
 275                         garbage[i] = 42
 276                 }
 277                 done <- true
 278         }()
 279         <-done
 280
 281         var prof bytes.Buffer
 282         if err := StartCPUProfile(&prof); err != nil {
 283                 t.Fatal(err)
 284         }
 285         defer StopCPUProfile()
 286
 287         for i := 0; i < 10; i++ {
 288                 exec.Command(os.Args[0], "-h").CombinedOutput()
 289         }
 290 }
 291
 292 // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
 293 // If it did, it would see inconsistent state and would either record an incorrect stack
 294 // or crash because the stack was malformed.
 295 func TestGoroutineSwitch(t *testing.T) {
 296         // How much to try. These defaults take about 1 seconds
 297         // on a 2012 MacBook Pro. The ones in short mode take
 298         // about 0.1 seconds.
 299         tries := 10
 300         count := 1000000
 301         if testing.Short() {
 302                 tries = 1
 303         }
 304         for try := 0; try < tries; try++ {
 305                 var prof bytes.Buffer
 306                 if err := StartCPUProfile(&prof); err != nil {
 307                         t.Fatal(err)
 308                 }
 309                 for i := 0; i < count; i++ {
 310                         runtime.Gosched()
 311                 }
 312                 StopCPUProfile()
 313
 314                 // Read profile to look for entries for runtime.gogo with an attempt at a traceback.
 315                 // The special entry
 316                 parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) {
 317                         // An entry with two frames with 'System' in its top frame
 318                         // exists to record a PC without a traceback. Those are okay.
 319                         if len(stk) == 2 {
 320                                 f := runtime.FuncForPC(stk[1])
 321                                 if f != nil && (f.Name() == "runtime._System" || f.Name() == "runtime._ExternalCode" || f.Name() == "runtime._GC") {
 322                                         return
 323                                 }
 324                         }
 325
 326                         // Otherwise, should not see runtime.gogo.
 327                         // The place we'd see it would be the inner most frame.
 328                         f := runtime.FuncForPC(stk[0])
 329                         if f != nil && f.Name() == "runtime.gogo" {
 330                                 var buf bytes.Buffer
 331                                 for _, pc := range stk {
 332                                         f := runtime.FuncForPC(pc)
 333                                         if f == nil {
 334                                                 fmt.Fprintf(&buf, "%#x ?:0\n", pc)
 335                                         } else {
 336                                                 file, line := f.FileLine(pc)
 337                                                 fmt.Fprintf(&buf, "%#x %s:%d\n", pc, file, line)
 338                                         }
 339                                 }
 340                                 t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String())
 341                         }
 342                 })
 343         }
 344 }
 345
 346 // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
 347 func TestMathBigDivide(t *testing.T) {
 348         testCPUProfile(t, nil, func(duration time.Duration) {
 349                 t := time.After(duration)
 350                 pi := new(big.Int)
 351                 for {
 352                         for i := 0; i < 100; i++ {
 353                                 n := big.NewInt(2646693125139304345)
 354                                 d := big.NewInt(842468587426513207)
 355                                 pi.Div(n, d)
 356                         }
 357                         select {
 358                         case <-t:
 359                                 return
 360                         default:
 361                         }
 362                 }
 363         })
 364 }
 365
 366 func TestStackBarrierProfiling(t *testing.T) {
 367         if (runtime.GOOS == "linux" && runtime.GOARCH == "arm") || runtime.GOOS == "openbsd" || runtime.GOOS == "solaris" || runtime.GOOS == "dragonfly" || runtime.GOOS == "freebsd" {
 368                 // This test currently triggers a large number of
 369                 // usleep(100)s. These kernels/arches have poor
 370                 // resolution timers, so this gives up a whole
 371                 // scheduling quantum. On Linux and the BSDs (and
 372                 // probably Solaris), profiling signals are only
 373                 // generated when a process completes a whole
 374                 // scheduling quantum, so this test often gets zero
 375                 // profiling signals and fails.
 376                 t.Skipf("low resolution timers inhibit profiling signals (golang.org/issue/13405)")
 377                 return
 378         }
 379
 380         if !strings.Contains(os.Getenv("GODEBUG"), "gcstackbarrierall=1") {
 381                 // Re-execute this test with constant GC and stack
 382                 // barriers at every frame.
 383                 testenv.MustHaveExec(t)
 384                 if runtime.GOARCH == "ppc64" || runtime.GOARCH == "ppc64le" {
 385                         t.Skip("gcstackbarrierall doesn't work on ppc64")
 386                 }
 387                 args := []string{"-test.run=TestStackBarrierProfiling"}
 388                 if testing.Short() {
 389                         args = append(args, "-test.short")
 390                 }
 391                 cmd := exec.Command(os.Args[0], args...)
 392                 cmd.Env = append([]string{"GODEBUG=gcstackbarrierall=1", "GOGC=1"}, os.Environ()...)
 393                 if out, err := cmd.CombinedOutput(); err != nil {
 394                         t.Fatalf("subprocess failed with %v:\n%s", err, out)
 395                 }
 396                 return
 397         }
 398
 399         testCPUProfile(t, nil, func(duration time.Duration) {
 400                 // In long mode, we're likely to get one or two
 401                 // samples in stackBarrier.
 402                 t := time.After(duration)
 403                 for {
 404                         deepStack(1000)
 405                         select {
 406                         case <-t:
 407                                 return
 408                         default:
 409                         }
 410                 }
 411         })
 412 }
 413
 414 var x []byte
 415
 416 func deepStack(depth int) int {
 417         if depth == 0 {
 418                 return 0
 419         }
 420         x = make([]byte, 1024)
 421         return deepStack(depth-1) + 1
 422 }
 423
 424 // Operating systems that are expected to fail the tests. See issue 13841.
 425 var badOS = map[string]bool{
 426         "darwin":    true,
 427         "netbsd":    true,
 428         "plan9":     true,
 429         "dragonfly": true,
 430         "solaris":   true,
 431 }
 432
 433 func TestBlockProfile(t *testing.T) {
 434         t.Skip("lots of details are different for gccgo; FIXME")
 435         type TestCase struct {
 436                 name string
 437                 f    func()
 438                 re   string
 439         }
 440         tests := [...]TestCase{
 441                 {"chan recv", blockChanRecv, `
 442 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 443 #       0x[0-9,a-f]+    runtime\.chanrecv1\+0x[0-9,a-f]+        .*/src/runtime/chan.go:[0-9]+
 444 #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanRecv\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+
 445 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 446 `},
 447                 {"chan send", blockChanSend, `
 448 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 449 #       0x[0-9,a-f]+    runtime\.chansend1\+0x[0-9,a-f]+        .*/src/runtime/chan.go:[0-9]+
 450 #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanSend\+0x[0-9,a-f]+ .*/src/runtime/pprof/pprof_test.go:[0-9]+
 451 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 452 `},
 453                 {"chan close", blockChanClose, `
 454 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 455 #       0x[0-9,a-f]+    runtime\.chanrecv1\+0x[0-9,a-f]+        .*/src/runtime/chan.go:[0-9]+
 456 #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanClose\+0x[0-9,a-f]+        .*/src/runtime/pprof/pprof_test.go:[0-9]+
 457 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 458 `},
 459                 {"select recv async", blockSelectRecvAsync, `
 460 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 461 #       0x[0-9,a-f]+    runtime\.selectgo\+0x[0-9,a-f]+ .*/src/runtime/select.go:[0-9]+
 462 #       0x[0-9,a-f]+    runtime/pprof_test\.blockSelectRecvAsync\+0x[0-9,a-f]+  .*/src/runtime/pprof/pprof_test.go:[0-9]+
 463 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 464 `},
 465                 {"select send sync", blockSelectSendSync, `
 466 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 467 #       0x[0-9,a-f]+    runtime\.selectgo\+0x[0-9,a-f]+ .*/src/runtime/select.go:[0-9]+
 468 #       0x[0-9,a-f]+    runtime/pprof_test\.blockSelectSendSync\+0x[0-9,a-f]+   .*/src/runtime/pprof/pprof_test.go:[0-9]+
 469 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 470 `},
 471                 {"mutex", blockMutex, `
 472 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 473 #       0x[0-9,a-f]+    sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+   .*/src/sync/mutex\.go:[0-9]+
 474 #       0x[0-9,a-f]+    runtime/pprof_test\.blockMutex\+0x[0-9,a-f]+    .*/src/runtime/pprof/pprof_test.go:[0-9]+
 475 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 476 `},
 477                 {"cond", blockCond, `
 478 [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
 479 #       0x[0-9,a-f]+    sync\.\(\*Cond\)\.Wait\+0x[0-9,a-f]+    .*/src/sync/cond\.go:[0-9]+
 480 #       0x[0-9,a-f]+    runtime/pprof_test\.blockCond\+0x[0-9,a-f]+     .*/src/runtime/pprof/pprof_test.go:[0-9]+
 481 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/runtime/pprof/pprof_test.go:[0-9]+
 482 `},
 483         }
 484
 485         runtime.SetBlockProfileRate(1)
 486         defer runtime.SetBlockProfileRate(0)
 487         for _, test := range tests {
 488                 test.f()
 489         }
 490         var w bytes.Buffer
 491         Lookup("block").WriteTo(&w, 1)
 492         prof := w.String()
 493
 494         if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
 495                 t.Fatalf("Bad profile header:\n%v", prof)
 496         }
 497
 498         for _, test := range tests {
 499                 if !regexp.MustCompile(strings.Replace(test.re, "\t", "\t+", -1)).MatchString(prof) {
 500                         t.Fatalf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
 501                 }
 502         }
 503 }
 504
 505 const blockDelay = 10 * time.Millisecond
 506
 507 func blockChanRecv() {
 508         c := make(chan bool)
 509         go func() {
 510                 time.Sleep(blockDelay)
 511                 c <- true
 512         }()
 513         <-c
 514 }
 515
 516 func blockChanSend() {
 517         c := make(chan bool)
 518         go func() {
 519                 time.Sleep(blockDelay)
 520                 <-c
 521         }()
 522         c <- true
 523 }
 524
 525 func blockChanClose() {
 526         c := make(chan bool)
 527         go func() {
 528                 time.Sleep(blockDelay)
 529                 close(c)
 530         }()
 531         <-c
 532 }
 533
 534 func blockSelectRecvAsync() {
 535         c := make(chan bool, 1)
 536         c2 := make(chan bool, 1)
 537         go func() {
 538                 time.Sleep(blockDelay)
 539                 c <- true
 540         }()
 541         select {
 542         case <-c:
 543         case <-c2:
 544         }
 545 }
 546
 547 func blockSelectSendSync() {
 548         c := make(chan bool)
 549         c2 := make(chan bool)
 550         go func() {
 551                 time.Sleep(blockDelay)
 552                 <-c
 553         }()
 554         select {
 555         case c <- true:
 556         case c2 <- true:
 557         }
 558 }
 559
 560 func blockMutex() {
 561         var mu sync.Mutex
 562         mu.Lock()
 563         go func() {
 564                 time.Sleep(blockDelay)
 565                 mu.Unlock()
 566         }()
 567         mu.Lock()
 568 }
 569
 570 func blockCond() {
 571         var mu sync.Mutex
 572         c := sync.NewCond(&mu)
 573         mu.Lock()
 574         go func() {
 575                 time.Sleep(blockDelay)
 576                 mu.Lock()
 577                 c.Signal()
 578                 mu.Unlock()
 579         }()
 580         c.Wait()
 581         mu.Unlock()
 582 }