runtime/pprof: TestStackBarrierProfiling hangs

[alexbrainman]

Please answer these questions before submitting your issue. Thanks!

1. What version of Go are you using (go version)?

go version devel +80e9a7f Thu Apr 28 05:26:36 2016 +0000 linux/386

1. What operating system and processor architecture are you using (go env)?

GOARCH="386"
GOBIN=""
GOEXE=""
GOHOSTARCH="386"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/root"
GORACE=""
GOROOT="/root/go"
GOTOOLDIR="/root/go/pkg/tool/linux_386"
CC="gcc"
GOGCCFLAGS="-fPIC -m32 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build695579586=/tmp/go-build"
CXX="g++"
CGO_ENABLED="1"

1. What did you do?
   If possible, provide a recipe for reproducing the error.
   A complete runnable program is good.
   A link on play.golang.org is best.

I run:

go test runtime/pprof -v -short -run=TestStackBarrierProfiling -timeout=1m

1. What did you expect to see?

I expect test pass.

1. What did you see instead?

=== RUN   TestStackBarrierProfiling
panic: test timed out after 1m0s

goroutine 8 [running]:
panic(0x813de00, 0x184262d0)
        /root/go/src/runtime/panic.go:500 +0x331
testing.startAlarm.func1()
        /root/go/src/testing/testing.go:855 +0xf5
created by time.goFunc
        /root/go/src/time/sleep.go:129 +0x36

goroutine 1 [chan receive]:
testing.(*T).Run(0x18418280, 0x8160c86, 0x19, 0x816f7b0, 0x1)
        /root/go/src/testing/testing.go:584 +0x2c4
testing.RunTests.func1(0x18418200)
        /root/go/src/testing/testing.go:730 +0x98
testing.tRunner(0x18418200, 0x18439ed8)
        /root/go/src/testing/testing.go:547 +0x8c
testing.RunTests(0x816f50c, 0x81d9da0, 0x9, 0x9, 0x18462001)
        /root/go/src/testing/testing.go:736 +0x332
testing.(*M).Run(0x18439f7c, 0x0)
        /root/go/src/testing/testing.go:680 +0x79
main.main()
        runtime/pprof/_test/_testmain.go:72 +0x100

goroutine 6 [syscall]:
syscall.Syscall6(0x72, 0x76c1, 0x184245cc, 0x0, 0x18478000, 0x0, 0x0, 0x80772bf, 0xb76df000, 0x0)
        /root/go/src/syscall/asm_linux_386.s:45 +0x5
syscall.wait4(0x76c1, 0x184245cc, 0x0, 0x18478000, 0x50, 0x0, 0x0)
        /root/go/src/syscall/zsyscall_linux_386.go:172 +0x71
syscall.Wait4(0x76c1, 0x184245f0, 0x0, 0x18478000, 0x184262b0, 0x0, 0x0)
        /root/go/src/syscall/syscall_linux.go:256 +0x4d
os.(*Process).wait(0x184103a0, 0x1f, 0x0, 0x0)
        /root/go/src/os/exec_unix.go:22 +0xae
os.(*Process).Wait(0x184103a0, 0x0, 0x0, 0x0)
        /root/go/src/os/doc.go:49 +0x2b
os/exec.(*Cmd).Wait(0x1840e140, 0x0, 0x0)
        /root/go/src/os/exec/exec.go:396 +0x11c
os/exec.(*Cmd).Run(0x1840e140, 0x0, 0x0)
        /root/go/src/os/exec/exec.go:262 +0x58
os/exec.(*Cmd).CombinedOutput(0x1840e140, 0x0, 0x0, 0x0, 0x0, 0x0)
        /root/go/src/os/exec/exec.go:453 +0x1a7
runtime/pprof_test.TestStackBarrierProfiling(0x18418280)
        /root/go/src/runtime/pprof/pprof_test.go:392 +0x2b6
testing.tRunner(0x18418280, 0x816f7b0)
        /root/go/src/testing/testing.go:547 +0x8c
created by testing.(*T).Run
        /root/go/src/testing/testing.go:583 +0x2a5

goroutine 7 [syscall]:
syscall.Syscall(0x3, 0x4, 0x1847a000, 0x200, 0xb76df000, 0x0, 0x1)
        /root/go/src/syscall/asm_linux_386.s:20 +0x5
syscall.read(0x4, 0x1847a000, 0x200, 0x200, 0x816f4fc, 0x0, 0x0)
        /root/go/src/syscall/zsyscall_linux_386.go:783 +0x5b
syscall.Read(0x4, 0x1847a000, 0x200, 0x200, 0x0, 0x0, 0x0)
        /root/go/src/syscall/syscall_unix.go:161 +0x45
os.(*File).read(0x184262a8, 0x1847a000, 0x200, 0x200, 0x1847a000, 0x0, 0x0)
        /root/go/src/os/file_unix.go:228 +0x4a
os.(*File).Read(0x184262a8, 0x1847a000, 0x200, 0x200, 0x11de5298, 0x0, 0x0)
        /root/go/src/os/file.go:97 +0x6f
bytes.(*Buffer).ReadFrom(0x18462180, 0x81c9770, 0x184262a8, 0x0, 0x0, 0x0, 0x0)
        /root/go/src/bytes/buffer.go:176 +0x1c5
io.copyBuffer(0x81c96f0, 0x18462180, 0x81c9770, 0x184262a8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /root/go/src/io/io.go:392 +0x129
io.Copy(0x81c96f0, 0x18462180, 0x81c9770, 0x184262a8, 0x0, 0x0, 0x0, 0x0)
        /root/go/src/io/io.go:368 +0x53
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
        /root/go/src/os/exec/exec.go:236 +0x57
os/exec.(*Cmd).Start.func1(0x1840e140, 0x18410260)
        /root/go/src/os/exec/exec.go:344 +0x1d
created by os/exec.(*Cmd).Start
        /root/go/src/os/exec/exec.go:345 +0x698
exit status 2
FAIL    runtime/pprof   60.005s

The test fails on my windows-amd64 too.

Alex

[ianlancetaylor]

CC @aclements

[aclements]

@alexbrainman, can you re-run with GOTRACEBACK=crash?

[alexbrainman]

re-run with GOTRACEBACK=crash?

=== RUN   TestStackBarrierProfiling
panic: test timed out after 1m0s

goroutine 8 [running]:
panic(0x813de00, 0x184262d0)
    /root/go/src/runtime/panic.go:500 +0x331 fp=0x184257a0 sp=0x1842575c
testing.startAlarm.func1()
    /root/go/src/testing/testing.go:855 +0xf5 fp=0x184257e0 sp=0x184257a0
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x184257e4 sp=0x184257e0
created by time.goFunc
    /root/go/src/time/sleep.go:129 +0x36

goroutine 1 [chan receive]:
runtime.gopark(0x816f6d8, 0x184422b0, 0x815e3ca, 0xc, 0x81d7d17, 0x3)
    /root/go/src/runtime/proc.go:264 +0x130 fp=0x18439d08 sp=0x18439cf4
runtime.goparkunlock(0x184422b0, 0x815e3ca, 0xc, 0x809cf17, 0x3)
    /root/go/src/runtime/proc.go:270 +0x4b fp=0x18439d24 sp=0x18439d08
runtime.chanrecv(0x813cc80, 0x18442280, 0x0, 0x18439d01, 0x80a0000)
    /root/go/src/runtime/chan.go:496 +0x3e8 fp=0x18439d6c sp=0x18439d24
runtime.chanrecv1(0x813cc80, 0x18442280, 0x0)
    /root/go/src/runtime/chan.go:378 +0x24 fp=0x18439d84 sp=0x18439d6c
testing.(*T).Run(0x18418280, 0x8160c86, 0x19, 0x816f7b0, 0x1)
    /root/go/src/testing/testing.go:584 +0x2c4 fp=0x18439dec sp=0x18439d84
testing.RunTests.func1(0x18418200)
    /root/go/src/testing/testing.go:730 +0x98 fp=0x18439e34 sp=0x18439dec
testing.tRunner(0x18418200, 0x18439ed8)
    /root/go/src/testing/testing.go:547 +0x8c fp=0x18439e58 sp=0x18439e34
testing.RunTests(0x816f50c, 0x81d9da0, 0x9, 0x9, 0x18462001)
    /root/go/src/testing/testing.go:736 +0x332 fp=0x18439eec sp=0x18439e58
testing.(*M).Run(0x18439f7c, 0x0)
    /root/go/src/testing/testing.go:680 +0x79 fp=0x18439f2c sp=0x18439eec
main.main()
    runtime/pprof/_test/_testmain.go:72 +0x100 fp=0x18439fa8 sp=0x18439f2c
runtime.main()
    /root/go/src/runtime/proc.go:188 +0x276 fp=0x18439fd0 sp=0x18439fa8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x18439fd4 sp=0x18439fd0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x816f6d8, 0x81dae88, 0x815ebae, 0xf, 0x14adb14, 0x1)
    /root/go/src/runtime/proc.go:264 +0x130 fp=0x184227ac sp=0x18422798
runtime.goparkunlock(0x81dae88, 0x815ebae, 0xf, 0x18400014, 0x1)
    /root/go/src/runtime/proc.go:270 +0x4b fp=0x184227c8 sp=0x184227ac
runtime.forcegchelper()
    /root/go/src/runtime/proc.go:229 +0xaa fp=0x184227e0 sp=0x184227c8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x184227e4 sp=0x184227e0
created by runtime.init.4
    /root/go/src/runtime/proc.go:218 +0x2a

goroutine 3 [GC sweep wait]:
runtime.gopark(0x816f6d8, 0x81daf60, 0x815e607, 0xd, 0x8062f14, 0x1)
    /root/go/src/runtime/proc.go:264 +0x130 fp=0x18422fa0 sp=0x18422f8c
runtime.goparkunlock(0x81daf60, 0x815e607, 0xd, 0x14, 0x1)
    /root/go/src/runtime/proc.go:270 +0x4b fp=0x18422fbc sp=0x18422fa0
runtime.bgsweep(0x18442000)
    /root/go/src/runtime/mgcsweep.go:63 +0xa0 fp=0x18422fd8 sp=0x18422fbc
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x18422fdc sp=0x18422fd8
created by runtime.gcenable
    /root/go/src/runtime/mgc.go:195 +0x52

goroutine 4 [finalizer wait]:
runtime.gopark(0x816f6d8, 0x81eb258, 0x815e8df, 0xe, 0x14, 0x1)
    /root/go/src/runtime/proc.go:264 +0x130 fp=0x1842378c sp=0x18423778
runtime.goparkunlock(0x81eb258, 0x815e8df, 0xe, 0x14, 0x1)
    /root/go/src/runtime/proc.go:270 +0x4b fp=0x184237a8 sp=0x1842378c
runtime.runfinq()
    /root/go/src/runtime/mfinal.go:158 +0x9e fp=0x184237e0 sp=0x184237a8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x184237e4 sp=0x184237e0
created by runtime.createfing
    /root/go/src/runtime/mfinal.go:139 +0x5c

goroutine 5 [timer goroutine (idle)]:
runtime.gopark(0x816f6d8, 0x81db000, 0x81605ad, 0x16, 0x816f814, 0x1)
    /root/go/src/runtime/proc.go:264 +0x130 fp=0x18423f70 sp=0x18423f5c
runtime.goparkunlock(0x81db000, 0x81605ad, 0x16, 0x14, 0x1)
    /root/go/src/runtime/proc.go:270 +0x4b fp=0x18423f8c sp=0x18423f70
runtime.timerproc()
    /root/go/src/runtime/time.go:202 +0x123 fp=0x18423fe0 sp=0x18423f8c
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x18423fe4 sp=0x18423fe0
created by runtime.addtimerLocked
    /root/go/src/runtime/time.go:116 +0x112

goroutine 6 [syscall]:
syscall.Syscall6(0x72, 0x1217, 0x184245cc, 0x0, 0x18478000, 0x0, 0x0, 0x80772bf, 0xb76fd000, 0x0)
    /root/go/src/syscall/asm_linux_386.s:45 +0x5 fp=0x18424570 sp=0x1842456c
syscall.wait4(0x1217, 0x184245cc, 0x0, 0x18478000, 0x50, 0x0, 0x0)
    /root/go/src/syscall/zsyscall_linux_386.go:172 +0x71 fp=0x184245b0 sp=0x18424570
syscall.Wait4(0x1217, 0x184245f0, 0x0, 0x18478000, 0x184262b0, 0x0, 0x0)
    /root/go/src/syscall/syscall_linux.go:256 +0x4d fp=0x184245d4 sp=0x184245b0
os.(*Process).wait(0x184103a0, 0x20, 0x0, 0x0)
    /root/go/src/os/exec_unix.go:22 +0xae fp=0x1842462c sp=0x184245d4
os.(*Process).Wait(0x184103a0, 0x0, 0x0, 0x0)
    /root/go/src/os/doc.go:49 +0x2b fp=0x18424640 sp=0x1842462c
os/exec.(*Cmd).Wait(0x1840e140, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:396 +0x11c fp=0x184246a8 sp=0x18424640
os/exec.(*Cmd).Run(0x1840e140, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:262 +0x58 fp=0x184246c0 sp=0x184246a8
os/exec.(*Cmd).CombinedOutput(0x1840e140, 0x0, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:453 +0x1a7 fp=0x18424708 sp=0x184246c0
runtime/pprof_test.TestStackBarrierProfiling(0x18418280)
    /root/go/src/runtime/pprof/pprof_test.go:392 +0x2b6 fp=0x184247b4 sp=0x18424708
testing.tRunner(0x18418280, 0x816f7b0)
    /root/go/src/testing/testing.go:547 +0x8c fp=0x184247d8 sp=0x184247b4
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x184247dc sp=0x184247d8
created by testing.(*T).Run
    /root/go/src/testing/testing.go:583 +0x2a5

goroutine 7 [syscall]:
syscall.Syscall(0x3, 0x4, 0x1847a000, 0x200, 0xb76fd000, 0x0, 0x1)
    /root/go/src/syscall/asm_linux_386.s:20 +0x5 fp=0x18424dfc sp=0x18424df8
syscall.read(0x4, 0x1847a000, 0x200, 0x200, 0x816f4fc, 0x0, 0x0)
    /root/go/src/syscall/zsyscall_linux_386.go:783 +0x5b fp=0x18424e28 sp=0x18424dfc
syscall.Read(0x4, 0x1847a000, 0x200, 0x200, 0x0, 0x0, 0x0)
    /root/go/src/syscall/syscall_unix.go:161 +0x45 fp=0x18424e48 sp=0x18424e28
os.(*File).read(0x184262a8, 0x1847a000, 0x200, 0x200, 0x1847a000, 0x0, 0x0)
    /root/go/src/os/file_unix.go:228 +0x4a fp=0x18424e68 sp=0x18424e48
os.(*File).Read(0x184262a8, 0x1847a000, 0x200, 0x200, 0x11de5298, 0x0, 0x0)
    /root/go/src/os/file.go:97 +0x6f fp=0x18424e94 sp=0x18424e68
bytes.(*Buffer).ReadFrom(0x18462180, 0x81c9770, 0x184262a8, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/bytes/buffer.go:176 +0x1c5 fp=0x18424eec sp=0x18424e94
io.copyBuffer(0x81c96f0, 0x18462180, 0x81c9770, 0x184262a8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /root/go/src/io/io.go:392 +0x129 fp=0x18424f50 sp=0x18424eec
io.Copy(0x81c96f0, 0x18462180, 0x81c9770, 0x184262a8, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/io/io.go:368 +0x53 fp=0x18424f80 sp=0x18424f50
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
    /root/go/src/os/exec/exec.go:236 +0x57 fp=0x18424fc0 sp=0x18424f80
os/exec.(*Cmd).Start.func1(0x1840e140, 0x18410260)
    /root/go/src/os/exec/exec.go:344 +0x1d fp=0x18424fd8 sp=0x18424fc0
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1601 +0x1 fp=0x18424fdc sp=0x18424fd8
created by os/exec.(*Cmd).Start
    /root/go/src/os/exec/exec.go:345 +0x698
signal: aborted
FAIL    runtime/pprof   60.007s

Alex

[aclements]

@alexbrainman, are you (or were you) able to reproduce this reliably? How many CPUs does the host have?

I haven't been able to reproduce this on a linux/amd64 host with GOARCH=386, or on the linux-386 gomote. If you can still reproduce this easily, could you run GODEBUG=gcstackbarrierall=1 GOGC=1 ./pprof.test -test.v -test.short -test.run=TestStackBarrierProfiling -test.timeout=1m?

[aclements]

Actually, GODEBUG=gcstackbarrierall=1 GOGC=1 GOTRACEBACK=crash ./pprof.test -test.v -test.short -test.run=TestStackBarrierProfiling -test.timeout=1m

[gopherbot]

CL https://golang.org/cl/23134 mentions this issue.

[alexbrainman]

are you (or were you) able to reproduce this reliably?

Yes. It fails nearly every time.

How many CPUs does the host have?

processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model       : 26
model name  : Intel(R) Xeon(R) CPU           E5530  @ 2.40GHz
stepping    : 5
microcode   : 0x10
cpu MHz     : 2400.085
cache size  : 8192 KB
fdiv_bug    : no
hlt_bug     : no
f00f_bug    : no
coma_bug    : no
fpu     : yes
fpu_exception   : yes
cpuid level : 11
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss nx rdtscp lm constant_tsc up arch_perfmon pebs bts xtopology tsc_reliable nonstop_tsc aperfmperf pni ssse3 cx16 sse4_1 sse4_2 popcnt hypervisor lahf_lm ida dts
bogomips    : 4800.17
clflush size    : 64
cache_alignment : 64
address sizes   : 40 bits physical, 48 bits virtual
power management:

Actually, GODEBUG=gcstackbarrierall=1 GOGC=1 GOTRACEBACK=crash ./pprof.test -test.v -test.short -test.run=TestStackBarrierProfiling -test.timeout=1m

If I use GODEBUG=gcstackbarrierall=1, the problem goes away. So running:

# go test -c && GOGC=1 GOTRACEBACK=crash ./pprof.test -test.v -test.short -test.run=TestStackBarrierProfiling -test.timeout=1m
panic: test timed out after 1m0s

goroutine 9 [running]:
panic(0x8142240, 0x185261d8)
    /root/go/src/runtime/panic.go:500 +0x331 fp=0x1851f7a0 sp=0x1851f75c
testing.startAlarm.func1()
    /root/go/src/testing/testing.go:855 +0xf5 fp=0x1851f7e0 sp=0x1851f7a0
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x1851f7e4 sp=0x1851f7e0
created by time.goFunc
    /root/go/src/time/sleep.go:129 +0x36

goroutine 1 [chan receive, 1 minutes]:
runtime.gopark(0x8174460, 0x185421b0, 0x8162da0, 0xc, 0x18512017, 0x3)
    /root/go/src/runtime/proc.go:265 +0x130 fp=0x1853ed10 sp=0x1853ecfc
runtime.goparkunlock(0x185421b0, 0x8162da0, 0xc, 0x809f617, 0x3)
    /root/go/src/runtime/proc.go:271 +0x4b fp=0x1853ed2c sp=0x1853ed10
runtime.chanrecv(0x8141080, 0x18542180, 0x0, 0x1853ed01, 0x80a0000)
    /root/go/src/runtime/chan.go:496 +0x3e8 fp=0x1853ed74 sp=0x1853ed2c
runtime.chanrecv1(0x8141080, 0x18542180, 0x0)
    /root/go/src/runtime/chan.go:378 +0x24 fp=0x1853ed8c sp=0x1853ed74
testing.(*T).Run(0x18518200, 0x8165738, 0x19, 0x8174538, 0x8056401)
    /root/go/src/testing/testing.go:584 +0x2c4 fp=0x1853edf4 sp=0x1853ed8c
testing.RunTests.func1(0x18518100)
    /root/go/src/testing/testing.go:730 +0x98 fp=0x1853ee3c sp=0x1853edf4
testing.tRunner(0x18518100, 0x1853eee0)
    /root/go/src/testing/testing.go:547 +0x8c fp=0x1853ee60 sp=0x1853ee3c
testing.RunTests(0x817428c, 0x81dfee0, 0x9, 0x9, 0x1856c001)
    /root/go/src/testing/testing.go:736 +0x332 fp=0x1853eef4 sp=0x1853ee60
testing.(*M).Run(0x1853ef84, 0x0)
    /root/go/src/testing/testing.go:680 +0x79 fp=0x1853ef34 sp=0x1853eef4
main.main()
    runtime/pprof/_test/_testmain.go:72 +0x100 fp=0x1853efb0 sp=0x1853ef34
runtime.main()
    /root/go/src/runtime/proc.go:189 +0x276 fp=0x1853efd8 sp=0x1853efb0
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x1853efdc sp=0x1853efd8

goroutine 2 [force gc (idle), 1 minutes]:
runtime.gopark(0x8174460, 0x81e0fe8, 0x816359b, 0xf, 0x1508814, 0x1)
    /root/go/src/runtime/proc.go:265 +0x130 fp=0x185227ac sp=0x18522798
runtime.goparkunlock(0x81e0fe8, 0x816359b, 0xf, 0x18500014, 0x1)
    /root/go/src/runtime/proc.go:271 +0x4b fp=0x185227c8 sp=0x185227ac
runtime.forcegchelper()
    /root/go/src/runtime/proc.go:230 +0xaa fp=0x185227e0 sp=0x185227c8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x185227e4 sp=0x185227e0
created by runtime.init.4
    /root/go/src/runtime/proc.go:219 +0x2a

goroutine 3 [GC sweep wait]:
runtime.gopark(0x8174460, 0x81e10e0, 0x8162ff6, 0xd, 0x8096514, 0x1)
    /root/go/src/runtime/proc.go:265 +0x130 fp=0x18522fa0 sp=0x18522f8c
runtime.goparkunlock(0x81e10e0, 0x8162ff6, 0xd, 0x14, 0x1)
    /root/go/src/runtime/proc.go:271 +0x4b fp=0x18522fbc sp=0x18522fa0
runtime.bgsweep(0x18542000)
    /root/go/src/runtime/mgcsweep.go:79 +0x125 fp=0x18522fd8 sp=0x18522fbc
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x18522fdc sp=0x18522fd8
created by runtime.gcenable
    /root/go/src/runtime/mgc.go:195 +0x52

goroutine 4 [GC worker (idle)]:
runtime.gopark(0x81743b0, 0x18510110, 0x8163797, 0x10, 0x14, 0x0)
    /root/go/src/runtime/proc.go:265 +0x130 fp=0x1852379c sp=0x18523788
runtime.gcBgMarkWorker(0x1851c000)
    /root/go/src/runtime/mgc.go:1421 +0xd6 fp=0x185237d8 sp=0x1852379c
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x185237dc sp=0x185237d8
created by runtime.gcBgMarkStartWorkers
    /root/go/src/runtime/mgc.go:1342 +0x79

goroutine 5 [finalizer wait, 1 minutes]:
runtime.gopark(0x8174460, 0x81f13fc, 0x81632e9, 0xe, 0x14, 0x1)
    /root/go/src/runtime/proc.go:265 +0x130 fp=0x18523f8c sp=0x18523f78
runtime.goparkunlock(0x81f13fc, 0x81632e9, 0xe, 0x14, 0x1)
    /root/go/src/runtime/proc.go:271 +0x4b fp=0x18523fa8 sp=0x18523f8c
runtime.runfinq()
    /root/go/src/runtime/mfinal.go:158 +0x9e fp=0x18523fe0 sp=0x18523fa8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x18523fe4 sp=0x18523fe0
created by runtime.createfing
    /root/go/src/runtime/mfinal.go:139 +0x5c

goroutine 6 [timer goroutine (idle)]:
runtime.gopark(0x8174460, 0x81e1180, 0x816505e, 0x16, 0x8174514, 0x1)
    /root/go/src/runtime/proc.go:265 +0x130 fp=0x18524770 sp=0x1852475c
runtime.goparkunlock(0x81e1180, 0x816505e, 0x16, 0x14, 0x1)
    /root/go/src/runtime/proc.go:271 +0x4b fp=0x1852478c sp=0x18524770
runtime.timerproc()
    /root/go/src/runtime/time.go:202 +0x123 fp=0x185247e0 sp=0x1852478c
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x185247e4 sp=0x185247e0
created by runtime.addtimerLocked
    /root/go/src/runtime/time.go:116 +0x112

goroutine 7 [syscall]:
syscall.Syscall6(0x72, 0x7ed0, 0x1853dda0, 0x0, 0x1855c000, 0x0, 0x0, 0xb76ec000, 0x0, 0x16caa3ff)
    /root/go/src/syscall/asm_linux_386.s:45 +0x5 fp=0x1853dd44 sp=0x1853dd40
syscall.wait4(0x7ed0, 0x1853dda0, 0x0, 0x1855c000, 0x50, 0x0, 0x0)
    /root/go/src/syscall/zsyscall_linux_386.go:172 +0x71 fp=0x1853dd84 sp=0x1853dd44
syscall.Wait4(0x7ed0, 0x1853ddc4, 0x0, 0x1855c000, 0x18510240, 0x0, 0x0)
    /root/go/src/syscall/syscall_linux.go:256 +0x4d fp=0x1853dda8 sp=0x1853dd84
os.(*Process).wait(0x185103a0, 0x0, 0x0, 0x0)
    /root/go/src/os/exec_unix.go:22 +0xae fp=0x1853de00 sp=0x1853dda8
os.(*Process).Wait(0x185103a0, 0x1850e700, 0x0, 0x0)
    /root/go/src/os/doc.go:49 +0x2b fp=0x1853de14 sp=0x1853de00
os/exec.(*Cmd).WaitContext(0x185120a0, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:424 +0x198 fp=0x1853de88 sp=0x1853de14
os/exec.(*Cmd).Wait(0x185120a0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:399 +0x35 fp=0x1853dea0 sp=0x1853de88
os/exec.(*Cmd).Run(0x185120a0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:263 +0x58 fp=0x1853deb8 sp=0x1853dea0
os/exec.(*Cmd).CombinedOutput(0x185120a0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:484 +0x1a7 fp=0x1853df00 sp=0x1853deb8
runtime/pprof_test.TestStackBarrierProfiling(0x18518200)
    /root/go/src/runtime/pprof/pprof_test.go:392 +0x2c8 fp=0x1853dfac sp=0x1853df00
testing.tRunner(0x18518200, 0x8174538)
    /root/go/src/testing/testing.go:547 +0x8c fp=0x1853dfd0 sp=0x1853dfac
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x1853dfd4 sp=0x1853dfd0
created by testing.(*T).Run
    /root/go/src/testing/testing.go:583 +0x2a5

goroutine 8 [syscall]:
syscall.Syscall(0x3, 0x4, 0x1856e000, 0x200, 0x8095550, 0x18528500, 0x0)
    /root/go/src/syscall/asm_linux_386.s:20 +0x5 fp=0x185205fc sp=0x185205f8
syscall.read(0x4, 0x1856e000, 0x200, 0x200, 0x817427c, 0x0, 0x0)
    /root/go/src/syscall/zsyscall_linux_386.go:783 +0x5b fp=0x18520628 sp=0x185205fc
syscall.Read(0x4, 0x1856e000, 0x200, 0x200, 0x0, 0x0, 0x0)
    /root/go/src/syscall/syscall_unix.go:161 +0x45 fp=0x18520648 sp=0x18520628
os.(*File).read(0x18526188, 0x1856e000, 0x200, 0x200, 0x80564fe, 0x0, 0x0)
    /root/go/src/os/file_unix.go:228 +0x4a fp=0x18520668 sp=0x18520648
os.(*File).Read(0x18526188, 0x1856e000, 0x200, 0x200, 0x185206ac, 0x0, 0x0)
    /root/go/src/os/file.go:97 +0x6f fp=0x18520694 sp=0x18520668
bytes.(*Buffer).ReadFrom(0x1856c060, 0x81cf770, 0x18526188, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/bytes/buffer.go:176 +0x1c5 fp=0x185206ec sp=0x18520694
io.copyBuffer(0x81cf6f0, 0x1856c060, 0x81cf770, 0x18526188, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /root/go/src/io/io.go:392 +0x129 fp=0x18520750 sp=0x185206ec
io.Copy(0x81cf6f0, 0x1856c060, 0x81cf770, 0x18526188, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/io/io.go:368 +0x53 fp=0x18520780 sp=0x18520750
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
    /root/go/src/os/exec/exec.go:237 +0x57 fp=0x185207c0 sp=0x18520780
os/exec.(*Cmd).Start.func1(0x185120a0, 0x18510240)
    /root/go/src/os/exec/exec.go:354 +0x1d fp=0x185207d8 sp=0x185207c0
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1605 +0x1 fp=0x185207dc sp=0x185207d8
created by os/exec.(*Cmd).Start
    /root/go/src/os/exec/exec.go:355 +0x698

This is all on current tip:

go version devel +495e3c6 Tue May 17 04:02:11 2016 +0000 linux/386

I hope you have everything you need, Dr Austin.

Alex

[aclements]

Oh, is this a single core? If it is, this is probably the same as #15706.

[aclements]

@alexbrainman, could you give https://golang.org/cl/23172 a try?

[alexbrainman]

Oh, is this a single core?

It is.

... this is probably the same as #15706.

It is. The issue #15706 is about the same TestStackBarrierProfiling hangs. I am closing my issue as duplicate.

... could you give https://golang.org/cl/23172 a try?

CL 23172 fixes my problem. I can run all.bash without fear now. Thank you.

Alex

[aclements]

Great! Thanks for testing.