Deferred mutex unlocks hanging in websocket

[Patrick Higgins]

I have written a stress testing program in Go for a chat server I have
also written in Go. As the test ramps down, I find it never completes
because a few of the sending goroutines are stuck on line 204 of
websocket.go, which looks like:


202 func (ws *Conn) Write(msg []byte) (n int, err error) {
203 ws.wio.Lock()
204 defer ws.wio.Unlock()
...

I have seen this behavior on 386 and amd64 Linux.

Here is a goroutine stack dump from 386. The goroutines in [sleep]
state seem the most puzzling to me. Can anyone explain what is going
on here? Is this a Go bug or perhaps a problem with my code?

goroutine 20005 [running]:
runtime/pprof.writeGoroutineStacks(0xf84119bcf0, 0xf8404f6880,
0x7fb1d20d9bb7, 0x10, 0x7fb1d20d9ca8, ...)
/usr/local/go/src/pkg/runtime/pprof/pprof.go:488 +0x6f
runtime/pprof.writeGoroutine(0xf84119bcf0, 0xf8404f6880, 0x2,
0xe434f5a7c78c9800, 0x30, ...)
/usr/local/go/src/pkg/runtime/pprof/pprof.go:477 +0x3a
runtime/pprof.(*Profile).WriteTo(0x794a58, 0xf84119bcf0, 0xf8404f6880,
0xf800000002, 0xf8404f6880, ...)
/usr/local/go/src/pkg/runtime/pprof/pprof.go:221 +0xa2
net/http/pprof.handler.ServeHTTP(0xf840072c71, 0xf800000009,
0xf84110c080, 0xf8404f6880, 0xf840e0fb40, ...)
/usr/local/go/src/pkg/net/http/pprof/pprof.go:154 +0x210
net/http/pprof.Index(0xf84110c080, 0xf8404f6880, 0xf840e0fb40,
0x45cca4, 0x46b143, ...)
/usr/local/go/src/pkg/net/http/pprof/pprof.go:166 +0x143
net/http.HandlerFunc.ServeHTTP(0x46b143, 0xf84110c080, 0xf8404f6880,
0xf840e0fb40, 0xf800000000, ...)
/usr/local/go/src/pkg/net/http/server.go:690 +0x3d
net/http.(*ServeMux).ServeHTTP(0xf84006f5a0, 0xf84110c080,
0xf8404f6880, 0xf840e0fb40, 0xf8404f6880, ...)
/usr/local/go/src/pkg/net/http/server.go:926 +0xe7
net/http.(*conn).serve(0xf845ae5f60, 0x0)
/usr/local/go/src/pkg/net/http/server.go:656 +0x621
created by net/http.(*Server).Serve
/usr/local/go/src/pkg/net/http/server.go:1042 +0x430

goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xf8407a12b0, 0xf8407a12b0)
/tmp/bindist510773444/go/src/pkg/runtime/zsema_amd64.c:146 +0x25
sync.(*WaitGroup).Wait(0xf84006fe00, 0xf8407a12a8)
/usr/local/go/src/pkg/sync/waitgroup.go:78 +0xf2
main.main()
/home/phiggins/gocode/src/geochat/geobot/geobot.go:81 +0x746

goroutine 2 [syscall]:
created by runtime.main
/tmp/bindist510773444/go/src/pkg/runtime/proc.c:221

goroutine 3 [chan receive]:
net.(*pollServer).WaitRead(0xf8400c7600, 0xf840d5aa20, 0xf840a5ede0,
0xb, 0x1, ...)
/usr/local/go/src/pkg/net/fd.go:268 +0x73
net.(*netFD).accept(0xf840d5aa20, 0x44561c, 0x0, 0xf840071fc0,
0xf840097040, ...)
/usr/local/go/src/pkg/net/fd.go:622 +0x20d
net.(*TCPListener).AcceptTCP(0xf840a80dc8, 0xf84008ac80, 0x0, 0x0, 0x8, ...)
/usr/local/go/src/pkg/net/tcpsock_posix.go:320 +0x71
net.(*TCPListener).Accept(0xf840a80dc8, 0x0, 0x0, 0x0, 0x0, ...)
/usr/local/go/src/pkg/net/tcpsock_posix.go:330 +0x49
net/http.(*Server).Serve(0xf8400d0000, 0xf840cf7340, 0xf840a80dc8,
0x0, 0x0, ...)
/usr/local/go/src/pkg/net/http/server.go:1014 +0x88
net/http.(*Server).ListenAndServe(0xf8400d0000, 0xf8400d0000, 0x0, 0x4013fe)
/usr/local/go/src/pkg/net/http/server.go:1004 +0xb6
net/http.ListenAndServe(0x632ccc, 0x3330333a00000005, 0x0, 0x0,
0xf8400cf000, ...)
/usr/local/go/src/pkg/net/http/server.go:1076 +0x69
main._func_001()
/home/phiggins/gocode/src/geochat/geobot/geobot.go:67 +0x38
created by main.main
/home/phiggins/gocode/src/geochat/geobot/geobot.go:68 +0x49d

goroutine 17543 [sleep]:
code.google.com/p/go.net/websocket.(*Conn).Write(0xf8427e3c80,
0xf84e5c7080, 0x1a0000001a, 0x7fb100000000, 0x0, ...)
/home/phiggins/gocode/src/code.google.com/p/go.net/websocket/websocket.go:204
+0x5f
geochat/bot.(*Bot).send(0xf8402f8190, 0x40fa6e)
/home/phiggins/gocode/src/geochat/bot/bot.go:55 +0x13f
geochat/bot._func_001(0xf84e3b8640, 0xf8404f05b0, 0x0, 0x0)
/home/phiggins/gocode/src/geochat/bot/bot.go:138 +0x67
created by geochat/bot.(*Bot).Run
/home/phiggins/gocode/src/geochat/bot/bot.go:139 +0x7e0

goroutine 3868 [chan receive]:
net.(*pollServer).WaitRead(0xf8400c7600, 0xf840cdb510, 0xf840a5ede0,
0xb, 0x1, ...)
/usr/local/go/src/pkg/net/fd.go:268 +0x73
net.(*netFD).Read(0xf840cdb510, 0xf84664d000, 0x100000001000,
0xffffffff, 0xf840071fc0, ...)
/usr/local/go/src/pkg/net/fd.go:428 +0x1ec
net.(*TCPConn).Read(0xf84663a138, 0xf84664d000, 0x100000001000,
0xf8500000000, 0x0, ...)
/usr/local/go/src/pkg/net/tcpsock_posix.go:87 +0xce
bufio.(*Reader).fill(0xf846605180, 0x7fb1d31d9ba8)
/usr/local/go/src/pkg/bufio/bufio.go:77 +0xf0
bufio.(*Reader).ReadByte(0xf846605180, 0x5fcef0, 0x0, 0x0, 0xf8409653c0, ...)
/usr/local/go/src/pkg/bufio/bufio.go:166 +0x83
code.google.com/p/go.net/websocket.hybiFrameReaderFactory.NewFrameReader(0xf846605180,
0xf840e690f0, 0xf8409653c0, 0x0, 0x0, ...)
/home/phiggins/gocode/src/code.google.com/p/go.net/websocket/hybi.go:115 +0xd0
code.google.com/p/go.net/websocket.(*Conn).Read(0xf8427e3c80,
0xf84e3bb000, 0x100000001000, 0xf800000000, 0xf840071060, ...)
/home/phiggins/gocode/src/code.google.com/p/go.net/websocket/websocket.go:177
+0xc5
geochat/bot.(*Bot).recv(0xf8402f8190, 0xf8404f05b0)
/home/phiggins/gocode/src/geochat/bot/bot.go:74 +0x9a
geochat/bot.(*Bot).Run(0xf8402f8190, 0x0, 0x40eba6, 0xf84006fe00)
/home/phiggins/gocode/src/geochat/bot/bot.go:140 +0x7f3
main._func_002(0xf84006fe00, 0xf8402d0db8, 0x0, 0x0)
/home/phiggins/gocode/src/geochat/geobot/geobot.go:78 +0x4d
created by main.main
/home/phiggins/gocode/src/geochat/geobot/geobot.go:79 +0x71e

goroutine 18999 [sleep]:
code.google.com/p/go.net/websocket.(*Conn).Write(0xf845d1cd00,
0xf846a766e0, 0x1a0000001a, 0x7fb100000000, 0x0, ...)
/home/phiggins/gocode/src/code.google.com/p/go.net/websocket/websocket.go:204
+0x5f
geochat/bot.(*Bot).send(0xf8406e3fa0, 0x40fa6e)
/home/phiggins/gocode/src/geochat/bot/bot.go:55 +0x13f
geochat/bot._func_001(0xf846a76640, 0xf8408f6e78, 0x0, 0x0)
/home/phiggins/gocode/src/geochat/bot/bot.go:138 +0x67
created by geochat/bot.(*Bot).Run
/home/phiggins/gocode/src/geochat/bot/bot.go:139 +0x7e0

goroutine 20007 [chan receive]:
net.(*pollServer).WaitRead(0xf8400c7600, 0xf847c95120, 0xf840a5ede0,
0xb, 0x1, ...)
/usr/local/go/src/pkg/net/fd.go:268 +0x73
net.(*netFD).Read(0xf847c95120, 0xf84119d000, 0x100000001000,
0xffffffff, 0xf840071fc0, ...)
/usr/local/go/src/pkg/net/fd.go:428 +0x1ec
net.(*TCPConn).Read(0xf840097e98, 0xf84119d000, 0x100000001000,
0x7fb1d248ac27, 0x0, ...)
/usr/local/go/src/pkg/net/tcpsock_posix.go:87 +0xce
io.(*LimitedReader).Read(0xf84006fbe0, 0xf84119d000, 0x100000001000,
0x4089f9, 0x0, ...)
/usr/local/go/src/pkg/io/io.go:394 +0xc1
bufio.(*Reader).fill(0xf8404f6100, 0x100000000000)
/usr/local/go/src/pkg/bufio/bufio.go:77 +0xf0
bufio.(*Reader).ReadSlice(0xf8404f6100, 0x7fb1d248ac0a, 0x0, 0x0, 0x0, ...)
/usr/local/go/src/pkg/bufio/bufio.go:257 +0x1b6
bufio.(*Reader).ReadLine(0xf8404f6100, 0x0, 0x0, 0x0, 0x0, ...)
/usr/local/go/src/pkg/bufio/bufio.go:283 +0x5b
net/textproto.(*Reader).readLineSlice(0xf8400d1e00, 0xc0, 0x100000000, 0x1)
/usr/local/go/src/pkg/net/textproto/reader.go:55 +0x4f
net/textproto.(*Reader).ReadLine(0xf8400d1e00, 0xf84c277300, 0x30, 0x0)
/usr/local/go/src/pkg/net/textproto/reader.go:36 +0x25
net/http.ReadRequest(0xf8404f6100, 0xf84c277300, 0x0, 0x0,
0x1000000045b64e, ...)
/usr/local/go/src/pkg/net/http/request.go:457 +0xb1
net/http.(*conn).readRequest(0xf8400ad4e0, 0xf845ae5f00, 0x0, 0x0,
0x40c400, ...)
/usr/local/go/src/pkg/net/http/server.go:240 +0xa8
net/http.(*conn).serve(0xf8400ad4e0, 0x0)
/usr/local/go/src/pkg/net/http/server.go:594 +0x145
created by net/http.(*Server).Serve
/usr/local/go/src/pkg/net/http/server.go:1042 +0x430

goroutine 7989 [chan receive]:
net.(*pollServer).WaitRead(0xf8400c7600, 0xf840c16480, 0xf840a5ede0,
0xb, 0x1, ...)
/usr/local/go/src/pkg/net/fd.go:268 +0x73
net.(*netFD).Read(0xf840c16480, 0xf84b9ba000, 0x100000001000,
0xffffffff, 0xf840071fc0, ...)
/usr/local/go/src/pkg/net/fd.go:428 +0x1ec
net.(*TCPConn).Read(0xf84b984788, 0xf84b9ba000, 0x100000001000,
0xf8400000000, 0x0, ...)
/usr/local/go/src/pkg/net/tcpsock_posix.go:87 +0xce
bufio.(*Reader).fill(0xf84b9167c0, 0x7fb1d21b2ba8)
/usr/local/go/src/pkg/bufio/bufio.go:77 +0xf0
bufio.(*Reader).ReadByte(0xf84b9167c0, 0x5fcef0, 0x0, 0x0, 0xf845ae6b40, ...)
/usr/local/go/src/pkg/bufio/bufio.go:166 +0x83
code.google.com/p/go.net/websocket.hybiFrameReaderFactory.NewFrameReader(0xf84b9167c0,
0xf840e690f0, 0xf845ae6b40, 0x0, 0x0, ...)
/home/phiggins/gocode/src/code.google.com/p/go.net/websocket/hybi.go:115 +0xd0
code.google.com/p/go.net/websocket.(*Conn).Read(0xf845d1cd00,
0xf846a79000, 0x100000001000, 0xf800000000, 0xf840071060, ...)
/home/phiggins/gocode/src/code.google.com/p/go.net/websocket/websocket.go:177
+0xc5
geochat/bot.(*Bot).recv(0xf8406e3fa0, 0xf8408f6e78)
/home/phiggins/gocode/src/geochat/bot/bot.go:74 +0x9a
geochat/bot.(*Bot).Run(0xf8406e3fa0, 0x0, 0x40eba6, 0xf84006fe00)
/home/phiggins/gocode/src/geochat/bot/bot.go:140 +0x7f3
main._func_002(0xf84006fe00, 0xf8406e21b8, 0x0, 0x0)
/home/phiggins/gocode/src/geochat/geobot/geobot.go:78 +0x4d
created by main.main
/home/phiggins/gocode/src/geochat/geobot/geobot.go:79 +0x71e

goroutine 10004 [syscall]:
syscall.Syscall6()
/tmp/bindist510773444/go/src/pkg/syscall/asm_linux_amd64.s:40 +0x5
syscall.EpollWait(0xf800002706, 0xf840a73010, 0xa0000000a, 0xffffffff, 0xc, ...)
/usr/local/go/src/pkg/syscall/zerrors_linux_amd64.go:1781 +0xa1
net.(*pollster).WaitFD(0xf840a73000, 0xf8400c7600, 0x0, 0x0, 0x0, ...)
/usr/local/go/src/pkg/net/fd_linux.go:146 +0x110
net.(*pollServer).Run(0xf8400c7600, 0x0)
/usr/local/go/src/pkg/net/fd.go:236 +0xe4
created by net.newPollServer
/usr/local/go/src/pkg/net/newpollserver.go:35 +0x382

[Patrick Higgins]

After further testing, this problem appears to go away when I set GOMAXPROCS=1. I have 2 cores and have been using GOMAXPROCS=2 and occasionally try GOMAXPROCS=4. Both of those settings result in these hangs.

[Kyle Lemons]

On Fri, May 25, 2012 at 4:19 PM, Patrick Higgins <patrick.al...@gmail.com> wrote:

After further testing, this problem appears to go away when I set GOMAXPROCS=1. I have 2 cores and have been using GOMAXPROCS=2 and occasionally try GOMAXPROCS=4. Both of those settings result in these hangs.

If that's the case, it sounds like there's a data race.  It could be that there is one in websocket.  You may also want to sanity-check any websocket types you're accessing concurrently, as I believe websocket.Conn is the only one that is interlocked (though I haven't delved into that code in awhile).

[Patrick Higgins]

On Friday, May 25, 2012 5:22:28 PM UTC-6, Kyle Lemons wrote:

If that's the case, it sounds like there's a data race.  It could be that there is one in websocket.  You may also want to sanity-check any websocket types you're accessing concurrently, as I believe websocket.Conn is the only one that is interlocked (though I haven't delved into that code in awhile).

I have posted my code at http://play.golang.org/p/aj0lpymOMg

I am calling Read() and Write() concurrently on the same websocket from two different goroutines. Is that incorrect usage?

The other obvious issue to me is the weird handling of my websocket.Conn.Close(). I close it after sending all of my messages, but I do have another goroutine waiting in websocket.Conn.Read() at the time of close. This leads to strange error messages and some really nasty error handling code to try and not log any of the common errors.

[Patrick Higgins]

I have added comments to the weirder bits and posted it at http://play.golang.org/p/wCKX9LDPZx

As another aside, I have tried updating to the current tip (13312:40632db23c46) and still see the problem.

[Dmitry Vyukov]

On Saturday, May 26, 2012 2:21:07 AM UTC+4, Patrick Higgins wrote:

I have written a stress testing program in Go for a chat server I have
also written in Go. As the test ramps down, I find it never completes
because a few of the sending goroutines are stuck on line 204 of
websocket.go, which looks like:


202 func (ws *Conn) Write(msg []byte) (n int, err error) {
203        ws.wio.Lock()
204        defer ws.wio.Unlock()

I think it may actually be line 203. Do you see any other goroutine that holds the mutex?

[Patrick Higgins]

On May 25, 2012 11:15 PM, "Dmitry Vyukov" <dvy...@google.com> wrote:
> I think it may actually be line 203. Do you see any other goroutine that holds the mutex?

I don't. If that were the case, wouldn't the stack dump show the state as semacquire? That's what I saw when the server had a dead lock in it.

I also tried removing the locks from websocket as I do not believe my program needs them. After that I saw a similar hang in a sleep state on a simple allocation line in websocket/hybi.go. I don't have the line number, but it looked like:

h := &hybiFrameHeader{...normal fields which didnt appear to acquire any locks...}

It just didn't make any sense. It was this that made me wonder of there was a garbage collection or allocation bug, so I updated to tip to see your GC improvements, Dmitry (thanks for those, BTW!).

This is looking like a scheduler bug to me--the state of the goroutine (sleep) just looks wrong.

[Dmitry Vyukov]

On Saturday, May 26, 2012 4:51:32 PM UTC+4, Patrick Higgins wrote:

Humm... looks strange. Please run it with GOTRACEBACK=2 env.

 

[Patrick Higgins]

On Sun, May 27, 2012 at 10:33 AM, Dmitry Vyukov <dvy...@google.com> wrote:
> Humm... looks strange. Please run it with GOTRACEBACK=2 env.

Thanks, I didn't know about GOTRACEBACK. The output follows. The
[sleep]ing goroutines do appear to be waiting for malloc to return.

goroutine 20005 [running]:
runtime/pprof.writeGoroutineStacks(0x19974500, 0x188cd4e0, 0x820a770,
0x188cdf7b)
/home/phiggins/go/src/pkg/runtime/pprof/pprof.go:488 +0x74
runtime/pprof.writeGoroutine(0x19974500, 0x188cd4e0, 0x2, 0x18df5f30, 0x0, ...)
/home/phiggins/go/src/pkg/runtime/pprof/pprof.go:477 +0x35
runtime/pprof.(*Profile).WriteTo(0x83969d8, 0x19974500, 0x188cd4e0,
0x2, 0x188cd4e0, ...)
/home/phiggins/go/src/pkg/runtime/pprof/pprof.go:221 +0x92
net/http/pprof.handler.ServeHTTP(0x188cdf71, 0x9, 0x19974d00,
0x188cd4e0, 0x1e1863f0, ...)
/home/phiggins/go/src/pkg/net/http/pprof/pprof.go:154 +0x18e
net/http/pprof.Index(0x19974d00, 0x188cd4e0, 0x1e1863f0, 0x809c98c)
/home/phiggins/go/src/pkg/net/http/pprof/pprof.go:166 +0x132
net/http.HandlerFunc.ServeHTTP(0x80a9f28, 0x19974d00, 0x188cd4e0,
0x1e1863f0, 0x0, ...)
/home/phiggins/go/src/pkg/net/http/server.go:690 +0x35
net/http.(*ServeMux).ServeHTTP(0x18857720, 0x19974d00, 0x188cd4e0,
0x1e1863f0, 0x188cd4e0, ...)
/home/phiggins/go/src/pkg/net/http/server.go:926 +0xd3
net/http.(*conn).serve(0x189c65d0, 0x18a24690)
/home/phiggins/go/src/pkg/net/http/server.go:656 +0x4fa
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by net/http.(*Server).Serve
/home/phiggins/go/src/pkg/net/http/server.go:1042 +0x3aa

goroutine 1 [semacquire]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.semacquire(0x18df1450, 0x0)
/home/phiggins/go/src/pkg/runtime/zsema_386.c:106 +0xec
sync.runtime_Semacquire(0x18df1450, 0x18df1450)
/home/phiggins/go/src/pkg/runtime/zsema_386.c:146 +0x29
sync.(*WaitGroup).Wait(0x188a3200, 0x18df1440)
/home/phiggins/go/src/pkg/sync/waitgroup.go:78 +0xe6
main.main()
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:81 +0x5db
runtime.main()
/home/phiggins/go/src/pkg/runtime/proc.c:244 +0x8c
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271

goroutine 2 [syscall]:
runtime.entersyscall()
/home/phiggins/go/src/pkg/runtime/proc.c:952 +0x33
runtime.MHeap_Scavenger()
/home/phiggins/go/src/pkg/runtime/mheap.c:363 +0xe3
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by runtime.main
/home/phiggins/go/src/pkg/runtime/proc.c:221

goroutine 3 [chan receive]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.chanrecv(0x818aa30, 0x19586600, 0xb7533dc8, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/runtime/chan.c:359 +0x1ab
runtime.chanrecv1(0x818aa30, 0x19586600, 0x72)
/home/phiggins/go/src/pkg/runtime/chan.c:408 +0x2f
net.(*pollServer).WaitRead(0x188e6c90, 0x194e6b60, 0x188f1ca0, 0xb)
/home/phiggins/go/src/pkg/net/fd.go:268 +0x75
net.(*netFD).accept(0x194e6b60, 0x8087c86, 0x0, 0x188570e0, 0x18800170, ...)
/home/phiggins/go/src/pkg/net/fd.go:622 +0x199
net.(*TCPListener).AcceptTCP(0x19591ae8, 0x18e63100, 0x0, 0x0)
/home/phiggins/go/src/pkg/net/tcpsock_posix.go:320 +0x56
net.(*TCPListener).Accept(0x19591ae8, 0x0, 0x0, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/net/tcpsock_posix.go:330 +0x39
net/http.(*Server).Serve(0x18845e40, 0x19590680, 0x19591ae8, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/net/http/server.go:1014 +0x77
net/http.(*Server).ListenAndServe(0x18845e40, 0x18845e40, 0x0)
/home/phiggins/go/src/pkg/net/http/server.go:1004 +0x9f
net/http.ListenAndServe(0x8205f20, 0x5, 0x0, 0x0, 0x188720ac, ...)
/home/phiggins/go/src/pkg/net/http/server.go:1076 +0x55
main._func_001()
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:67 +0x33
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by main.main
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:68 +0x35f

goroutine 15991 [sleep]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.mallocgc(0x1c, 0x0, 0x0, 0x1, 0x3, ...)
/home/phiggins/go/src/pkg/runtime/zmalloc_386.c:29 +0x374
runtime.malloc(0x1c, 0x80ad813)
/home/phiggins/go/src/pkg/runtime/zmalloc_386.c:92 +0x42
runtime.deferproc(0x4, 0x80ad89d, 0x21a94c5c)
/home/phiggins/go/src/pkg/runtime/proc.c:1311 +0x12
code.google.com/p/go.net/websocket.(*Conn).Write(0x21a94c30,
0x21b00120, 0x1a, 0x1a, 0x0, ...)
/home/phiggins/src/gocode/src/code.google.com/p/go.net/websocket/websocket.go:204
+0x52
geochat/bot.(*Bot).send(0x18a1a240, 0x8056127)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:58 +0x10d
geochat/bot._func_001(0x21add320, 0x18cba578, 0x0)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:153 +0x66
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by geochat/bot.(*Bot).Run
/home/phiggins/src/gocode/src/geochat/bot/bot.go:154 +0x763

goroutine 5978 [chan receive]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.chanrecv(0x818aa30, 0x1c860780, 0xb29e4b48, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/runtime/chan.c:359 +0x1ab
runtime.chanrecv1(0x818aa30, 0x1c860780, 0x72)
/home/phiggins/go/src/pkg/runtime/chan.c:408 +0x2f
net.(*pollServer).WaitRead(0x188e6c90, 0x19af0230, 0x188f1ca0, 0xb)
/home/phiggins/go/src/pkg/net/fd.go:268 +0x75
net.(*netFD).Read(0x19af0230, 0x1c8f1000, 0x1000, 0x1000, 0xffffffff, ...)
/home/phiggins/go/src/pkg/net/fd.go:428 +0x19a
net.(*TCPConn).Read(0x1b23c928, 0x1c8f1000, 0x1000, 0x1000, 0x0, ...)
/home/phiggins/go/src/pkg/net/tcpsock_posix.go:87 +0xb1
bufio.(*Reader).fill(0x1bb295a0, 0x1)
/home/phiggins/go/src/pkg/bufio/bufio.go:77 +0x115
bufio.(*Reader).ReadByte(0x1bb295a0, 0x81e98b8, 0x0, 0x0)
/home/phiggins/go/src/pkg/bufio/bufio.go:166 +0x85
code.google.com/p/go.net/websocket.hybiFrameReaderFactory.NewFrameReader(0x1bb295a0,
0x18f24e40, 0x197030c0, 0x0, 0x0, ...)
/home/phiggins/src/gocode/src/code.google.com/p/go.net/websocket/hybi.go:115
+0x98
code.google.com/p/go.net/websocket.(*Conn).Read(0x21a94c30,
0x21af6000, 0x1000, 0x1000, 0x0, ...)
/home/phiggins/src/gocode/src/code.google.com/p/go.net/websocket/websocket.go:177
+0x87
geochat/bot.(*Bot).recv(0x18a1a240, 0x18cba578)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:77 +0x7a
geochat/bot.(*Bot).Run(0x18a1a240, 0x0, 0x8055350)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:155 +0x781
main._func_002(0x188a3200, 0x18a18420, 0x0)
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:78 +0x4c
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by main.main
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:79 +0x5b7

goroutine 20008 [chan receive]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.chanrecv(0x818aa30, 0x18eb1bc0, 0xb2802ba8, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/runtime/chan.c:359 +0x1ab
runtime.chanrecv1(0x818aa30, 0x18eb1bc0, 0x72)
/home/phiggins/go/src/pkg/runtime/chan.c:408 +0x2f
net.(*pollServer).WaitRead(0x188e6c90, 0x1b93db60, 0x188f1ca0, 0xb)
/home/phiggins/go/src/pkg/net/fd.go:268 +0x75
net.(*netFD).Read(0x1b93db60, 0x18a7f000, 0x1000, 0x1000, 0xffffffff, ...)
/home/phiggins/go/src/pkg/net/fd.go:428 +0x19a
net.(*TCPConn).Read(0x19c6e8c0, 0x18a7f000, 0x1000, 0x1000, 0x0, ...)
/home/phiggins/go/src/pkg/net/tcpsock_posix.go:87 +0xb1
io.(*LimitedReader).Read(0x197893e0, 0x18a7f000, 0x1000, 0x1000, 0x0, ...)
/home/phiggins/go/src/pkg/io/io.go:394 +0xfc
bufio.(*Reader).fill(0x188c1ab0, 0x0)
/home/phiggins/go/src/pkg/bufio/bufio.go:77 +0x115
bufio.(*Reader).ReadSlice(0x188c1ab0, 0x1880000a, 0x0, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/bufio/bufio.go:257 +0x1f3
bufio.(*Reader).ReadLine(0x188c1ab0, 0x0, 0x0, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/bufio/bufio.go:283 +0x43
net/textproto.(*Reader).readLineSlice(0x1a46b220, 0x804fbe9, 0x8)
/home/phiggins/go/src/pkg/net/textproto/reader.go:55 +0x40
net/textproto.(*Reader).ReadLine(0x1a46b220, 0x1e1db3f0, 0xb2802e5c)
/home/phiggins/go/src/pkg/net/textproto/reader.go:36 +0x29
net/http.ReadRequest(0x188c1ab0, 0x1e1db3f0, 0x0, 0x0)
/home/phiggins/go/src/pkg/net/http/request.go:457 +0xa2
net/http.(*conn).readRequest(0x188c1a80, 0x18cecb80, 0x0, 0x0)
/home/phiggins/go/src/pkg/net/http/server.go:240 +0xba
net/http.(*conn).serve(0x188c1a80, 0x18a31300)
/home/phiggins/go/src/pkg/net/http/server.go:594 +0x124
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by net/http.(*Server).Serve
/home/phiggins/go/src/pkg/net/http/server.go:1042 +0x3aa

goroutine 18140 [sleep]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.mallocgc(0x1c, 0x0, 0x0, 0x1, 0x3, ...)
/home/phiggins/go/src/pkg/runtime/zmalloc_386.c:29 +0x374
runtime.malloc(0x1c, 0x80ad813)
/home/phiggins/go/src/pkg/runtime/zmalloc_386.c:92 +0x42
runtime.deferproc(0x4, 0x80ad89d, 0x1e9fd98c)
/home/phiggins/go/src/pkg/runtime/proc.c:1311 +0x12
code.google.com/p/go.net/websocket.(*Conn).Write(0x1e9fd960,
0x21de6bc0, 0x1a, 0x1a, 0x0, ...)
/home/phiggins/src/gocode/src/code.google.com/p/go.net/websocket/websocket.go:204
+0x52
geochat/bot.(*Bot).send(0x18aa2120, 0x8056127)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:58 +0x10d
geochat/bot._func_001(0x21de8920, 0x18d84900, 0x0)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:153 +0x66
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by geochat/bot.(*Bot).Run
/home/phiggins/src/gocode/src/geochat/bot/bot.go:154 +0x763

goroutine 8172 [chan receive]:
runtime.gosched()
/home/phiggins/go/src/pkg/runtime/proc.c:927 +0x56
runtime.chanrecv(0x818aa30, 0x1b18d980, 0xb2136b48, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/runtime/chan.c:359 +0x1ab
runtime.chanrecv1(0x818aa30, 0x1b18d980, 0x72)
/home/phiggins/go/src/pkg/runtime/chan.c:408 +0x2f
net.(*pollServer).WaitRead(0x188e6c90, 0x194b40e0, 0x188f1ca0, 0xb)
/home/phiggins/go/src/pkg/net/fd.go:268 +0x75
net.(*netFD).Read(0x194b40e0, 0x1c865000, 0x1000, 0x1000, 0xffffffff, ...)
/home/phiggins/go/src/pkg/net/fd.go:428 +0x19a
net.(*TCPConn).Read(0x18a0b6d8, 0x1c865000, 0x1000, 0x1000, 0x0, ...)
/home/phiggins/go/src/pkg/net/tcpsock_posix.go:87 +0xb1
bufio.(*Reader).fill(0x1891e960, 0x1)
/home/phiggins/go/src/pkg/bufio/bufio.go:77 +0x115
bufio.(*Reader).ReadByte(0x1891e960, 0x81e98b8, 0x0, 0x0)
/home/phiggins/go/src/pkg/bufio/bufio.go:166 +0x85
code.google.com/p/go.net/websocket.hybiFrameReaderFactory.NewFrameReader(0x1891e960,
0x18f24e40, 0x18b4a300, 0x0, 0x0, ...)
/home/phiggins/src/gocode/src/code.google.com/p/go.net/websocket/hybi.go:115
+0x98
code.google.com/p/go.net/websocket.(*Conn).Read(0x1e9fd960,
0x21deb000, 0x1000, 0x1000, 0x0, ...)
/home/phiggins/src/gocode/src/code.google.com/p/go.net/websocket/websocket.go:177
+0x87
geochat/bot.(*Bot).recv(0x18aa2120, 0x18d84900)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:77 +0x7a
geochat/bot.(*Bot).Run(0x18aa2120, 0x0, 0x8055350)
/home/phiggins/src/gocode/src/geochat/bot/bot.go:155 +0x781
main._func_002(0x188a3200, 0x18aa3040, 0x0)
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:78 +0x4c
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by main.main
/home/phiggins/src/gocode/src/geochat/geobot/geobot.go:79 +0x5b7

goroutine 10004 [syscall]:
runtime.entersyscall()
/home/phiggins/go/src/pkg/runtime/proc.c:952 +0x33
syscall.Syscall6()
/home/phiggins/go/src/pkg/syscall/asm_linux_386.s:46 +0x27
syscall.EpollWait(0x2716, 0x18869f08, 0xa, 0xa, 0xffffffff, ...)
/home/phiggins/go/src/pkg/syscall/zerrors_linux_386.go:1780 +0x7d
net.(*pollster).WaitFD(0x18869f00, 0x188e6c90, 0x0, 0x0, 0x0, ...)
/home/phiggins/go/src/pkg/net/fd_linux.go:146 +0x12b
net.(*pollServer).Run(0x188e6c90, 0x0)
/home/phiggins/go/src/pkg/net/fd.go:236 +0xdf
runtime.goexit()
/home/phiggins/go/src/pkg/runtime/proc.c:271
created by net.newPollServer
/home/phiggins/go/src/pkg/net/newpollserver.go:35 +0x308

[Dmitry Vyukov]

What version of GO are you using?

[Dmitry Vyukov]

>What version of GO are you using?

There was a bug in timers quite some time ago.

May you also show geochat/bot/bot.go?

[Patrick Higgins]

Forwarding to list.

---------- Forwarded message ----------
From: Patrick Higgins <patrick.al...@gmail.com>
Date: Tue, May 29, 2012 at 10:49 AM
Subject: Re: [go-nuts] Re: Deferred mutex unlocks hanging in websocket
To: Dmitry Vyukov <dvy...@google.com>

On Tue, May 29, 2012 at 10:27 AM, Dmitry Vyukov <dvy...@google.com> wrote:
>>What version of GO are you using?
> There was a bug in timers quite some time ago.

The trace above is compiled from tip as of May 25: 13312:40632db23c46.

I can recompile with 1.0.1, but I believe the same problem exists there.

> May you also show geochat/bot/bot.go?

You can find this at http://play.golang.org/p/aj0lpymOMg

[Patrick Higgins]

Forwarding to list. I am not very familiar with Gmail yet.

---------- Forwarded message ----------
From: Patrick Higgins <patrick.al...@gmail.com>
Date: Tue, May 29, 2012 at 10:54 AM
Subject: Re: [go-nuts] Re: Deferred mutex unlocks hanging in websocket
To: Dmitry Vyukov <dvy...@google.com>

On Tue, May 29, 2012 at 10:49 AM, Patrick Higgins
<patrick.al...@gmail.com> wrote:

> On Tue, May 29, 2012 at 10:27 AM, Dmitry Vyukov <dvy...@google.com> wrote:
>> May you also show geochat/bot/bot.go?
>

> You can find this at http://play.golang.org/p/aj0lpymOMg

Pardon, the current version is actually at http://play.golang.org/p/wCKX9LDPZx

[Dmitry Vyukov]

I see the problem. Oooouuuuch!

[Patrick Higgins]

On Tue, May 29, 2012 at 11:04 AM, Dmitry Vyukov <dvy...@google.com> wrote:
> I see the problem. Oooouuuuch!

Is it in my code or the Go runtime? Should I file an issue? I am
working on a simpler test case now.

[Dmitry Vyukov]

Here it is:

http://codereview.appspot.com/6250072

[Patrick Higgins]

Your patch resolves the issue for me. Thanks so much!

This process has been very helpful for me to discover how to poke
around the runtime of a Go process with gdb. Searching for the
locations where g->waitreason is set to "sleep" sure does narrow the
search!