runtime: tests timing out

[alberts]

What steps will reproduce the problem?

go test -v -cpu 1,2,4 -timeout=30m

What do you see instead?

=== RUN TestSimpleDeadlock
panic: test timed out

goroutine 65 [running]:
testing.alarm()
    /build/go.tip/go/src/pkg/testing/testing.go:526 +0x53
created by time.goFunc
    /build/go.tip/go/src/pkg/time/sleep.go:122 +0x48

goroutine 1 [chan receive]:
testing.RunTests(0x644e20, 0x74bae0, 0x22, 0x22, 0x1, ...)
    /build/go.tip/go/src/pkg/testing/testing.go:427 +0x88e
testing.Main(0x644e20, 0x74bae0, 0x22, 0x22, 0x74d580, ...)
    /build/go.tip/go/src/pkg/testing/testing.go:358 +0x8a
main.main()
    runtime/_test/_testmain.go:251 +0x9a

goroutine 46 [syscall]:
syscall.Syscall6()
    /build/go.tip/go/src/pkg/syscall/asm_linux_amd64.s:41 +0x5
syscall.wait4(0x38e9, 0xc2000006f0, 0x0, 0xc200119240, 0x100000001, ...)
    /build/go.tip/go/src/pkg/syscall/zerrors_linux_amd64.go:1640 +0x7b
syscall.Wait4(0x38e9, 0x7f9eafe7eb44, 0x0, 0xc200119240, 0xc200114840, ...)
    /build/go.tip/go/src/pkg/syscall/syscall_linux.go:222 +0x6c
os.(*Process).wait(0xc20011a500, 0x0, 0x0, 0x0)
    /build/go.tip/go/src/pkg/os/exec_unix.go:22 +0xea
os.(*Process).Wait(0xc20011a500, 0xc200000668, 0x0, 0x0)
    /build/go.tip/go/src/pkg/os/doc.go:43 +0x25
os/exec.(*Cmd).Wait(0xc2000da8c0, 0x0, 0x0)
    /build/go.tip/go/src/pkg/os/exec/exec.go:308 +0x197
os/exec.(*Cmd).Run(0xc2000da8c0, 0xc2000c3cb0, 0xc200114840)
    /build/go.tip/go/src/pkg/os/exec/exec.go:232 +0x52
os/exec.(*Cmd).CombinedOutput(0xc2000da8c0, 0x2, 0x7f9eafe7edc0, 0x2, 0x2, ...)
    /build/go.tip/go/src/pkg/os/exec/exec.go:352 +0x20d
runtime_test.executeTest(0xc2000c2f30, 0x639b90, 0x29, 0x0, 0x0, ...)
    /build/go.tip/go/src/pkg/runtime/crash_test.go:40 +0x61f
runtime_test.testDeadlock(0xc2000c2f30, 0x639b90, 0x29)
    /build/go.tip/go/src/pkg/runtime/crash_test.go:71 +0x56
runtime_test.TestSimpleDeadlock(0xc2000c2f30)
    /build/go.tip/go/src/pkg/runtime/crash_test.go:79 +0x39
testing.tRunner(0xc2000c2f30, 0x74bba0)
    /build/go.tip/go/src/pkg/testing/testing.go:346 +0x8a
created by testing.RunTests
    /build/go.tip/go/src/pkg/testing/testing.go:426 +0x86b

goroutine 51 [finalizer wait]:

goroutine 49 [syscall]:
syscall.Syscall()
    /build/go.tip/go/src/pkg/syscall/asm_linux_amd64.s:16 +0x5
syscall.read(0x4, 0xc200112a00, 0x200, 0x200, 0x8, ...)
    /build/go.tip/go/src/pkg/syscall/zerrors_linux_amd64.go:2337 +0x70
syscall.Read(0x4, 0xc200112a00, 0x200, 0x200, 0x413b64, ...)
    /build/go.tip/go/src/pkg/syscall/syscall_unix.go:132 +0x5a
os.(*File).read(0xc200000698, 0xc200112a00, 0x200, 0x200, 0x569f80, ...)
    /build/go.tip/go/src/pkg/os/file_unix.go:174 +0x60
os.(*File).Read(0xc200000698, 0xc200112a00, 0x200, 0x200, 0x0, ...)
    /build/go.tip/go/src/pkg/os/file.go:95 +0x96
bytes.(*Buffer).ReadFrom(0xc2000c3cb0, 0xc2000c0d80, 0xc200000698, 0x0, 0x0, ...)
    /build/go.tip/go/src/pkg/bytes/buffer.go:166 +0x203
io.Copy(0xc2000c0ab0, 0xc2000c3cb0, 0xc2000c0d80, 0xc200000698, 0x0, ...)
    /build/go.tip/go/src/pkg/io/io.go:328 +0xa3
os/exec.func·003(0x639bb9, 0xc2000c3b60)
    /build/go.tip/go/src/pkg/os/exec/exec.go:207 +0x60
os/exec.func·004(0xc20011a240)
    /build/go.tip/go/src/pkg/os/exec/exec.go:274 +0x2a
created by os/exec.(*Cmd).Start
    /build/go.tip/go/src/pkg/os/exec/exec.go:275 +0x6ac
FAIL    runtime 1800.016s

Which compiler are you using (5g, 6g, 8g, gccgo)?

6g

Which operating system are you using?

linux

Which version are you using?  (run 'go version')

go version devel +8377d19921c3 Sun Mar 10 16:32:00 2013 -0400 linux/amd64

Please provide any additional information below.

seems like a leftover from all the stuff I reported in issue #5007

[alberts]

Comment 1:

seeing similar stuff on linux/386

[dvyukov]

Comment 2:

Labels changed: added priority-soon, go1.1, removed priority-triage.

Owner changed to @dvyukov.

[dvyukov]

Comment 3:

I can not reproduce it on linux/amd64.
Please provide more details on how to reproduce it.
It seems that the test is waiting for child process (goroutine 46). Can you obtain the
stack dump for the child process (the test starts another 'go run' process)?

[alberts]

Comment 4:

I'll try to reproduce. I hit this flakiness in the mean time:
--- FAIL: TestStackMem-256 (2.97 seconds)
        stack_test.go:1574: Consumed 9MB for stack mem
        stack_test.go:1580: Stack inuse: want 4194304, got 5345280
--- FAIL: TestStackMem-256 (3.26 seconds)
        stack_test.go:1574: Consumed 9MB for stack mem
        stack_test.go:1580: Stack inuse: want 4194304, got 5337088
It would help to fix it, since it will make other failures easier to hit.
script:
#!/bin/bash
set -xe
go test -c runtime
while true; do
go version
date
GOMAXPROCS=$[ 1 + $[ RANDOM % 512 ]] ./runtime.test -test.v -test.timeout=1000m
done
go version:
go version devel +6415ff684316 Sun Mar 10 19:07:16 2013 -0700 linux/amd64

[alberts]

Comment 5:

It might be worth poking at issue #5005 while I track this down.

[alberts]

Comment 6:

this triggered it after about 3 hours:
#!/bin/bash
set -xe
go test -c runtime
while true; do
go version
date
GOMAXPROCS=16 go test runtime -test.v -test.timeout=5000m -test.cpu 1,2,4 || true
done
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 7169
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) thread apply all bt
Thread 1 (process 7169):
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e2c3 in gcstopm () at /build/go/go/src/pkg/runtime/proc.c:952
#5  0x000000000040e3f6 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:992
#6  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#7  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#8  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#9  0x0000000000441320 in runtime.g0 ()
#10 0x00000000004175aa in _rt0_amd64 () at /build/go/go/src/pkg/runtime/asm_amd64.s:73
#11 0x0000000000000001 in ?? ()
#12 0x00007fffe30a8c88 in ?? ()
#13 0x0000000000000001 in ?? ()
#14 0x00007fffe30a8c88 in ?? ()
#15 0x0000000000000000 in ?? ()
parent process is stuck at:
=== RUN TestGoexitDeadlock
go version devel +6415ff684316 Sun Mar 10 19:07:16 2013 -0700 linux/amd64

[rsc]

Comment 7:

Sometimes you have to get the full thread list by ls /proc/$pid/task and
then run gdb on each to get the stack traces. It looks like this is one of
those times, unless the ls confirms that there is really only one thread
(very unlikely).

[dvyukov]

Comment 8:

Is it a trace from parent or child process?

[alberts]

Comment 9:

Here we go. I hope I got all of them...
$ ls -l /proc/7169/task
total 0
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 11244
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 12497
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 13297
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 13332
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 7169
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 7170
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 7171
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 7172
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 7381
dr-xr-xr-x 6 alberts users 0 Mar 11 16:11 9355
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 7170
warning: process 7170 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x0000000000410101 in sysmon () at /build/go/go/src/pkg/runtime/proc.c:1939
#4  0x000000000040d7b2 in runtime.mstart () at /build/go/go/src/pkg/runtime/proc.c:482
#5  0x0000000000417ec7 in runtime.clone () at
/build/go/go/src/pkg/runtime/sys_linux_amd64.s:307
#6  0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 7171
warning: process 7171 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x000000000040423f in runtime.notetsleep (n=void, ns=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:147
#3  0x000000000040a83e in runtime.MHeap_Scavenger () at
/build/go/go/src/pkg/runtime/mheap.c:432
#4  0x000000000040ea50 in ?? () at /build/go/go/src/pkg/runtime/proc.c:1155
#5  0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 7172
warning: process 7172 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e685 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:1061
#5  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#6  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#7  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#8  0x000000c20001d0a0 in ?? ()
#9  0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 7381
warning: process 7381 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e685 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:1061
#5  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#6  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#7  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#8  0x000000c20000fc20 in ?? ()
#9  0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 9355
warning: process 9355 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e2c3 in gcstopm () at /build/go/go/src/pkg/runtime/proc.c:952
#5  0x000000000040e3f6 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:992
#6  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#7  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#8  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#9  0x000000c20000fe20 in ?? ()
#10 0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 11244
warning: process 11244 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e685 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:1061
#5  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#6  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#7  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#8  0x000000c200075020 in ?? ()
#9  0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 12497
warning: process 12497 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e685 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:1061
#5  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#6  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#7  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#8  0x000000c200075220 in ?? ()
#9  0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 13297
warning: process 13297 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e2c3 in gcstopm () at /build/go/go/src/pkg/runtime/proc.c:952
#5  0x000000000040e3f6 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:992
#6  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#7  0x000000000040eb77 in goexit0 (gp=void) at /build/go/go/src/pkg/runtime/proc.c:1183
#8  0x00000000004176d9 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:182
#9  0x000000c200075420 in ?? ()
#10 0x0000000000000000 in ?? ()
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 13332
warning: process 13332 is a cloned process
runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
267     RET
Loading Go Runtime support.
(gdb) bt
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x00000000004134e9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:62
#2  0x0000000000404179 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x000000000040dc8f in stopm () at /build/go/go/src/pkg/runtime/proc.c:791
#4  0x000000000040e2c3 in gcstopm () at /build/go/go/src/pkg/runtime/proc.c:952
#5  0x000000000040e3f6 in findrunnable () at /build/go/go/src/pkg/runtime/proc.c:992
#6  0x000000000040e76d in schedule () at /build/go/go/src/pkg/runtime/proc.c:1083
#7  0x000000000040d7e3 in runtime.mstart () at /build/go/go/src/pkg/runtime/proc.c:491
#8  0x0000000000417ec7 in runtime.clone () at
/build/go/go/src/pkg/runtime/sys_linux_amd64.s:307
#9  0x0000000000000000 in ?? ()

[alberts]

Comment 10:

this is the complete trace from the child process:
Attaching to program: /tmp/go-build227511012/command-line-arguments/_obj/exe/main,
process 7169

[dvyukov]

Comment 11:

I am able to reproduce it on TestGoexitDeadlock

[dvyukov]

Comment 12:

This issue was closed by revision 6ee739d.

Status changed to Fixed.