Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: hangs in TestGdbAutotmpTypes with various GOMAXPROCS on ppc64le; setting GOEXPERIMENT=nopacerredesign avoids the hangs #49852

Open
laboger opened this issue Nov 29, 2021 · 13 comments
Assignees
Milestone

Comments

@laboger
Copy link
Contributor

@laboger laboger commented Nov 29, 2021

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

$ go version
tip

Does this issue reproduce with the latest release?

Does not fail on go 1.17

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

Different ppc64le systems; it fails on power8 ubuntu, power9 rhel8, and a power10 (debian I think).
Behavior described below is the same on all systems.

What did you do?

We have seen intermittent hangs in the runtime tests on various machines. When tracking it down I found it was hanging in TestGdbAutotmpTypes.

On my power9 RH8 I can make it hang consistently with this:
go test -c
export GOMAXPROCS=64
./runtime.test -test.run=TestGdbAutotmpTypes -test.cpu=1 -test.count=10
If I set GOEXPERIMENT=nopacerredesign it doesn't hang.
It doesn't consistently hang if count=1.
It doesn't seem to hang with GOMAXPROCS=2 but didn't try many experiments.
It does not hang on go 1.17.

What did you expect to see?

PASS

What did you see instead?

Test hangs, and viewing the processes shows it is trying to run TestGdbAutotmpTypes.

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Nov 30, 2021

This is likely a test that assumes a GC won't run, but then it does and breaks the test. We've run into and fixed many such tests at this point in the release cycle.

I can look into it, but my guess is this is a test-only failure with pretty low severity.

@mknyszek mknyszek self-assigned this Nov 30, 2021
@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Nov 30, 2021

Also, since it hangs it should be straightforward to send it a SIGABRT and see where it's stuck. If you're able to do this easily, could you please share the resulting stack trace? That would save me some time! Thanks.

@laboger
Copy link
Contributor Author

@laboger laboger commented Nov 30, 2021

I used GOMAXPROCS=32

Does not hang for GOMAXPROCS<=16

[boger@trout runtime]$ ./runtime.test -test.run=TestGdbAutotmp -test.v -test.count=4
=== RUN   TestGdbAutotmpTypes
=== PAUSE TestGdbAutotmpTypes
=== CONT  TestGdbAutotmpTypes
    runtime-gdb_test.go:76: gdb version 8.2
SIGABRT: abort
PC=0x85ecc m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex()
	/home/boger/golang/work/go/src/runtime/sys_linux_ppc64x.s:793 +0x1c fp=0x7ffff1a1fbe0 sp=0x7ffff1a1fbe0 pc=0x85ecc
runtime.futexsleep(0x59ec4?, 0x3f6c80?, 0xc000040000?)
	/home/boger/golang/work/go/src/runtime/os_linux.go:56 +0x30 fp=0x7ffff1a1fc40 sp=0x7ffff1a1fbe0 pc=0x48010
runtime.notesleep(0x3f6dd0)
	/home/boger/golang/work/go/src/runtime/lock_futex.go:159 +0xc0 fp=0x7ffff1a1fc88 sp=0x7ffff1a1fc40 pc=0x1cef0
runtime.mPark()
	/home/boger/golang/work/go/src/runtime/proc.go:1433 +0x20 fp=0x7ffff1a1fcb8 sp=0x7ffff1a1fc88 pc=0x51340
runtime.stoplockedm()
	/home/boger/golang/work/go/src/runtime/proc.go:2597 +0x64 fp=0x7ffff1a1fd18 sp=0x7ffff1a1fcb8 pc=0x53494
runtime.schedule()
	/home/boger/golang/work/go/src/runtime/proc.go:3294 +0x48 fp=0x7ffff1a1fd70 sp=0x7ffff1a1fd18 pc=0x555b8
runtime.park_m(0xc0000021a0?)
	/home/boger/golang/work/go/src/runtime/proc.go:3511 +0x160 fp=0x7ffff1a1fdb0 sp=0x7ffff1a1fd70 pc=0x55e00
runtime.mcall()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:198 +0x54 fp=0x7ffff1a1fdd8 sp=0x7ffff1a1fdb0 pc=0x82064

goroutine 1 [chan receive, 6 minutes, locked to thread]:
runtime.gopark(0xc00001c480?, 0x4e9bc?, 0x38?, 0x7b?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00011f870 sp=0xc00011f840 pc=0x4e938
runtime.chanrecv(0xc0000fa150, 0x0, 0x1)
	/home/boger/golang/work/go/src/runtime/chan.go:577 +0x674 fp=0xc00011f910 sp=0xc00011f870 pc=0x18654
runtime.chanrecv1(0xc000026240?, 0xf42bc?)
	/home/boger/golang/work/go/src/runtime/chan.go:440 +0x10 fp=0xc00011f948 sp=0xc00011f910 pc=0x17fa0
testing.tRunner.func1()
	/home/boger/golang/work/go/src/testing/testing.go:1376 +0x500 fp=0xc00011fac8 sp=0xc00011f948 pc=0xf3b70
testing.tRunner(0xc000183380, 0xc00011fc08)
	/home/boger/golang/work/go/src/testing/testing.go:1416 +0x160 fp=0xc00011fb28 sp=0xc00011fac8 pc=0xf35f0
testing.runTests(0xc0000e43c0?, {0x3f2ba0, 0x173, 0x173}, {0x38?, 0x7fffa1830108?, 0x0?})
	/home/boger/golang/work/go/src/testing/testing.go:1808 +0x438 fp=0xc00011fc28 sp=0xc00011fb28 pc=0xf5f98
testing.(*M).Run(0xc0000e43c0)
	/home/boger/golang/work/go/src/testing/testing.go:1690 +0x558 fp=0xc00011fe30 sp=0xc00011fc28 pc=0xf4be8
runtime_test.TestMain(0xc0000021a0?)
	/home/boger/golang/work/go/src/runtime/crash_test.go:28 +0x2c fp=0xc00011fe80 sp=0xc00011fe30 pc=0x16d61c
main.main()
	_testmain.go:1295 +0x1ac fp=0xc00011ff50 sp=0xc00011fe80 pc=0x1eb3fc
runtime.main()
	/home/boger/golang/work/go/src/runtime/proc.go:255 +0x280 fp=0xc00011ffc0 sp=0xc00011ff50 pc=0x4e4e0
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00011ffc0 sp=0xc00011ffc0 pc=0x84b14

goroutine 2 [force gc (idle), 2 minutes]:
runtime.gopark(0x451df77de0e2e?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008af80 sp=0xc00008af50 pc=0x4e938
runtime.goparkunlock(...)
	/home/boger/golang/work/go/src/runtime/proc.go:372
runtime.forcegchelper()
	/home/boger/golang/work/go/src/runtime/proc.go:306 +0xc8 fp=0xc00008afc0 sp=0xc00008af80 pc=0x4e7a8
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008afc0 sp=0xc00008afc0 pc=0x84b14
created by runtime.init.5
	/home/boger/golang/work/go/src/runtime/proc.go:294 +0x2c

goroutine 3 [GC sweep wait]:
runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008b750 sp=0xc00008b720 pc=0x4e938
runtime.goparkunlock(...)
	/home/boger/golang/work/go/src/runtime/proc.go:372
runtime.bgsweep(0x0?)
	/home/boger/golang/work/go/src/runtime/mgcsweep.go:297 +0x12c fp=0xc00008b798 sp=0xc00008b750 pc=0x390ec
runtime.gcenable.func1()
	/home/boger/golang/work/go/src/runtime/mgc.go:177 +0x4c fp=0xc00008b7c0 sp=0xc00008b798 pc=0x2de7c
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008b7c0 sp=0xc00008b7c0 pc=0x84b14
created by runtime.gcenable
	/home/boger/golang/work/go/src/runtime/mgc.go:177 +0x7c

goroutine 4 [GC scavenge wait]:
runtime.gopark(0x451df77f707fb?, 0x10000?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00009aee0 sp=0xc00009aeb0 pc=0x4e938
runtime.goparkunlock(...)
	/home/boger/golang/work/go/src/runtime/proc.go:372
runtime.bgscavenge(0x0?)
	/home/boger/golang/work/go/src/runtime/mgcscavenge.go:357 +0x2a8 fp=0xc00009af98 sp=0xc00009aee0 pc=0x36e68
runtime.gcenable.func2()
	/home/boger/golang/work/go/src/runtime/mgc.go:178 +0x4c fp=0xc00009afc0 sp=0xc00009af98 pc=0x2de1c
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00009afc0 sp=0xc00009afc0 pc=0x84b14
created by runtime.gcenable
	/home/boger/golang/work/go/src/runtime/mgc.go:178 +0xc4

goroutine 5 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x208d20?, 0x80?, 0x6c?, 0x84b14?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008a718 sp=0xc00008a6e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00008a7c0 sp=0xc00008a718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008a7c0 sp=0xc00008a7c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 18 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000086718 sp=0xc0000866e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0000867c0 sp=0xc000086718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0000867c0 sp=0xc0000867c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 19 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000086f18 sp=0xc000086ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000086fc0 sp=0xc000086f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000086fc0 sp=0xc000086fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 34 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000112718 sp=0xc0001126e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0001127c0 sp=0xc000112718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0001127c0 sp=0xc0001127c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 20 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000087718 sp=0xc0000876e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0000877c0 sp=0xc000087718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0000877c0 sp=0xc0000877c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 35 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000112f18 sp=0xc000112ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000112fc0 sp=0xc000112f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000112fc0 sp=0xc000112fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 21 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000087f18 sp=0xc000087ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000087fc0 sp=0xc000087f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000087fc0 sp=0xc000087fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 36 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000113718 sp=0xc0001136e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0001137c0 sp=0xc000113718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0001137c0 sp=0xc0001137c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 37 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000113f18 sp=0xc000113ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000113fc0 sp=0xc000113f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000113fc0 sp=0xc000113fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 38 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000114718 sp=0xc0001146e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0001147c0 sp=0xc000114718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0001147c0 sp=0xc0001147c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 39 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000114f18 sp=0xc000114ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000114fc0 sp=0xc000114f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000114fc0 sp=0xc000114fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 40 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000115718 sp=0xc0001156e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0001157c0 sp=0xc000115718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0001157c0 sp=0xc0001157c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 41 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000115f18 sp=0xc000115ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000115fc0 sp=0xc000115f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000115fc0 sp=0xc000115fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 42 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00010e718 sp=0xc00010e6e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00010e7c0 sp=0xc00010e718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00010e7c0 sp=0xc00010e7c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 6 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008c718 sp=0xc00008c6e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00008c7c0 sp=0xc00008c718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008c7c0 sp=0xc00008c7c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 50 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000206718 sp=0xc0002066e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0002067c0 sp=0xc000206718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0002067c0 sp=0xc0002067c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 51 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000206f18 sp=0xc000206ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000206fc0 sp=0xc000206f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000206fc0 sp=0xc000206fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 7 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008cf18 sp=0xc00008cee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00008cfc0 sp=0xc00008cf18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008cfc0 sp=0xc00008cfc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 22 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000088718 sp=0xc0000886e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0000887c0 sp=0xc000088718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0000887c0 sp=0xc0000887c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 52 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000207718 sp=0xc0002076e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0002077c0 sp=0xc000207718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0002077c0 sp=0xc0002077c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 43 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00010ef18 sp=0xc00010eee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00010efc0 sp=0xc00010ef18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00010efc0 sp=0xc00010efc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 44 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00010f718 sp=0xc00010f6e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00010f7c0 sp=0xc00010f718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00010f7c0 sp=0xc00010f7c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 8 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008d718 sp=0xc00008d6e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00008d7c0 sp=0xc00008d718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008d7c0 sp=0xc00008d7c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 9 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00008df18 sp=0xc00008dee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc00008dfc0 sp=0xc00008df18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00008dfc0 sp=0xc00008dfc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 10 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000202718 sp=0xc0002026e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0002027c0 sp=0xc000202718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0002027c0 sp=0xc0002027c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 11 [GC worker (idle), 6 minutes]:
runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000202f18 sp=0xc000202ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000202fc0 sp=0xc000202f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000202fc0 sp=0xc000202fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 12 [GC worker (idle)]:
runtime.gopark(0x451df77e4b29e?, 0x0?, 0x0?, 0x0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000203718 sp=0xc0002036e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0002037c0 sp=0xc000203718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0002037c0 sp=0xc0002037c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 13 [GC worker (idle)]:
runtime.gopark(0x451df77e37b5f?, 0x3?, 0x87?, 0x43?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000203f18 sp=0xc000203ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000203fc0 sp=0xc000203f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000203fc0 sp=0xc000203fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 14 [GC worker (idle), 2 minutes]:
runtime.gopark(0x42bf20?, 0x1?, 0x46?, 0x14?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000204718 sp=0xc0002046e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0002047c0 sp=0xc000204718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0002047c0 sp=0xc0002047c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 15 [GC worker (idle), 2 minutes]:
runtime.gopark(0x42bf20?, 0x1?, 0x38?, 0xa0?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000098f18 sp=0xc000098ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000098fc0 sp=0xc000098f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000098fc0 sp=0xc000098fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 16 [GC worker (idle)]:
runtime.gopark(0x42bf20?, 0x1?, 0xe2?, 0xeb?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000205718 sp=0xc0002056e8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc0002057c0 sp=0xc000205718 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0002057c0 sp=0xc0002057c0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 66 [GC worker (idle)]:
runtime.gopark(0x451df77e361b5?, 0x3?, 0xff?, 0x8a?, 0x0?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc000205f18 sp=0xc000205ee8 pc=0x4e938
runtime.gcBgMarkWorker()
	/home/boger/golang/work/go/src/runtime/mgc.go:1198 +0x104 fp=0xc000205fc0 sp=0xc000205f18 pc=0x302b4
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc000205fc0 sp=0xc000205fc0 pc=0x84b14
created by runtime.gcBgMarkStartWorkers
	/home/boger/golang/work/go/src/runtime/mgc.go:1122 +0x30

goroutine 67 [finalizer wait, 4 minutes]:
runtime.gopark(0x0?, 0x2700f8?, 0x0?, 0x0?, 0x1000000010?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc00009bdd8 sp=0xc00009bda8 pc=0x4e938
runtime.goparkunlock(...)
	/home/boger/golang/work/go/src/runtime/proc.go:372
runtime.runfinq()
	/home/boger/golang/work/go/src/runtime/mfinal.go:177 +0xd4 fp=0xc00009bfc0 sp=0xc00009bdd8 pc=0x2cf54
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00009bfc0 sp=0xc00009bfc0 pc=0x84b14
created by runtime.createfing
	/home/boger/golang/work/go/src/runtime/mfinal.go:157 +0x78

goroutine 68 [syscall, 6 minutes]:
syscall.Syscall6(0x110, 0x1, 0x145bd5, 0xc00011b920, 0x1000004, 0x0, 0x0)
	/home/boger/golang/work/go/src/syscall/asm_linux_ppc64x.s:39 +0xc fp=0xc00011b8b0 sp=0xc00011b890 pc=0x945bc
os.(*Process).blockUntilWaitable(0xc000020270)
	/home/boger/golang/work/go/src/os/wait_waitid.go:32 +0xa0 fp=0xc00011b9b0 sp=0xc00011b8b0 pc=0xb0f10
os.(*Process).wait(0xc000020270)
	/home/boger/golang/work/go/src/os/exec_unix.go:22 +0x3c fp=0xc00011ba30 sp=0xc00011b9b0 pc=0xac0ac
os.(*Process).Wait(...)
	/home/boger/golang/work/go/src/os/exec.go:132
os/exec.(*Cmd).Wait(0xc000380000)
	/home/boger/golang/work/go/src/os/exec/exec.go:507 +0x64 fp=0xc00011bad8 sp=0xc00011ba30 pc=0xfde44
os/exec.(*Cmd).Run(0xc00011be40?)
	/home/boger/golang/work/go/src/os/exec/exec.go:341 +0x50 fp=0xc00011bb08 sp=0xc00011bad8 pc=0xfd170
os/exec.(*Cmd).CombinedOutput(0xc000380000)
	/home/boger/golang/work/go/src/os/exec/exec.go:567 +0xb8 fp=0xc00011bb60 sp=0xc00011bb08 pc=0xfe1a8
runtime_test.TestGdbAutotmpTypes(0xc000183520)
	/home/boger/golang/work/go/src/runtime/runtime-gdb_test.go:501 +0x498 fp=0xc00011bf30 sp=0xc00011bb60 pc=0x1d12e8
testing.tRunner(0xc000183520, 0x271788)
	/home/boger/golang/work/go/src/testing/testing.go:1410 +0x11c fp=0xc00011bf90 sp=0xc00011bf30 pc=0xf35ac
testing.(*T).Run.func1()
	/home/boger/golang/work/go/src/testing/testing.go:1457 +0x50 fp=0xc00011bfc0 sp=0xc00011bf90 pc=0xf4370
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc00011bfc0 sp=0xc00011bfc0 pc=0x84b14
created by testing.(*T).Run
	/home/boger/golang/work/go/src/testing/testing.go:1457 +0x36c

goroutine 69 [IO wait, 6 minutes]:
runtime.gopark(0x9453c?, 0x0?, 0x60?, 0x38?, 0x200000003?)
	/home/boger/golang/work/go/src/runtime/proc.go:366 +0x118 fp=0xc0001b9be8 sp=0xc0001b9bb8 pc=0x4e938
runtime.netpollblock(0x7fffa1830378?, 0xa7d90?, 0x0?)
	/home/boger/golang/work/go/src/runtime/netpoll.go:453 +0x184 fp=0xc0001b9c30 sp=0xc0001b9be8 pc=0x473c4
internal/poll.runtime_pollWait(0x7fff780b4528, 0x72)
	/home/boger/golang/work/go/src/runtime/netpoll.go:233 +0xdc fp=0xc0001b9c68 sp=0xc0001b9c30 pc=0x7f8bc
internal/poll.(*pollDesc).wait(0xc000000240?, 0xc00038a153?, 0x1)
	/home/boger/golang/work/go/src/internal/poll/fd_poll_runtime.go:83 +0x4c fp=0xc0001b9cc0 sp=0xc0001b9c68 pc=0xa719c
internal/poll.(*pollDesc).waitRead(...)
	/home/boger/golang/work/go/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0xc000000240, {0xc00038a153, 0x4ad, 0x4ad})
	/home/boger/golang/work/go/src/internal/poll/fd_unix.go:167 +0x258 fp=0xc0001b9d50 sp=0xc0001b9cc0 pc=0xa7d68
os.(*File).read(...)
	/home/boger/golang/work/go/src/os/file_posix.go:31
os.(*File).Read(0xc000010030, {0xc00038a153?, 0x0?, 0x0?})
	/home/boger/golang/work/go/src/os/file.go:119 +0x8c fp=0xc0001b9dc8 sp=0xc0001b9d50 pc=0xac6fc
bytes.(*Buffer).ReadFrom(0xc0000c8990, {0x2b2b50, 0xc000010030})
	/home/boger/golang/work/go/src/bytes/buffer.go:204 +0xb8 fp=0xc0001b9e30 sp=0xc0001b9dc8 pc=0xdf6e8
io.copyBuffer({0x2b2910, 0xc0000c8990}, {0x2b2b50, 0xc000010030}, {0x0, 0x0, 0x0})
	/home/boger/golang/work/go/src/io/io.go:412 +0x160 fp=0xc0001b9ee0 sp=0xc0001b9e30 pc=0xa3f90
io.Copy(...)
	/home/boger/golang/work/go/src/io/io.go:385
os/exec.(*Cmd).writerDescriptor.func1()
	/home/boger/golang/work/go/src/os/exec/exec.go:311 +0x4c fp=0xc0001b9f50 sp=0xc0001b9ee0 pc=0xfd0dc
os/exec.(*Cmd).Start.func1(0x0?)
	/home/boger/golang/work/go/src/os/exec/exec.go:441 +0x40 fp=0xc0001b9f98 sp=0xc0001b9f50 pc=0xfdd70
os/exec.(*Cmd).Start.func3()
	/home/boger/golang/work/go/src/os/exec/exec.go:442 +0x58 fp=0xc0001b9fc0 sp=0xc0001b9f98 pc=0xfdd18
runtime.goexit()
	/home/boger/golang/work/go/src/runtime/asm_ppc64x.s:905 +0x4 fp=0xc0001b9fc0 sp=0xc0001b9fc0 pc=0x84b14
created by os/exec.(*Cmd).Start
	/home/boger/golang/work/go/src/os/exec/exec.go:440 +0x7a8

r0   0xdd	r1   0x7ffff1a1fbe0
r2   0x0	r3   0x3f6dd0
r4   0x80	r5   0x0
r6   0x0	r7   0x0
r8   0x0	r9   0x0
r10  0x0	r11  0x0
r12  0x0	r13  0x7fffa1b7a920
r14  0xc0000fa190	r15  0x0
r16  0x0	r17  0x25bc23
r18  0x11	r19  0x4000
r20  0xc0000022e8	r21  0x0
r22  0x7ffff1221160	r23  0xc00011f8f0
r24  0x18	r25  0x20
r26  0x25b2ee	r27  0x25b2e0
r28  0xffffffffffffffff	r29  0x26fa35
r30  0x3f68a0	r31  0x1cef0
pc   0x85ecc	ctr  0x0
link 0x48010	xer  0x0
ccr  0x54448884	trap 0xc00
[boger@trout runtime]$ 

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Nov 30, 2021

Ugh. It looks like it's blocking on a child process that is the actual culprit.

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Dec 2, 2021

I can't trivially reproduce this myself because we're missing gdb on the linux-ppc64le-buildlet gomotes. I tried to install via apt but apt-get install apparently has some broken links and apt-get update fails saying that I need to explicitly opt-in to something (probably for good reason).

This may be why we haven't seen this failure on the builders.

I have a CL out to roll back the heap minimum, https://golang.org/cl/368137, could you try that out and let me know if it helps?

Given the program that's executing I'm very surprised that the GC is executing at all (I mean it must be if the pacer changes are to blame in any way), but maybe there's more to this than meets the eye.

My next steps to getting to the bottom of this are to introduce a line like go runtime.GC() at the beginning of main in autotmpTypeSource, then building the test with GOEXPERIMENT=nopacerredesign. If that hangs then we know it's for sure something weird with the test. This could also be something weird about the platform gdb not being able to cope with a GC executing in the context of all these specific commands.

@pmur
Copy link
Contributor

@pmur pmur commented Dec 2, 2021

I took a look to understand why the child is deadlocking. The gdb process is waiting (in the poll syscall) for the parent to read it's stdout pipe. It looks like the goroutine responsible for reading the pipe is halted for GC.

@laboger
Copy link
Contributor Author

@laboger laboger commented Dec 2, 2021

This runtime test no longer hangs with CL 368137 under the same conditions as reported above.

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Dec 2, 2021

Alrighty, good to know. We should still understand why the test is failing. Either a GC really isn't allowed here so we should figure out how best to disable a GC in the child, or we fix the test to tolerate additional GC cycles.

@pmur
Copy link
Contributor

@pmur pmur commented Dec 2, 2021

I suspect I am missing some details, but how do we generically avoid deadlocks like those when using the (*cmd).CombinedOutput? If I understand it correctly, this method implicitly creates a goroutine to slurp up stdout/stderr from the child via a pipe, and then parks itself in a blocking wait syscall.

If a GC halts the slurping goroutine, and then the child blocks waiting on the other end of the pipe to slurp, and then the GC is waiting to halt the goroutine stuck in the wait syscall, we are deadlocked. How do we avoid this?

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Dec 2, 2021

Goroutines that block in syscalls can be scanned by the GC without issue, generally speaking. The GC grabs the goroutine by setting its Gscan bit in its status, and upon exiting the syscall the goroutine tries to reacquire its own status, spinning until the GC is done with it.

There have been some subtle deadlocks around this code before, but if this was a problem with even a small fraction of CombinedOutput calls I think we'd be seeing a lot more failures (on other platforms too). This seems specific to the gdb environment.

@mknyszek
Copy link
Contributor

@mknyszek mknyszek commented Dec 3, 2021

This is effectively mitigated for this release since https://golang.org/cl/368137 went in, so I don't think it should be marked a release blocker anymore. We've basically confirmed that it's not a new bug in the release because we know the difference is that a GC was happening during this test somewhere where it wasn't happening before (which in theory should not change anything -- the rest of the GC has had very few changes this cycle).

We should still keep this open, and I intend to continue investigating, but this is going to be lower priority for me.

If you want to reproduce now, you'll have to also specify GOEXPERIMENT=heapminimum512kib.

@mknyszek mknyszek removed this from the Go1.18 milestone Dec 3, 2021
@mknyszek mknyszek added this to the Go1.19 milestone Dec 3, 2021
@pmur
Copy link
Contributor

@pmur pmur commented Dec 9, 2021

Take another look at this one, I see a different behavior now. The gdb command starts, hit the breakpoint main.main and hangs waiting for the step command to complete. Looking at the inferior state when this happens, n-1 of the threads are stuck in the tracing state.

I wonder if gdb is halting the other threads while executing the step, and we happen to get preempted with a GC operation.

@gopherbot
Copy link

@gopherbot gopherbot commented Dec 9, 2021

Change https://golang.org/cl/370775 mentions this issue: runtime: avoid potential hang in TestGdbAutotmpTypes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants