runtime/pprof: TestCPUProfileWithFork is flaky

[bcmills]

(Extracted from a comment on #18332.)

TestCPUProfileWithFork is flaky for me using all.bash.

$ go version
go version devel +0cd2bf4 Thu Dec 15 22:43:28 2016 +0000 linux/amd64

$ $(go env CC) --version
gcc (Ubuntu 4.8.4-2ubuntu1~14.04.3) 4.8.4

SIGQUIT: quit
PC=0x466343 m=0 sigcode=0

goroutine 16 [running]:
syscall.RawSyscall6(0x38, 0x11, 0x0, 0x0, 0x0, 0x0, 0x0, 0x125, 0xc4204f8a50, 0x80000)
	/home/bcmills/src/go/src/syscall/asm_linux_amd64.s:100 +0x23 fp=0xc4204f89a0 sp=0xc4204f8998
syscall.forkAndExecInChild(0xc420016840, 0xc4204d8560, 0x3, 0x3, 0xc4202c21e0, 0x3c, 0x3c, 0x0, 0x0, 0xc4204f8cc0, ...)
	/home/bcmills/src/go/src/syscall/exec_linux.go:101 +0x210 fp=0xc4204f8ab0 sp=0xc4204f89a0
syscall.forkExec(0x7ffc81cdb688, 0x35, 0xc4204d8000, 0x2, 0x2, 0xc4204f8cc0, 0x0, 0x0, 0x0)
	/home/bcmills/src/go/src/syscall/exec_unix.go:193 +0x368 fp=0xc4204f8bd8 sp=0xc4204f8ab0
syscall.StartProcess(0x7ffc81cdb688, 0x35, 0xc4204d8000, 0x2, 0x2, 0xc4204f8cc0, 0x2, 0x4, 0xc4204e20f0, 0xc4204f8c90)
	/home/bcmills/src/go/src/syscall/exec_unix.go:240 +0x64 fp=0xc4204f8c30 sp=0xc4204f8bd8
os.startProcess(0x7ffc81cdb688, 0x35, 0xc4204d8000, 0x2, 0x2, 0xc4204f8e68, 0xc4204d6800, 0x3b, 0x3b)
	/home/bcmills/src/go/src/os/exec_posix.go:45 +0x1a3 fp=0xc4204f8d18 sp=0xc4204f8c30
os.StartProcess(0x7ffc81cdb688, 0x35, 0xc4204d8000, 0x2, 0x2, 0xc4204f8e68, 0x0, 0x0, 0x4512d0)
	/home/bcmills/src/go/src/os/exec.go:94 +0x64 fp=0xc4204f8d70 sp=0xc4204f8d18
os/exec.(*Cmd).Start(0xc4200b8000, 0xc4200fd701, 0xc4200ba1c0)
	/home/bcmills/src/go/src/os/exec/exec.go:359 +0x3d2 fp=0xc4204f8ec0 sp=0xc4204f8d70
os/exec.(*Cmd).Run(0xc4200b8000, 0xc4200ba1c0, 0xc4200b8000)
	/home/bcmills/src/go/src/os/exec/exec.go:277 +0x2b fp=0xc4204f8ee8 sp=0xc4204f8ec0
os/exec.(*Cmd).CombinedOutput(0xc4200b8000, 0x35, 0xc4200fd778, 0x1, 0x1, 0xc4200b8000)
	/home/bcmills/src/go/src/os/exec/exec.go:495 +0x127 fp=0xc4204f8f20 sp=0xc4204f8ee8
runtime/pprof_test.TestCPUProfileWithFork(0xc420070270)
	/home/bcmills/src/go/src/runtime/pprof/pprof_test.go:271 +0x228 fp=0xc4204f8fa8 sp=0xc4204f8f20
testing.tRunner(0xc420070270, 0x5bf5b8)
	/home/bcmills/src/go/src/testing/testing.go:656 +0x93 fp=0xc4204f8fd0 sp=0xc4204f8fa8
runtime.goexit()
	/home/bcmills/src/go/src/runtime/asm_amd64.s:2184 +0x1 fp=0xc4204f8fd8 sp=0xc4204f8fd0
created by testing.(*T).Run
	/home/bcmills/src/go/src/testing/testing.go:693 +0x2c4

goroutine 1 [chan receive, 3 minutes]:
testing.(*T).Run(0xc4200704e0, 0x5b7328, 0x16, 0x5bf5b8, 0xc420043d01)
	/home/bcmills/src/go/src/testing/testing.go:694 +0x2ee
testing.runTests.func1(0xc4200704e0)
	/home/bcmills/src/go/src/testing/testing.go:877 +0x67
testing.tRunner(0xc4200704e0, 0xc420043de0)
	/home/bcmills/src/go/src/testing/testing.go:656 +0x93
testing.runTests(0xc42000ab60, 0x69b100, 0xa, 0xa, 0x5b3376)
	/home/bcmills/src/go/src/testing/testing.go:883 +0x29d
testing.(*M).Run(0xc420043f20, 0xc420043f20)
	/home/bcmills/src/go/src/testing/testing.go:818 +0xfc
main.main()
runtime/pprof/_test/_testmain.go:60 +0xf7

goroutine 36 [syscall]:
runtime.CPUProfile(0x59a540, 0xc4200a8000, 0x69d620)
	/home/bcmills/src/go/src/runtime/cpuprof.go:448 +0x2d
runtime/pprof.profileWriter(0x6843a0, 0xc4200ba0e0)
	/home/bcmills/src/go/src/runtime/pprof/pprof.go:701 +0x63
created by runtime/pprof.StartCPUProfile
	/home/bcmills/src/go/src/runtime/pprof/pprof.go:688 +0x122

rax    0x38
rbx    0x69ddc0
rcx    0xffffffffffffffff
rdx    0x0
rdi    0x11
rsi    0x0
rbp    0xc4204f8aa0
rsp    0xc4204f8998
r8     0x0
r9     0x0
r10    0x0
r11    0x206
r12    0x0
r13    0xffffffee
r14    0x740
r15    0x100
rip    0x466343
rflags 0x206
cs     0x33
fs     0x0
gs     0x0
*** Test killed with quit: ran too long (4m0s).
FAIL    runtime/pprof   240.059s

[ianlancetaylor]

Thanks for pulling this out of the other issue. I'm not sure what is happening here. The test was killed because it ran for more than 4 minutes. When I run the test with -test.short, which is how all.bash runs it, it takes around 1.3 seconds. The interrupt occurred while the syscall package was calling the clone syscall. It appears that that somehow hung. I can not think of anything that would cause that to happen.

Can you recreate this at all? Do you have any FUSE file systems mounted (I'm looking at #11155)?

[bcmills]

I do indeed have a FUSE filesystem mounted, but I don't think the all.bash test environment includes any FUSE-mounted paths on my system.

I saw several flakes yesterday, but am unable to reproduce one today.

Pardon my ignorance, but I can't seem to figure out how to run individual standard-library tests in the correct environment. (go test runtime/pprof/pprof_test.go -test.short fails for me every time in an unrelated way, so I'm assuming I'm invoking it incorrectly.) Could you share the command-line you're using to run it?

[bradfitz]

go test generally takes a package, not a file. The file support is very limited and weird, and probably doesn't work for the standard library.

$ go test -short runtime/pprof
$ go test -short -run=RegexpFilter runtime/pprof

[bcmills]

Found a command-line that seems to run the test, but it's not reproducing the failure:

$ GOPATH="$GOROOT/src" go test runtime/pprof -test.short

[bradfitz]

GOPATH="$GOROOT/src" is bogus. The GOPATH and GOROOT can't overlap. Some commands throw errors if they do. Probably "go test" should also.

[bcmills]

Ok, I think I've got my workspace in a more sane state: go test runtime/pprof -test.short works out of the box now. Still trying to reproduce the failure.

[bradfitz]

@bcmills, any update?

[bcmills]

I still haven't been able to reproduce the flakes I was seeing.