runtime: another deadlock issue maybe

[alberts]

What steps will reproduce the problem?

running an internal test

will try to factor it out when I can reproduce it

What do you see instead?

program is stuck doing this:

[pid 18251] select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
[pid 18251] select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
[pid 18251] select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
[pid 18251] select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
[pid 18251] select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
[pid 18251] select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)

gdb backtraces:

Thread 4 (Thread 0x7f820101e700 (LWP 18251)):
#0  runtime.usleep (usec=void) at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:76
#1  0x00000000004176a7 in sysmon () at /build/go/go/src/pkg/runtime/proc.c:1989
#2  0x00000000004145c2 in runtime.mstart () at /build/go/go/src/pkg/runtime/proc.c:485
#3  0x00000000006115c4 in crosscall_amd64 ()
#4  0x0000000000000003 in ?? ()
#5  0x0000000000000000 in ?? ()

Thread 3 (Thread 0x7f820071a700 (LWP 18256)):
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x000000000041baf9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:58
#2  0x000000000040aa49 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x0000000000414bcf in stopm () at /build/go/go/src/pkg/runtime/proc.c:794
#4  0x00000000004163f8 in exitsyscall0 (gp=void) at
/build/go/go/src/pkg/runtime/proc.c:1407
#5  0x0000000000421559 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:194
#6  0x000000c2000c1000 in ?? ()
#7  0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7f81fff19700 (LWP 18257)):
#0  bytes.(*Buffer).Read (b=0xc20016d000, p= []uint8 = {...}, n=0, err=0) at
/build/go/go/src/pkg/bytes/buffer.go:256
#1  0x00000000004967ba in foo.bytesBuffer.Read (this=..., p·4= []uint8 = {...}, n·1=0,
err·2=0)
#2  0x000000000049838e in foo.start (this=0xc2000bbc00) at foo.go:36
#3  0x0000000000415b90 in ?? () at /build/go/go/src/pkg/runtime/proc.c:1209
#4  0x000000c2000bbc00 in ?? ()
#5  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x7f8211802700 (LWP 18241)):
#0  runtime.futex () at /build/go/go/src/pkg/runtime/sys_linux_amd64.s:267
#1  0x000000000041baf9 in runtime.futexsleep (addr=void, val=void, ns=void) at
/build/go/go/src/pkg/runtime/thread_linux.c:58
#2  0x000000000040aa49 in runtime.notesleep (n=void) at
/build/go/go/src/pkg/runtime/lock_futex.c:125
#3  0x0000000000414bcf in stopm () at /build/go/go/src/pkg/runtime/proc.c:794
#4  0x00000000004163f8 in exitsyscall0 (gp=void) at
/build/go/go/src/pkg/runtime/proc.c:1407
#5  0x0000000000421559 in runtime.mcall (fn=void) at
/build/go/go/src/pkg/runtime/asm_amd64.s:194
#6  0x00000000009c6fa0 in runtime.g0 ()
#7  0x0000000000421421 in _rt0_amd64 () at /build/go/go/src/pkg/runtime/asm_amd64.s:85
#8  0x0000000000000004 in ?? ()
#9  0x00007fffabf93018 in ?? ()
#10 0x0000000000000004 in ?? ()
#11 0x00007fffabf93018 in ?? ()
#12 0x0000000000000000 in ?? ()

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 +90c75b8f9526 Wed Mar 13 23:32:12 2013 -0400

Please provide any additional information below.

looks a bit like issue #5025, but not quite.

I'm going to try to get a smaller sample that shows the problem.

[alberts]

Comment 1:

this is an internal test that is run with -test.timeout=600s, but for some reason it
gets into a state where that timeout can never trigger.

[alberts]

Comment 2:

here's a goroutine trace from when it gets stuck. looks different to the other one, but
maybe it's useful.
running with GOTRACEBACK=2
SIGQUIT: quit
PC=0x4236c1
runtime.futex()
    /build/go/go/src/pkg/runtime/sys_linux_amd64.s:266 +0x21
runtime.futexsleep(0x9c74d8, 0x0, 0xffffffffffffffff)
    /build/go/go/src/pkg/runtime/os_linux.c:56 +0x59
runtime.notesleep(0x9c74d8)
    /build/go/go/src/pkg/runtime/lock_futex.c:125 +0x69
stopm()
    /build/go/go/src/pkg/runtime/proc.c:794 +0xdf
exitsyscall0(0xc2000b1800)
    /build/go/go/src/pkg/runtime/proc.c:1407 +0xc8
runtime.mcall()
    /build/go/go/src/pkg/runtime/asm_amd64.s:194 +0x49
goroutine 1 [chan receive]:
runtime.park(0x40a930, 0xc2000f6530, 0x9b994a)
    /build/go/go/src/pkg/runtime/proc.c:1167 +0x64
runtime.chanrecv(0x667220, 0xc2000f64e0, 0x7f95f27a5ce0, 0x0, 0x0, ...)
    /build/go/go/src/pkg/runtime/chan.c:366 +0x566
runtime.chanrecv1()
    /build/go/go/src/pkg/runtime/chan.c:458 +0x38
testing.RunTests(0x814e50, 0x9b3190, 0x1, 0x1, 0x1, ...)
    /build/go/go/src/pkg/testing/testing.go:427 +0x88e
testing.Main(0x814e50, 0x9b3190, 0x1, 0x1, 0x9beca0, ...)
    /build/go/go/src/pkg/testing/testing.go:358 +0x8a
main.main()
    foo/_test/_testmain.go:43 +0x9a
runtime.main()
    /build/go/go/src/pkg/runtime/proc.c:182 +0x92
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
goroutine 2 [syscall]:
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
goroutine 3 [syscall]:
runtime.entersyscallblock()
    /build/go/go/src/pkg/runtime/proc.c:1324 +0x16e
runtime.MHeap_Scavenger()
    /build/go/go/src/pkg/runtime/mheap.c:435 +0xee
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
created by runtime.main
    /build/go/go/src/pkg/runtime/proc.c:165
goroutine 5 [runnable]:
runtime.exitsyscall()
    /build/go/go/src/pkg/runtime/proc.c:1379 +0x119
timerproc()
    /build/go/go/src/pkg/runtime/ztime_linux_amd64.c:196 +0xc1
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
created by addtimer
    /build/go/go/src/pkg/runtime/ztime_linux_amd64.c:82
goroutine 6 [runnable]:
runtime.park(0x40a930, 0xc2000f65f0, 0x9b994a)
    /build/go/go/src/pkg/runtime/proc.c:1167 +0x64
runtime.chanrecv(0x667160, 0xc2000f65a0, 0x7f95f27b1e20, 0x0, 0x0, ...)
    /build/go/go/src/pkg/runtime/chan.c:366 +0x566
runtime.chanrecv1()
    /build/go/go/src/pkg/runtime/chan.c:458 +0x38
foo.(*Service).StartWait(0xc2000f0b40)
    b.go:96 +0x63
foo.TestContainsCheck(0xc200153180)
    e.go:45 +0x2d6
foo.TestStaticChecks(0xc2000e8360)
    foo_test.go:16 +0x84
testing.tRunner(0xc2000e8360, 0x9b3190)
    /build/go/go/src/pkg/testing/testing.go:346 +0x8a
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
created by testing.RunTests
    /build/go/go/src/pkg/testing/testing.go:426 +0x86b
goroutine 7 [running]:
syscall.Syscall()
    /build/go/go/src/pkg/syscall/asm_linux_amd64.s:16 +0x5
syscall.write(0x2, 0xc2000a9800, 0x112a, 0x1573, 0x112a, ...)
    /build/go/go/src/pkg/syscall/zerrors_linux_amd64.go:2717 +0x70
syscall.Write(0x2, 0xc2000a9800, 0x112a, 0x1573, 0x47a6e8, ...)
    /build/go/go/src/pkg/syscall/syscall_unix.go:143 +0x5a
os.(*File).write(0xc200000010, 0x0, 0x0, 0x1573, 0x112a, ...)
    /build/go/go/src/pkg/os/file_unix.go:188 +0x79
os.(*File).Write(0xc2000ef270, 0xc2000a9800, 0x45d35d, 0x9c9938, 0xffffffff, ...)
    /build/go/go/src/pkg/os/file.go:144 +0xdb
fmt.Fprintf(0x9c9938, 0xc200000010, 0x76a860, 0x3, 0x7f95e072dcf0, ...)
    /build/go/go/src/pkg/fmt/print.go:215 +0xdd
foo/log.(*ioWriter).Write(0xc2000d6b30, 0xc2000e83f0, 0x0, 0x0)
    foo/log/log.go:367 +0x152
foo/log.(*loggerImpl).write(0xc2000d77d0, 0x2, 0xc200166100, 0x10d5, 0x0, ...)
    foo/log/log.go:209 +0x1a1
foo/log.(*loggerImpl).Crit(0xc2000d77d0, 0xc200166100, 0x10d5, 0x0, 0x0, ...)
    foo/log/log.go:387 +0x60
foo.VotePB(0xc2000f0c80)
    c.go:28 +0x76
foox.Vote(0x44796c, 0xc200161150, 0x0, 0x0, 0x0, ...)
    c.go:24 +0x157
foo.(*ContainsCheck).Match(0xc200161150, 0xc200163000, 0x477, 0x1000)
    d.go:38 +0x2eb
foo.(*thread).start(0xc2000f0b80)
    b.go:36 +0x24e
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
created by foo.(*Service).Start
    a.go:72 +0x618
rax     0xca
rbx     0x9c0de0
rcx     0xffffffffffffffff
rdx     0x0
rdi     0x9c74d8
rsi     0x0
rbp     0xc2000f0b08
rsp     0x7fff88568b18
r8      0x0
r9      0x0
r10     0x0
r11     0x246
r12     0xb
r13     0xb
r14     0x0
r15     0x2
rip     0x4236c1
rflags  0x246
cs      0x33
fs      0x0
gs      0x0

[dvyukov]

Comment 3:

Are you sure that it's stuck? In both cases it looks running:
Thread 2 (Thread 0x7f81fff19700 (LWP 18257)):
#0  bytes.(*Buffer).Read (b=0xc20016d000, p= []uint8 = {...}, n=0, err=0) at
/build/go/go/src/pkg/bytes/buffer.go:256
#1  0x00000000004967ba in foo.bytesBuffer.Read (this=..., p·4= []uint8 = {...}, n·1=0,
err·2=0)
#2  0x000000000049838e in foo.start (this=0xc2000bbc00) at foo.go:36
goroutine 7 [running]:
syscall.Syscall()
    /build/go/go/src/pkg/syscall/asm_linux_amd64.s:16 +0x5
syscall.write(0x2, 0xc2000a9800, 0x112a, 0x1573, 0x112a, ...)
    /build/go/go/src/pkg/syscall/zerrors_linux_amd64.go:2717 +0x70
syscall.Write(0x2, 0xc2000a9800, 0x112a, 0x1573, 0x47a6e8, ...)
    /build/go/go/src/pkg/syscall/syscall_unix.go:143 +0x5a
os.(*File).write(0xc200000010, 0x0, 0x0, 0x1573, 0x112a, ...)
    /build/go/go/src/pkg/os/file_unix.go:188 +0x79
os.(*File).Write(0xc2000ef270, 0xc2000a9800, 0x45d35d, 0x9c9938, 0xffffffff, ...)
    /build/go/go/src/pkg/os/file.go:144 +0xdb
fmt.Fprintf(0x9c9938, 0xc200000010, 0x76a860, 0x3, 0x7f95e072dcf0, ...)
    /build/go/go/src/pkg/fmt/print.go:215 +0xdd
foo/log.(*ioWriter).Write(0xc2000d6b30, 0xc2000e83f0, 0x0, 0x0)
    foo/log/log.go:367 +0x152
foo/log.(*loggerImpl).write(0xc2000d77d0, 0x2, 0xc200166100, 0x10d5, 0x0, ...)
    foo/log/log.go:209 +0x1a1
foo/log.(*loggerImpl).Crit(0xc2000d77d0, 0xc200166100, 0x10d5, 0x0, 0x0, ...)
    foo/log/log.go:387 +0x60
foo.VotePB(0xc2000f0c80)
    c.go:28 +0x76
foox.Vote(0x44796c, 0xc200161150, 0x0, 0x0, 0x0, ...)
    c.go:24 +0x157
foo.(*ContainsCheck).Match(0xc200161150, 0xc200163000, 0x477, 0x1000)
    d.go:38 +0x2eb
foo.(*thread).start(0xc2000f0b80)
    b.go:36 +0x24e
runtime.goexit()
    /build/go/go/src/pkg/runtime/proc.c:1214
created by foo.(*Service).Start
And in both cases in something called foo.(*thread).start.
Can you try to figure out what the goroutine is doing at the time of hang?

[alberts]

Comment 4:

Looking into it. Might be that we are hitting our own bugs due to the better scheduler.
The strange thing is that the test timeout never manages to fire.

[dvyukov]

Comment 5:

It's possible if the running goroutine never yields.
However the strange thing is that I do not see timer thread in gdb dump.

[alberts]

Comment 6:

Here's the last bunch of system calls from the process:
12962 12:20:59.592270 mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x7f32fdfc8000
12956 12:20:59.592297 <... select resumed> ) = 0 (Timeout)
12956 12:20:59.592317 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.592432 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.592545 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.592657 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
12962 12:20:59.592808 open("/etc/localtime", O_RDONLY <unfinished ...>
12956 12:20:59.592819 <... select resumed> ) = 0 (Timeout)
12962 12:20:59.592830 <... open resumed> ) = 6
12956 12:20:59.592842 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
12962 12:20:59.592853 read(6, "...", 4096) = 118
12962 12:20:59.592889 read(6, "", 4096) = 0
12962 12:20:59.592919 close(6)          = 0
12956 12:20:59.592945 <... select resumed> ) = 0 (Timeout)
12956 12:20:59.592967 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
12962 12:20:59.593002 write(2, "LONG STRING HERE"..., 4394 <unfinished ...>
this write system call is goroutine 7 in the trace I posted.
so although the goroutine dump shows that it is still busy with the write system call, I
actually believe it has completed.
then it keeps going:
12956 12:20:59.593070 <... select resumed> ) = 0 (Timeout)
12956 12:20:59.593096 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
12962 12:20:59.593151 <... write resumed> ) = 4394
12956 12:20:59.593195 <... select resumed> ) = 0 (Timeout)
12956 12:20:59.593216 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.593335 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.593453 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.593572 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.593735 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.593855 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.593977 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.594094 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.594211 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.594328 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.594445 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
12956 12:20:59.594562 select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
this goes on for a while. then I see:
12956 12:21:14.565255 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.575412 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.585588 select(0, NULL, NULL, NULL, {0, 10000} <unfinished ...>
12955 12:21:14.592410 <... futex resumed> ) = -1 ETIMEDOUT (Connection timed out)
12955 12:21:14.592454 futex(0x9c74d8, FUTEX_WAIT, 0, NULL <unfinished ...>
12956 12:21:14.595751 <... select resumed> ) = 0 (Timeout)
12956 12:21:14.595785 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.605952 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.616127 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.626322 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.636515 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.646713 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.656899 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.667093 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
12956 12:21:14.677268 select(0, NULL, NULL, NULL, {0, 10000}) = 0 (Timeout)
that looks like the futex associated with the test.timeout=15s firing, but it doesn't
cause anything to happen in the test.

[dvyukov]

Comment 7:

> so although the goroutine dump shows that it is still busy with the write system call,
I actually believe it has completed.
Yes, runtime remembers the stack before last syscall (or last blocking) for running
goroutines. So it's running somewhere after the write(). The question is what exactly it
is doing.
> that looks like the futex associated with the test.timeout=15s firing, but it doesn't
cause anything to happen in the test.
I guess you are running with GOMAXPROCS=1, so the times goroutine is not scheduled
because another goroutine is already running.
For now it looks like foo.(*thread).start(0xc2000f0b80) goroutine hang in infinite loop.

[dvyukov]

Comment 8:

You can switch to the thread running foo.(*thread).start(0xc2000f0b80) in gdb, and
sample it's stacks and execute 'finish' until you hit a function which it can't finish
(what is that function? and why it can't finish it?).

[alberts]

Comment 9:

thanks for the info so far. yes, it hangs specifically when GOMAXPROCS=1.
will look into the "thread" goroutine and what it's up to.

[alberts]

Comment 10:

it's a goroutine stuck in an infinite loop because it wasn't checking an error.
will kill programmer responsible.
sorry for the noise.

[dvyukov]

Comment 11:

Status changed to WorkingAsIntended.