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 package pprof_test
   6
   7 import (
   8         "bytes"
   9         "fmt"
  10         "hash/crc32"
  11         "math/big"
  12         "os/exec"
  13         "regexp"
  14         "runtime"
  15         . "runtime/pprof"
  16         "strings"
  17         "sync"
  18         "testing"
  19         "time"
  20         "unsafe"
  21 )
  22
  23 func TestCPUProfile(t *testing.T) {
  24         buf := make([]byte, 100000)
  25         testCPUProfile(t, []string{"crc32.update"}, func() {
  26                 // This loop takes about a quarter second on a 2 GHz laptop.
  27                 // We only need to get one 100 Hz clock tick, so we've got
  28                 // a 25x safety buffer.
  29                 for i := 0; i < 1000; i++ {
  30                         crc32.ChecksumIEEE(buf)
  31                 }
  32         })
  33 }
  34
  35 func TestCPUProfileMultithreaded(t *testing.T) {
  36         // TODO(brainman): delete when issue 6986 is fixed.
  37         if runtime.GOOS == "windows" && runtime.GOARCH == "amd64" {
  38                 t.Skip("skipping broken test on windows-amd64-race")
  39         }
  40         buf := make([]byte, 100000)
  41         defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(2))
  42         testCPUProfile(t, []string{"crc32.update"}, func() {
  43                 c := make(chan int)
  44                 go func() {
  45                         for i := 0; i < 2000; i++ {
  46                                 crc32.Update(0, crc32.IEEETable, buf)
  47                         }
  48                         c <- 1
  49                 }()
  50                 // This loop takes about a quarter second on a 2 GHz laptop.
  51                 // We only need to get one 100 Hz clock tick, so we've got
  52                 // a 25x safety buffer.
  53                 for i := 0; i < 2000; i++ {
  54                         crc32.ChecksumIEEE(buf)
  55                 }
  56                 <-c
  57         })
  58 }
  59
  60 func parseProfile(t *testing.T, bytes []byte, f func(uintptr, []uintptr)) {
  61         // Convert []byte to []uintptr.
  62         l := len(bytes) / int(unsafe.Sizeof(uintptr(0)))
  63         val := *(*[]uintptr)(unsafe.Pointer(&bytes))
  64         val = val[:l]
  65
  66         // 5 for the header, 2 for the per-sample header on at least one sample, 3 for the trailer.
  67         if l < 5+2+3 {
  68                 t.Logf("profile too short: %#x", val)
  69                 if badOS[runtime.GOOS] {
  70                         t.Skipf("ignoring failure on %s; see golang.org/issue/6047", runtime.GOOS)
  71                         return
  72                 }
  73                 t.FailNow()
  74         }
  75
  76         hd, val, tl := val[:5], val[5:l-3], val[l-3:]
  77         if hd[0] != 0 || hd[1] != 3 || hd[2] != 0 || hd[3] != 1e6/100 || hd[4] != 0 {
  78                 t.Fatalf("unexpected header %#x", hd)
  79         }
  80
  81         if tl[0] != 0 || tl[1] != 1 || tl[2] != 0 {
  82                 t.Fatalf("malformed end-of-data marker %#x", tl)
  83         }
  84
  85         for len(val) > 0 {
  86                 if len(val) < 2 || val[0] < 1 || val[1] < 1 || uintptr(len(val)) < 2+val[1] {
  87                         t.Fatalf("malformed profile.  leftover: %#x", val)
  88                 }
  89                 f(val[0], val[2:2+val[1]])
  90                 val = val[2+val[1]:]
  91         }
  92 }
  93
  94 func testCPUProfile(t *testing.T, need []string, f func()) {
  95         switch runtime.GOOS {
  96         case "darwin":
  97                 out, err := exec.Command("uname", "-a").CombinedOutput()
  98                 if err != nil {
  99                         t.Fatal(err)
 100                 }
 101                 vers := string(out)
 102                 t.Logf("uname -a: %v", vers)
 103         case "plan9":
 104                 // unimplemented
 105                 return
 106         }
 107
 108         var prof bytes.Buffer
 109         if err := StartCPUProfile(&prof); err != nil {
 110                 t.Fatal(err)
 111         }
 112         f()
 113         StopCPUProfile()
 114
 115         // Check that profile is well formed and contains ChecksumIEEE.
 116         have := make([]uintptr, len(need))
 117         parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) {
 118                 for _, pc := range stk {
 119                         f := runtime.FuncForPC(pc)
 120                         if f == nil {
 121                                 continue
 122                         }
 123                         for i, name := range need {
 124                                 if strings.Contains(f.Name(), name) {
 125                                         have[i] += count
 126                                 }
 127                         }
 128                 }
 129         })
 130
 131         if len(need) == 0 {
 132                 return
 133         }
 134
 135         var total uintptr
 136         for i, name := range need {
 137                 total += have[i]
 138                 t.Logf("%s: %d\n", name, have[i])
 139         }
 140         ok := true
 141         if total == 0 {
 142                 t.Logf("no CPU profile samples collected")
 143                 ok = false
 144         }
 145         min := total / uintptr(len(have)) / 3
 146         for i, name := range need {
 147                 if have[i] < min {
 148                         t.Logf("%s has %d samples out of %d, want at least %d, ideally %d", name, have[i], total, min, total/uintptr(len(have)))
 149                         ok = false
 150                 }
 151         }
 152
 153         if !ok {
 154                 if badOS[runtime.GOOS] {
 155                         t.Skipf("ignoring failure on %s; see golang.org/issue/6047", runtime.GOOS)
 156                         return
 157                 }
 158                 t.FailNow()
 159         }
 160 }
 161
 162 func TestCPUProfileWithFork(t *testing.T) {
 163         // Fork can hang if preempted with signals frequently enough (see issue 5517).
 164         // Ensure that we do not do this.
 165         heap := 1 << 30
 166         if testing.Short() {
 167                 heap = 100 << 20
 168         }
 169         // This makes fork slower.
 170         garbage := make([]byte, heap)
 171         // Need to touch the slice, otherwise it won't be paged in.
 172         done := make(chan bool)
 173         go func() {
 174                 for i := range garbage {
 175                         garbage[i] = 42
 176                 }
 177                 done <- true
 178         }()
 179         <-done
 180
 181         var prof bytes.Buffer
 182         if err := StartCPUProfile(&prof); err != nil {
 183                 t.Fatal(err)
 184         }
 185         defer StopCPUProfile()
 186
 187         for i := 0; i < 10; i++ {
 188                 exec.Command("go").CombinedOutput()
 189         }
 190 }
 191
 192 // Test that profiler does not observe runtime.gogo as "user" goroutine execution.
 193 // If it did, it would see inconsistent state and would either record an incorrect stack
 194 // or crash because the stack was malformed.
 195 func TestGoroutineSwitch(t *testing.T) {
 196         if runtime.GOOS == "windows" {
 197                 t.Skip("flaky test; see http://golang.org/issue/6417")
 198         }
 199         // How much to try. These defaults take about 1 seconds
 200         // on a 2012 MacBook Pro. The ones in short mode take
 201         // about 0.1 seconds.
 202         tries := 10
 203         count := 1000000
 204         if testing.Short() {
 205                 tries = 1
 206         }
 207         for try := 0; try < tries; try++ {
 208                 var prof bytes.Buffer
 209                 if err := StartCPUProfile(&prof); err != nil {
 210                         t.Fatal(err)
 211                 }
 212                 for i := 0; i < count; i++ {
 213                         runtime.Gosched()
 214                 }
 215                 StopCPUProfile()
 216
 217                 // Read profile to look for entries for runtime.gogo with an attempt at a traceback.
 218                 // The special entry
 219                 parseProfile(t, prof.Bytes(), func(count uintptr, stk []uintptr) {
 220                         // An entry with two frames with 'System' in its top frame
 221                         // exists to record a PC without a traceback. Those are okay.
 222                         if len(stk) == 2 {
 223                                 f := runtime.FuncForPC(stk[1])
 224                                 if f != nil && f.Name() == "System" {
 225                                         return
 226                                 }
 227                         }
 228
 229                         // Otherwise, should not see runtime.gogo.
 230                         // The place we'd see it would be the inner most frame.
 231                         f := runtime.FuncForPC(stk[0])
 232                         if f != nil && f.Name() == "runtime.gogo" {
 233                                 var buf bytes.Buffer
 234                                 for _, pc := range stk {
 235                                         f := runtime.FuncForPC(pc)
 236                                         if f == nil {
 237                                                 fmt.Fprintf(&buf, "%#x ?:0\n", pc)
 238                                         } else {
 239                                                 file, line := f.FileLine(pc)
 240                                                 fmt.Fprintf(&buf, "%#x %s:%d\n", pc, file, line)
 241                                         }
 242                                 }
 243                                 t.Fatalf("found profile entry for runtime.gogo:\n%s", buf.String())
 244                         }
 245                 })
 246         }
 247 }
 248
 249 // Test that profiling of division operations is okay, especially on ARM. See issue 6681.
 250 func TestMathBigDivide(t *testing.T) {
 251         // TODO(brainman): delete when issue 6986 is fixed.
 252         if runtime.GOOS == "windows" && runtime.GOARCH == "amd64" {
 253                 t.Skip("skipping broken test on windows-amd64-race")
 254         }
 255         testCPUProfile(t, nil, func() {
 256                 t := time.After(5 * time.Second)
 257                 pi := new(big.Int)
 258                 for {
 259                         for i := 0; i < 100; i++ {
 260                                 n := big.NewInt(2646693125139304345)
 261                                 d := big.NewInt(842468587426513207)
 262                                 pi.Div(n, d)
 263                         }
 264                         select {
 265                         case <-t:
 266                                 return
 267                         default:
 268                         }
 269                 }
 270         })
 271 }
 272
 273 // Operating systems that are expected to fail the tests. See issue 6047.
 274 var badOS = map[string]bool{
 275         "darwin":  true,
 276         "netbsd":  true,
 277         "openbsd": true,
 278 }
 279
 280 func TestBlockProfile(t *testing.T) {
 281         t.Skip("lots of details are different for gccgo; FIXME")
 282         type TestCase struct {
 283                 name string
 284                 f    func()
 285                 re   string
 286         }
 287         tests := [...]TestCase{
 288                 {"chan recv", blockChanRecv, `
 289 [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]+
 290 #       0x[0-9,a-f]+    runtime\.chanrecv1\+0x[0-9,a-f]+        .*/src/pkg/runtime/chan.c:[0-9]+
 291 #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanRecv\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 292 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 293 `},
 294                 {"chan send", blockChanSend, `
 295 [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]+
 296 #       0x[0-9,a-f]+    runtime\.chansend1\+0x[0-9,a-f]+        .*/src/pkg/runtime/chan.c:[0-9]+
 297 #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanSend\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 298 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 299 `},
 300                 {"chan close", blockChanClose, `
 301 [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]+
 302 #       0x[0-9,a-f]+    runtime\.chanrecv1\+0x[0-9,a-f]+        .*/src/pkg/runtime/chan.c:[0-9]+
 303 #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanClose\+0x[0-9,a-f]+        .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 304 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 305 `},
 306                 {"select recv async", blockSelectRecvAsync, `
 307 [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]+
 308 #       0x[0-9,a-f]+    runtime\.selectgo\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+
 309 #       0x[0-9,a-f]+    runtime/pprof_test\.blockSelectRecvAsync\+0x[0-9,a-f]+  .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 310 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 311 `},
 312                 {"select send sync", blockSelectSendSync, `
 313 [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]+
 314 #       0x[0-9,a-f]+    runtime\.selectgo\+0x[0-9,a-f]+ .*/src/pkg/runtime/chan.c:[0-9]+
 315 #       0x[0-9,a-f]+    runtime/pprof_test\.blockSelectSendSync\+0x[0-9,a-f]+   .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 316 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 317 `},
 318                 {"mutex", blockMutex, `
 319 [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]+
 320 #       0x[0-9,a-f]+    sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+   .*/src/pkg/sync/mutex\.go:[0-9]+
 321 #       0x[0-9,a-f]+    runtime/pprof_test\.blockMutex\+0x[0-9,a-f]+    .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 322 #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
 323 `},
 324         }
 325
 326         runtime.SetBlockProfileRate(1)
 327         defer runtime.SetBlockProfileRate(0)
 328         for _, test := range tests {
 329                 test.f()
 330         }
 331         var w bytes.Buffer
 332         Lookup("block").WriteTo(&w, 1)
 333         prof := w.String()
 334
 335         if !strings.HasPrefix(prof, "--- contention:\ncycles/second=") {
 336                 t.Fatalf("Bad profile header:\n%v", prof)
 337         }
 338
 339         for _, test := range tests {
 340                 if !regexp.MustCompile(test.re).MatchString(prof) {
 341                         t.Fatalf("Bad %v entry, expect:\n%v\ngot:\n%v", test.name, test.re, prof)
 342                 }
 343         }
 344 }
 345
 346 const blockDelay = 10 * time.Millisecond
 347
 348 func blockChanRecv() {
 349         c := make(chan bool)
 350         go func() {
 351                 time.Sleep(blockDelay)
 352                 c <- true
 353         }()
 354         <-c
 355 }
 356
 357 func blockChanSend() {
 358         c := make(chan bool)
 359         go func() {
 360                 time.Sleep(blockDelay)
 361                 <-c
 362         }()
 363         c <- true
 364 }
 365
 366 func blockChanClose() {
 367         c := make(chan bool)
 368         go func() {
 369                 time.Sleep(blockDelay)
 370                 close(c)
 371         }()
 372         <-c
 373 }
 374
 375 func blockSelectRecvAsync() {
 376         c := make(chan bool, 1)
 377         c2 := make(chan bool, 1)
 378         go func() {
 379                 time.Sleep(blockDelay)
 380                 c <- true
 381         }()
 382         select {
 383         case <-c:
 384         case <-c2:
 385         }
 386 }
 387
 388 func blockSelectSendSync() {
 389         c := make(chan bool)
 390         c2 := make(chan bool)
 391         go func() {
 392                 time.Sleep(blockDelay)
 393                 <-c
 394         }()
 395         select {
 396         case c <- true:
 397         case c2 <- true:
 398         }
 399 }
 400
 401 func blockMutex() {
 402         var mu sync.Mutex
 403         mu.Lock()
 404         go func() {
 405                 time.Sleep(blockDelay)
 406                 mu.Unlock()
 407         }()
 408         mu.Lock()
 409 }