runtime/pprof: panic: test timed out after 9m0s

[YoshikiShibata]

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

$ go version
go version devel go1.19-335569b598 Sat May 14 23:57:43 2022 +0000 darwin/arm64

Does this issue reproduce with the latest release?

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

go env Output

$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/yoshiki.shibata/Library/Caches/go-build"
GOENV="/Users/yoshiki.shibata/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/yoshiki.shibata/gocode/pkg/mod"
GONOPROXY="github.com/kouzoh/*"
GONOSUMDB="github.com/kouzoh/*"
GOOS="darwin"
GOPATH="/Users/yoshiki.shibata/gocode"
GOPRIVATE="github.com/kouzoh/*"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/yoshiki.shibata/tools/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/yoshiki.shibata/tools/go/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="devel go1.19-335569b598 Sat May 14 23:57:43 2022 +0000"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/5y/6k1nfy3n0sn9h4g61bp36wv40000gp/T/go-build870740369=/tmp/go-build -gno-record-gcc-switches -fno-common"
GOROOT/bin/go version: go version devel go1.19-335569b598 Sat May 14 23:57:43 2022 +0000 darwin/arm64
GOROOT/bin/go tool compile -V: compile version devel go1.19-335569b598 Sat May 14 23:57:43 2022 +0000
uname -v: Darwin Kernel Version 21.4.0: Fri Mar 18 00:47:26 PDT 2022; root:xnu-8020.101.4~15/RELEASE_ARM64_T8101
ProductName:	macOS
ProductVersion:	12.3.1
BuildVersion:	21E258
lldb --version: lldb-1316.0.9.41
Apple Swift version 5.6 (swiftlang-5.6.0.323.62 clang-1316.0.20.8)

What did you do?

Run src/all.bash

What did you expect to see?

No error

What did you see instead?

panic: test timed out after 9m0s

goroutine 1171342058 [running]:
panic({0x1006e50e0, 0x1400004a420})
	/Users/yoshiki.shibata/tools/go/src/runtime/panic.go:985 +0x3c0 fp=0x14000059f80 sp=0x14000059ec0 pc=0x100584070
testing.(*M).startAlarm.func1()
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:2036 +0x88 fp=0x14000059fd0 sp=0x14000059f80 pc=0x10061b428
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x14000059fd0 sp=0x14000059fd0 pc=0x1005b6184
created by time.goFunc
	/Users/yoshiki.shibata/tools/go/src/time/sleep.go:176 +0x38

goroutine 1 [chan receive, 8 minutes]:
runtime.gopark(0x10082f9c0?, 0x1009cc130?, 0x78?, 0x1a?, 0x10055bcfc?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x140000719f0 sp=0x140000719d0 pc=0x100586d44
runtime.chanrecv(0x14000362000, 0x14000071aff, 0x1)
	/Users/yoshiki.shibata/tools/go/src/runtime/chan.go:583 +0x454 fp=0x14000071a80 sp=0x140000719f0 pc=0x100555394
runtime.chanrecv1(0x1400005c8a0?, 0x1?)
	/Users/yoshiki.shibata/tools/go/src/runtime/chan.go:442 +0x14 fp=0x14000071ab0 sp=0x14000071a80 pc=0x100554f34
testing.(*T).Run(0x14000003520, {0x10069a880?, 0x1161ba9d083?}, 0x100712fc8)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1494 +0x314 fp=0x14000071b50 sp=0x14000071ab0 pc=0x1006188a4
testing.runTests.func1(0x0?)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1846 +0x70 fp=0x14000071ba0 sp=0x14000071b50 pc=0x10061a560
testing.tRunner(0x14000003520, 0x1400009dcb8)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1446 +0x10c fp=0x14000071bf0 sp=0x14000071ba0 pc=0x100617c0c
testing.runTests(0x1400007d0e0?, {0x1007fc040, 0x23, 0x23}, {0x8300000000000000?, 0x83d09a07655afa95?, 0x1007ff980?})
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1844 +0x3f0 fp=0x14000071ce0 sp=0x14000071bf0 pc=0x10061a420
testing.(*M).Run(0x1400007d0e0)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1726 +0x4f0 fp=0x14000071ee0 sp=0x14000071ce0 pc=0x1006191c0
main.main()
	_testmain.go:117 +0x1d0 fp=0x14000071f70 sp=0x14000071ee0 pc=0x1006929d0
runtime.main()
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:250 +0x24c fp=0x14000071fd0 sp=0x14000071f70 pc=0x10058697c
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x14000071fd0 sp=0x14000071fd0 pc=0x1005b6184

goroutine 2 [force gc (idle), 8 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x14000034fa0 sp=0x14000034f80 pc=0x100586d44
runtime.goparkunlock(...)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:369
runtime.forcegchelper()
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:302 +0xac fp=0x14000034fd0 sp=0x14000034fa0 pc=0x100586bdc
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x14000034fd0 sp=0x14000034fd0 pc=0x1005b6184
created by runtime.init.6
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:290 +0x24

goroutine 3 [runnable]:
runtime.Gosched(...)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:318
runtime.bgsweep(0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/mgcsweep.go:283 +0x14c fp=0x140000357b0 sp=0x14000035770 pc=0x1005728ec
runtime.gcenable.func1()
	/Users/yoshiki.shibata/tools/go/src/runtime/mgc.go:178 +0x28 fp=0x140000357d0 sp=0x140000357b0 pc=0x1005671b8
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x140000357d0 sp=0x140000357d0 pc=0x1005b6184
created by runtime.gcenable
	/Users/yoshiki.shibata/tools/go/src/runtime/mgc.go:178 +0x74

goroutine 4 [runnable]:
runtime.gopark(0x14000010050?, 0x1170763b86f?, 0x0?, 0x0?, 0x100712bd8?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x14000033700 sp=0x140000336e0 pc=0x100586d44
runtime.goparkunlock(...)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:369
runtime.(*scavengerState).sleep(0x1007ffa00, 0x412857ce00000000)
	/Users/yoshiki.shibata/tools/go/src/runtime/mgcscavenge.go:468 +0x134 fp=0x14000033780 sp=0x14000033700 pc=0x100570a34
runtime.bgscavenge(0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/mgcscavenge.go:626 +0x9c fp=0x140000337b0 sp=0x14000033780 pc=0x100570e2c
runtime.gcenable.func2()
	/Users/yoshiki.shibata/tools/go/src/runtime/mgc.go:179 +0x28 fp=0x140000337d0 sp=0x140000337b0 pc=0x100567158
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x140000337d0 sp=0x140000337d0 pc=0x1005b6184
created by runtime.gcenable
	/Users/yoshiki.shibata/tools/go/src/runtime/mgc.go:179 +0xb8

goroutine 5 [finalizer wait, 8 minutes]:
runtime.gopark(0x0?, 0x1400000d548?, 0x60?, 0xc1?, 0x1000000010?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x14000057d80 sp=0x14000057d60 pc=0x100586d44
runtime.goparkunlock(...)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:369
runtime.runfinq()
	/Users/yoshiki.shibata/tools/go/src/runtime/mfinal.go:180 +0x120 fp=0x14000057fd0 sp=0x14000057d80 pc=0x1005663e0
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x14000057fd0 sp=0x14000057fd0 pc=0x1005b6184
created by runtime.createfing
	/Users/yoshiki.shibata/tools/go/src/runtime/mfinal.go:157 +0x84

goroutine 284 [chan receive, 8 minutes]:
runtime.gopark(0x10082f9c0?, 0x1009cc130?, 0x28?, 0x5e?, 0x10055bcfc?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x14000055da0 sp=0x14000055d80 pc=0x100586d44
runtime.chanrecv(0x1400004c000, 0x14000055eaf, 0x1)
	/Users/yoshiki.shibata/tools/go/src/runtime/chan.go:583 +0x454 fp=0x14000055e30 sp=0x14000055da0 pc=0x100555394
runtime.chanrecv1(0x1400005c8a0?, 0x1?)
	/Users/yoshiki.shibata/tools/go/src/runtime/chan.go:442 +0x14 fp=0x14000055e60 sp=0x14000055e30 pc=0x100554f34
testing.(*T).Run(0x1400032a4e0, {0x1006965ef?, 0x14000331f48?}, 0x1400004a880)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1494 +0x314 fp=0x14000055f00 sp=0x14000055e60 pc=0x1006188a4
runtime/pprof.TestGoroutineProfileConcurrency(0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:1574 +0x204 fp=0x14000055f60 sp=0x14000055f00 pc=0x100684c24
testing.tRunner(0x1400032a4e0, 0x100712fc8)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1446 +0x10c fp=0x14000055fb0 sp=0x14000055f60 pc=0x100617c0c
testing.(*T).Run.func1()
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1493 +0x2c fp=0x14000055fd0 sp=0x14000055fb0 pc=0x10061894c
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x14000055fd0 sp=0x14000055fd0 pc=0x1005b6184
created by testing.(*T).Run
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1493 +0x300

goroutine 9 [GC worker (idle)]:
runtime.gopark(0x193d6165a1f?, 0x14000036648?, 0xa8?, 0x67?, 0x10061894c?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x14000036740 sp=0x14000036720 pc=0x100586d44
runtime.gcBgMarkWorker()
	/Users/yoshiki.shibata/tools/go/src/runtime/mgc.go:1233 +0xec fp=0x140000367d0 sp=0x14000036740 pc=0x10056958c
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x140000367d0 sp=0x140000367d0 pc=0x1005b6184
created by runtime.gcBgMarkStartWorkers
	/Users/yoshiki.shibata/tools/go/src/runtime/mgc.go:1157 +0x28

goroutine 96162 [runnable]:
runtime/pprof.TestGoroutineProfileConcurrency.func6.1()
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:1490 fp=0x1400030a7d0 sp=0x1400030a7d0 pc=0x1006856a0
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x1400030a7d0 sp=0x1400030a7d0 pc=0x1005b6184
created by runtime/pprof.TestGoroutineProfileConcurrency.func6
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:1490 +0x1a4

goroutine 96161 [semacquire, 8 minutes]:
runtime.gopark(0x100806940?, 0x10055bcfc?, 0xe0?, 0xd?, 0x30?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x1400030f510 sp=0x1400030f4f0 pc=0x100586d44
runtime.goparkunlock(...)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:369
runtime.semacquire1(0x140004bc568, 0x28?, 0x1, 0x0)
	/Users/yoshiki.shibata/tools/go/src/runtime/sema.go:144 +0x20c fp=0x1400030f570 sp=0x1400030f510 pc=0x10059837c
sync.runtime_Semacquire(0x14000003040?)
	/Users/yoshiki.shibata/tools/go/src/runtime/sema.go:56 +0x28 fp=0x1400030f5a0 sp=0x1400030f570 pc=0x1005b1f08
sync.(*WaitGroup).Wait(0x140004bc560)
	/Users/yoshiki.shibata/tools/go/src/sync/waitgroup.go:136 +0x80 fp=0x1400030f5c0 sp=0x1400030f5a0 pc=0x1005bd610
runtime/pprof.TestGoroutineProfileConcurrency.func6(0x1400032a820)
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:1534 +0x2a0 fp=0x1400030f760 sp=0x1400030f5c0 pc=0x100684f30
testing.tRunner(0x1400032a820, 0x1400004a880)
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1446 +0x10c fp=0x1400030f7b0 sp=0x1400030f760 pc=0x100617c0c
testing.(*T).Run.func1()
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1493 +0x2c fp=0x1400030f7d0 sp=0x1400030f7b0 pc=0x10061894c
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x1400030f7d0 sp=0x1400030f7d0 pc=0x1005b6184
created by testing.(*T).Run
	/Users/yoshiki.shibata/tools/go/src/testing/testing.go:1493 +0x300

goroutine 78 [chan send, 8 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/proc.go:363 +0xe4 fp=0x14000058ee0 sp=0x14000058ec0 pc=0x100586d44
runtime.chansend(0x1400035a060, 0x1006d16c8, 0x1, 0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/chan.go:259 +0x43c fp=0x14000058f70 sp=0x14000058ee0 pc=0x10055460c
runtime.chansend1(0x0?, 0x0?)
	/Users/yoshiki.shibata/tools/go/src/runtime/chan.go:145 +0x18 fp=0x14000058fa0 sp=0x14000058f70 pc=0x1005541b8
runtime/pprof.TestMorestack.func1.1()
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:778 +0x34 fp=0x14000058fd0 sp=0x14000058fa0 pc=0x1006806d4
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x14000058fd0 sp=0x14000058fd0 pc=0x1005b6184
created by runtime/pprof.TestMorestack.func1
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:776 +0x84

goroutine 1171342057 [runnable]:
runtime/pprof.TestGoroutineProfileConcurrency.func6.2.1()
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:1527 fp=0x1400030d7d0 sp=0x1400030d7d0 pc=0x100685630
runtime.goexit()
	/Users/yoshiki.shibata/tools/go/src/runtime/asm_arm64.s:1155 +0x4 fp=0x1400030d7d0 sp=0x1400030d7d0 pc=0x1005b6184
created by runtime/pprof.TestGoroutineProfileConcurrency.func6.2
	/Users/yoshiki.shibata/tools/go/src/runtime/pprof/pprof_test.go:1527 +0x270
FAIL	runtime/pprof	540.815s

[rhysh]

I can reproduce this by running the test with -cpu=1 / GOMAXPROCS=1, and not otherwise (hinted by the crash dump including only one runtime.gcBgMarkWorker goroutine). The churn goroutine is crowding out the loop goroutine—it's not even to the point that the goroutine profiler has started trying to run.

It's easy to fix the test (have the churn goroutine call Gosched on occasion), and the broken part has nothing to do with whether the app is trying to collect a goroutine profile. I'll send a CL (sometime soon).

I wonder though if there's a runtime Quality-of-Implementation problem with allowing new goroutine launches to crowd out other work so effectively. (If that's in fact what's going on.)

Thank you for the report!

[YoshikiShibata]

@rhysh As you pointed out, I ran it with GOMAXPROCS=1

[bcmills]

I wonder though if there's a runtime Quality-of-Implementation problem with allowing new goroutine launches to crowd out other work so effectively. (If that's in fact what's going on.)

(CC @golang/runtime)

[gopherbot]

Change https://go.dev/cl/406654 mentions this issue: runtime/pprof: slow new goroutine launches in test

[YoshikiShibata]

@rhysh This problem is happening again.

$ go version
go version devel go1.19-dbf5220475 Thu May 26 21:06:31 2022 +0000 darwin/arm64

[rhysh]

Can you give more detail on the steps to reproduce, and the output you see when it fails? I'm no longer able to reproduce this on my machine.

$ go version
go version devel go1.19-dbf5220475 Thu May 26 21:06:31 2022 +0000 darwin/arm64
$ for i in {1..10}; do go test runtime/pprof -run=TestGoroutineProfileConcurrency -cpu=1 -count=1 -timeout=10s; done
ok  	runtime/pprof	0.351s
ok  	runtime/pprof	0.226s
ok  	runtime/pprof	0.236s
ok  	runtime/pprof	0.226s
ok  	runtime/pprof	0.237s
ok  	runtime/pprof	0.224s
ok  	runtime/pprof	0.241s
ok  	runtime/pprof	0.187s
ok  	runtime/pprof	0.222s
ok  	runtime/pprof	0.227s