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