Skip to content

runtime: all.bash intermittent hang running test for issue 19182 #23560

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.

Sign up for GitHub

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

Jump to bottom
Closed
jasonphi opened this issue Jan 26, 2018 · 6 comments
Closed

runtime: all.bash intermittent hang running test for issue 19182 #23560

jasonphi opened this issue Jan 26, 2018 · 6 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.10

Comments

@jasonphi
Copy link

Please answer these questions before submitting your issue. Thanks!

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

go1.10rc1

Does this issue reproduce with the latest release?

Yes, assuming go1.10rc1 is considered the latest release

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/jphillips/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/jphillips/go"
GORACE=""
GOROOT="/home/jphillips/devel/go"
GOTMPDIR=""
GOTOOLDIR="/home/jphillips/devel/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build514735573=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I ran all.bash after checking out the go1.10rc1 tag.

What did you expect to see?

all.bash complete successfully

What did you see instead?

all.bash hung on the issue19182 test for ~5 minutes before I killed it. During that time the issue19182 process was taking up ~100% CPU in "top".

Running all.bash a second time ran to completion.

Below is the SIGQUIT dump from killing all.bash:

##### ../test/bench/go1
testing: warning: no tests to run
PASS
ok  	_/home/jphillips/devel/go/test/bench/go1	2.515s

##### ../test
^\SIGQUIT: quit
PC=0x4541b1SIGQUIT: quit m=
0PC= sigcode=0x47b128128 m=
0
 sigcode=goroutine 1280
 [
idle]:
goroutine 1 [syscall]:
runtime.futex(0x6205a8, 0x0, 0x0, 0x0, 0x7ffe00000000, 0x0, 0x0, 0x0, 0x7ffee31f07f8syscall.Syscall6, (0x40de8b0xf7, ..., )
0x1	, /home/jphillips/devel/go/src/runtime/sys_linux_amd64.s0x6a1e:, 5260xc4201afb08 +, 0x210x1000004
, 0x0, runtime.futexsleep0x0(, 0x6205a80x0, , 0x00xb06320, , 0xffffffffffffffff0xc4200b7380)
)
		/home/jphillips/devel/go/src/runtime/os_linux.go/home/jphillips/devel/go/src/syscall/asm_linux_amd64.s::4544 + +0x4b0x5
 fp=0xc4201afab0 sp=runtime.notesleep0xc4201afaa8( pc=0x6205a80x47b105)

	/home/jphillips/devel/go/src/runtime/lock_futex.go:151os.(*Process).blockUntilWaitable +(0x9b0xc4200b0b70
, 0x0, 0x0, 0x4runtime.stopm)
(	)
/home/jphillips/devel/go/src/os/wait_waitid.go	:/home/jphillips/devel/go/src/runtime/proc.go31: +19470x98 + fp=0xe50xc4201afbb0
 sp=0xc4201afab0 pc=0x49d3f8
os.(*Process).waitruntime.findrunnable((0xc4200b0b700xc420031400, , 0xc4200be0200x0, )
0xc4200d4a78	, /home/jphillips/devel/go/src/runtime/proc.go0xc4200d4a78:)
2410	 +/home/jphillips/devel/go/src/os/exec_unix.go0x50c:
22 +0x3c fp=0xc4201afc28 sp=runtime.schedule0xc4201afbb0( pc=)
0x49674c	
/home/jphillips/devel/go/src/runtime/proc.go:2536os.(*Process).Wait +(0x13b0xc4200b0b70
, 0x8d5100, runtime.park_m0x8d5108(, 0xc4201836800x8d50f8)
)
		/home/jphillips/devel/go/src/runtime/proc.go/home/jphillips/devel/go/src/os/exec.go::2599118 + +0xb60x2b
 fp=runtime.mcall0xc4201afc58( sp=0x00xc4201afc28)
 pc=	0x495cfb/home/jphillips/devel/go/src/runtime/asm_amd64.s
:351 +0x5bos/exec.(*Cmd).Wait
(
0xc4200d49a0goroutine , 10x0 [, chan receive0x0, )
5	 minutes/home/jphillips/devel/go/src/os/exec/exec.go]:
:456 +0x5c fp=0xc4201afcd0main.(*tester).runPending sp=(0xc4201afc580xc4200a00a0 pc=, 0x4f3c5c0x0
)
	/home/jphillips/devel/go/src/cmd/dist/test.goos/exec.(*Cmd).Run:(10980xc4200d49a0 +, 0x3310xc4200d49a0
, 0x1)
main.(*tester).run	(/home/jphillips/devel/go/src/os/exec/exec.go0xc4200a00a0:)
300	 +/home/jphillips/devel/go/src/cmd/dist/test.go0x5c: fp=2060xc4201afcf8 + sp=0xa1d0xc4201afcd0
 pc=0x4f313cmain.cmdtest
()
	/home/jphillips/devel/go/src/cmd/dist/test.gocmd/go/internal/tool.runTool:(450xafc6c0 +, 0x2f70xc4200be020
, main.xmain0x4(, )
0x4	)
/home/jphillips/devel/go/src/cmd/dist/main.go	:/home/jphillips/devel/go/src/cmd/go/internal/tool/tool.go178: +780x116 +
0x522 fp=main.main0xc4201afe20( sp=)
0xc4201afcf8	 pc=/home/jphillips/devel/go/src/cmd/dist/main.go0x7c4d22:
161 +0x23f
main.main
(goroutine )
6	 [/home/jphillips/devel/go/src/cmd/go/main.goselect:, 1405 + minutes0x7e1]:
 fp=0xc4201aff88 sp=main.bghelper0xc4201afe20( pc=)
0x7c79e1	
/home/jphillips/devel/go/src/cmd/dist/util.go:138 +0x107runtime.main
(created by )
main.bginit	
/home/jphillips/devel/go/src/runtime/proc.go	:/home/jphillips/devel/go/src/cmd/dist/util.go198: +1310x212 + fp=0x5a0xc4201affe0
 sp=
0xc4201aff88goroutine  pc=70x42cbd2 [
select, 5runtime.goexit minutes(]:
)
	main.bghelper/home/jphillips/devel/go/src/runtime/asm_amd64.s(:)
2361	 +/home/jphillips/devel/go/src/cmd/dist/util.go0x1: fp=1380xc4201affe8 + sp=0x1070xc4201affe0
 pc=0x4579c1created by 
main.bginit
	
/home/jphillips/devel/go/src/cmd/dist/util.gogoroutine :19131 [ +syscall0x5a]:


goroutine 8 [selectos/signal.signal_recv, (50x0 minutes)
]:
	/home/jphillips/devel/go/src/runtime/sigqueue.go:main.bghelper139( +)
0xa6	
/home/jphillips/devel/go/src/cmd/dist/util.go:138 +0x107
created by main.bginitos/signal.loop
(	)
/home/jphillips/devel/go/src/cmd/dist/util.go	:/home/jphillips/devel/go/src/os/signal/signal_unix.go131: +220x5a +
0x22

goroutine created by 9os/signal.init.0 [
select	, /home/jphillips/devel/go/src/os/signal/signal_unix.go5: minutes28]:
 +0x41main.bghelper
(
)
rax    	0xf7/home/jphillips/devel/go/src/cmd/dist/util.go
:rbx    1380x0 +
0x107rcx    
0x47b12acreated by 
main.bginitrdx    
0xc4201afb08	
/home/jphillips/devel/go/src/cmd/dist/util.gordi    :0x1131
 +rsi    0x5a0x6a1e


rbp    goroutine 0xc4201afba0155
 [rsp    syscall0xc4201afaa8, 
5r8      minutes0x0]:

r9     0x0syscall.Syscall6
(r10    0xf70x1000004, 
0x1r11    , 0x2160x5075
, r12    0xc420284d680xffffffffffffffff, 
0x1000004r13    , 0x70x0
, r14    0x00x6, 
0x0r15    , 0x550xc420180000
, rip    0x00x47b128)

	rflags /home/jphillips/devel/go/src/syscall/asm_linux_amd64.s0x216:
44cs      +0x330x5

fs     0x0
os.(*Process).blockUntilWaitablegs     (0x00xc42001ae10
, 0x0, 0x0, 0x3)
	/home/jphillips/devel/go/src/os/wait_waitid.go:31 +0x98
os.(*Process).wait(0xc42001ae10, 0xc4203121b0, 0xc420178918, 0xc420178918)
	/home/jphillips/devel/go/src/os/exec_unix.go:22 +0x3c
os.(*Process).Wait(0xc42001ae10, 0x56add0, 0x56add8, 0x56adc8)
	/home/jphillips/devel/go/src/os/exec.go:118 +0x2b
os/exec.(*Cmd).Wait(0xc420178840, 0x0, 0x0)
	/home/jphillips/devel/go/src/os/exec/exec.go:456 +0x5c
os/exec.(*Cmd).Run(0xc420178840, 0xc4202d6000, 0xc420193901)
	/home/jphillips/devel/go/src/os/exec/exec.go:300 +0x5c
os/exec.(*Cmd).CombinedOutput(0xc420178840, 0x5, 0xc4201d6630, 0x8, 0xc420044fb0, 0x42fa78)
	/home/jphillips/devel/go/src/os/exec/exec.go:516 +0x106
main.(*tester).runPending.func1(0xc42023e4b0)
	/home/jphillips/devel/go/src/cmd/dist/test.go:1063 +0x93
created by main.(*tester).runPending
	/home/jphillips/devel/go/src/cmd/dist/test.go:1057 +0x105

goroutine 121 [runnable]:
bytes.(*Buffer).grow(0xc4202d6000, 0x200, 0x200)
	/home/jphillips/devel/go/src/bytes/buffer.go:118 +0x2ac
bytes.(*Buffer).ReadFrom(0xc4202d6000, 0x57e9a0, 0xc4202d8010, 0x7fa5b97e7020, 0xc4202d6000, 0x1)
	/home/jphillips/devel/go/src/bytes/buffer.go:204 +0x48
io.copyBuffer(0x57e860, 0xc4202d6000, 0x57e9a0, 0xc4202d8010, 0x0, 0x0, 0x0, 0xc4202cdf48, 0xc4202cdf48, 0x4c938b)
	/home/jphillips/devel/go/src/io/io.go:386 +0x31a
io.Copy(0x57e860, 0xc4202d6000, 0x57e9a0, 0xc4202d8010, 0xc42026c150, 0x1, 0xc42026c150)
	/home/jphillips/devel/go/src/io/io.go:362 +0x5a
os/exec.(*Cmd).writerDescriptor.func1(0x3, 0x0)
	/home/jphillips/devel/go/src/os/exec/exec.go:275 +0x4d
os/exec.(*Cmd).Start.func1(0xc420178840, 0xc42000a080)
	/home/jphillips/devel/go/src/os/exec/exec.go:391 +0x27
created by os/exec.(*Cmd).Start
	/home/jphillips/devel/go/src/os/exec/exec.go:390 +0x5df

goroutine 156 [chan send, 5 minutes]:
main.(*tester).runPending.func1(0xc42023e500)
	/home/jphillips/devel/go/src/cmd/dist/test.go:1066 +0x130
created by main.(*tester).runPending
	/home/jphillips/devel/go/src/cmd/dist/test.go:1057 +0x105

rax    0xca
rbx    0x620460
rcx    0x4541b3
rdx    0x0
rdi    0x6205a8
rsi    0x0
rbp    0x7ffee31f07c0
rsp    0x7ffee31f0778
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0xc420203000
r13    0x7
r14    0x4519e0
r15    0x0
rip    0x4541b1
rflags 0x286
cs     0x33
fs     0x0
gs     0x0
@ianlancetaylor ianlancetaylor added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 26, 2018
@ianlancetaylor ianlancetaylor added this to the Go1.10 milestone Jan 26, 2018
@ianlancetaylor
Copy link
Contributor

Has this happened more than once?

How many cores do you have on your system?

@ianlancetaylor ianlancetaylor changed the title all.bash intermittent hang running test for issue 19182 runtime: all.bash intermittent hang running test for issue 19182 Jan 26, 2018
@jasonphi
Copy link
Author

Has this happened more than once?

So far I've only seen it the first time running all.bash after updating to 1.10rc1. I can run all.bash in a loop and see if it happens again.

How many cores do you have on your system?

4

processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 58
model name	: Intel(R) Core(TM) i7-3770K CPU @ 3.50GHz
stepping	: 9
microcode	: 0x1c
cpu MHz		: 3503.551
cache size	: 8192 KB
physical id	: 0
siblings	: 8
core id		: 0
cpu cores	: 4
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 13
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 ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm cpuid_fault epb pti tpr_shadow vnmi flexpriority ept vpid fsgsbase smep erms xsaveopt dtherm ida arat pln pts
bugs		: cpu_meltdown spectre_v1 spectre_v2
bogomips	: 7007.10
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:

@jasonphi
Copy link
Author

all.bash ran 120 times in a row without issue. Closing as a freak occurrence.

@josharian
Copy link
Contributor

If you'd like to make sure, in a more efficient manner, you could also do something like this:

$ go get golang.org/x/tools/cmd/stress
$ go build -o issue19182  test/fixedbugs/issue19182.go
$ stress ./issue19182 -timeout 1m

and let it run for a while (obviously at least a minute!)...

@jasonphi
Copy link
Author

@josharian Thanks, I'll try that and report back.

@jasonphi
Copy link
Author

@josharian 1 million runs and no failures. Thanks for the pointer to "stress", though!

@golang golang locked and limited conversation to collaborators Jan 27, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.10
Development

No branches or pull requests
4 participants
@josharian @ianlancetaylor @gopherbot @jasonphi