runtime: random fatal errors in runtime

[methane]

Version: tip 8017ace
Program: https://github.com/methane/hellobench.go/blob/master/hello.go
Stack dump: https://gist.github.com/methane/9701f5c7f58e2d701b65
To reproduce:

• run program
• wrk -d1000 -c32 -t800 http://localhost:8080/plaintext

I've encountered this problem two times.
But I forgot to get core file.

Is this known bug?

[methane]

I can reproduce it with more simple code: https://gist.github.com/methane/7f0e381b6bde87dd8469#file-hello-go

$ ~/local/go-dev/bin/go version
go version devel +8017ace Sat May 23 17:42:43 2015 +0000 linux/amd64
$ ~/local/go-dev/bin/go build hello.go
$ GOMAXPROCS=16 ./hello
$ wrk -t4 -c800 http://127.0.0.1:8080/ -d10000

OS is Linux amd64

[methane]

But this time I got different crash message:

runtime: g678: leftover defer sp=0x0 pc=0xc208948800
    defer 0xc208c77140 sp=0x0 pc=0xc208948800
fatal error: traceback has leftover defers

https://gist.github.com/methane/7f0e381b6bde87dd8469#file-crashdump

[davecheney]

Thanks for your report. I have not been able to reproduced either of these crashes yet.

% go version
go version devel +001438b Thu May 21 19:14:03 2015 +0000 linux/amd64

Are you able to reproduce the crash outside the ec2 environment ?

[methane]

I think more concurrency makes easy to reproduce it.
I haven't reproduced it with GOMAXPROCS=4.
But I don't have manycore machine. I always use EC2 when I need power.

[minux]

I can't reproduce any crashes either. Even on a machine with 16 cores. $ go version go version devel +8017ace Sat May 23 17:42:43 2015 +0000 linux/amd64

[dspezia]

I cannot reproduce on small VMs. Will try later on larger ones.
How long do you have to let it run to produce a crash?

$ go version
go version devel +eeb64b7 Sat May 23 05:22:57 2015 +0000 linux/amd64

[dspezia]

I reproduced it on an EC2 instance with 36 vCPUs (and GOMAXPROCS=36), after 10 min of traffic injection at more than 400K r/s (about 200M requests).

runtime: g1645: leftover defer sp=0xdeaddeaddeaddead pc=0x4dfafe
        defer 0xc208257bc0 sp=0xdeaddeaddeaddead pc=0x4dfafe
        defer 0xc2080eeaa0 sp=0xc20a43bc80 pc=0x469ea6
fatal error: traceback has leftover defers

runtime stack:
runtime.throw(0x73c8d0, 0x1d)
        /home/ec2-user/go/src/runtime/panic.go:527 +0x96
runtime.gentraceback(0x428fbc, 0xc20a43b4b0, 0x0, 0xc20a53a280, 0x0, 0x0, 0x7fffffff, 0x7fae5cff8cb8, 0x0, 0x0, ...)
        /home/ec2-user/go/src/runtime/traceback.go:450 +0x7b9
runtime.scanstack(0xc20a53a280)
        /home/ec2-user/go/src/runtime/mgcmark.go:319 +0x28b
runtime.gcphasework(0xc20a53a280)
        /home/ec2-user/go/src/runtime/mgcmark.go:270 +0x5a
runtime.stopg(0xc20a53a280, 0x4)
        /home/ec2-user/go/src/runtime/proc1.go:395 +0x91
runtime.markroot(0xc20801a000, 0x4b6)
        /home/ec2-user/go/src/runtime/mgcmark.go:138 +0x1f2
runtime.parfordo(0xc20801a000)
        /home/ec2-user/go/src/runtime/parfor.go:95 +0x12d
runtime.gcscan_m()
        /home/ec2-user/go/src/runtime/mgcmark.go:37 +0xe1
runtime.gc.func1()
        /home/ec2-user/go/src/runtime/mgc.go:829 +0x5f
runtime.systemstack(0xc20802c000)
        /home/ec2-user/go/src/runtime/asm_amd64.s:262 +0x7c
runtime.mstart()
        /home/ec2-user/go/src/runtime/proc1.go:656

goroutine 194 [garbage collection scan]:
runtime.systemstack_switch()
        /home/ec2-user/go/src/runtime/asm_amd64.s:216 fp=0xc2088a6d90 sp=0xc2088a6d88
runtime.gc(0x0)
        /home/ec2-user/go/src/runtime/mgc.go:841 +0x1dc fp=0xc2088a6fb0 sp=0xc2088a6d90
runtime.backgroundgc()
        /home/ec2-user/go/src/runtime/mgc.go:761 +0x40 fp=0xc2088a6fe0 sp=0xc2088a6fb0
runtime.goexit()
        /home/ec2-user/go/src/runtime/asm_amd64.s:1670 +0x1 fp=0xc2088a6fe8 sp=0xc2088a6fe0
created by runtime.startGC
        /home/ec2-user/go/src/runtime/mgc.go:734 +0x14a
. . .

$ go version
go version devel +8017ace Sat May 23 17:42:43 2015 +0000 linux/amd64

[methane]

When I'm lucky (?), I can reproduce it in 1m30sec.

[RLH]

https://go-review.googlesource.com/#/c/9373/

Are folks using the stress tool? I have found it makes me lucky...

On Sun, May 24, 2015 at 5:49 AM, INADA Naoki notifications@github.com
wrote:

When I'm lucky (?), I can reproduce it in 1m30sec.

—
Reply to this email directly or view it on GitHub
#10941 (comment).

[methane]

@RLH Is it use processes to run parallel test?
I think more GOMAXPROCS make it easier to reproduce it than multi processes.

Here is new code to reproduce. This doesn't require wrk.
https://gist.github.com/methane/a874718dea95cc031f35

I have reproduced once on c4.4xlarge (16cores) within 1 hour.
Crash dump is different from previous code.

fatal error: acquireSudog: found s.elem != nil in cache

goroutine 55 [running]:
runtime.throw(0x75d970, 0x2a)
    /Users/inada-n/local/go/src/runtime/panic.go:527 +0x96 fp=0xc208d8e5a8 sp=0xc208d8e590
runtime.acquireSudog(0xc208e03700)
    /Users/inada-n/local/go/src/runtime/proc.go:232 +0x332 fp=0xc208d8e640 sp=0xc208d8e5a8
runtime.selectgoImpl(0xc208d8e938, 0x0, 0x18)
    /Users/inada-n/local/go/src/runtime/select.go:369 +0x889 fp=0xc208d8e7e8 sp=0xc208d8e640
runtime.selectgo(0xc208d8e938)
    /Users/inada-n/local/go/src/runtime/select.go:212 +0x12 fp=0xc208d8e808 sp=0xc208d8e7e8
net/http.(*persistConn).roundTrip(0xc2080fe000, 0xc2085da420, 0x0, 0x0, 0x0)
    /Users/inada-n/local/go/src/net/http/transport.go:1165 +0x8e1 fp=0xc208d8ea40 sp=0xc208d8e808
net/http.(*Transport).RoundTrip(0xc20806a120, 0xc208100f70, 0xc207ff2546, 0x0, 0x0)
    /Users/inada-n/local/go/src/net/http/transport.go:235 +0x533 fp=0xc208d8eb60 sp=0xc208d8ea40
net/http.send(0xc208100f70, 0x7fdfb4a2b468, 0xc20806a120, 0x16, 0x0, 0x0)
    /Users/inada-n/local/go/src/net/http/client.go:220 +0x4e1 fp=0xc208d8ec58 sp=0xc208d8eb60
net/http.(*Client).send(0x87cd20, 0xc208100f70, 0x16, 0x0, 0x0)
    /Users/inada-n/local/go/src/net/http/client.go:143 +0x15d fp=0xc208d8ed28 sp=0xc208d8ec58
net/http.(*Client).doFollowingRedirects(0x87cd20, 0xc208100f70, 0x78d1d8, 0x0, 0x0, 0x0)
    /Users/inada-n/local/go/src/net/http/client.go:380 +0xbc3 fp=0xc208d8ef28 sp=0xc208d8ed28
net/http.(*Client).Get(0x87cd20, 0xc208010540, 0x16, 0xd, 0x0, 0x0)
    /Users/inada-n/local/go/src/net/http/client.go:306 +0xad fp=0xc208d8ef78 sp=0xc208d8ef28
main.client()
    /Users/inada-n/work/hellobench.go/hello/repro.go:43 +0x44 fp=0xc208d8efe0 sp=0xc208d8ef78
runtime.goexit()
    /Users/inada-n/local/go/src/runtime/asm_amd64.s:1670 +0x1 fp=0xc208d8efe8 sp=0xc208d8efe0
created by main.main
    /Users/inada-n/work/hellobench.go/hello/repro.go:34 +0x122

goroutine 1 [sleep]:
time.Sleep(0x3b9aca00)
    /Users/inada-n/local/go/src/runtime/time.go:59 +0xfc
main.main()
    /Users/inada-n/work/hellobench.go/hello/repro.go:37 +0x142

goroutine 5 [IO wait, 46 minutes]:
net.runtime_pollWait(0x7fdfb4a30590, 0x72, 0xc20800a1a0)
    /Users/inada-n/local/go/src/runtime/netpoll.go:157 +0x63
net.(*pollDesc).Wait(0xc208042140, 0x72, 0x0, 0x0)
...

It was cross compiled on Mac.

$ ~/local/go/bin/go version
go version devel +8017ace Sat May 23 17:42:43 2015 +0000 darwin/amd64

[dspezia]

I have reproduced it with wrk on a physical box (32 HW threads, GOMAXPROCS=32), running SLES11SP2, in 15 minutes. The problem does not only occur on AWS EC2 instances.

runtime: g1256: leftover defer sp=0x0 pc=0xc208fb6800
        defer 0xc208510ec0 sp=0xc20a55c610 pc=0x4dfafe
        defer 0xc2096c4900 sp=0x0 pc=0xc208fb6800
fatal error: unexpected signal during runtime execution
[signal 0xb code=0x1 addr=0x15 pc=0x446634]

runtime stack:
runtime.throw(0x751dd0, 0x2a)
        /data2/ds/local/go/src/runtime/panic.go:527 +0x96
runtime.sigpanic()
        /data2/ds/local/go/src/runtime/sigpanic_unix.go:12 +0x5d
runtime.gentraceback(0x428fbc, 0xc20a55c538, 0x0, 0xc209680780, 0x0, 0x0, 0x7fffffff, 0x7f48ef559c78, 0x0, 0x0, ...)
        /data2/ds/local/go/src/runtime/traceback.go:448 +0x6d4
runtime.scanstack(0xc209680780)
        /data2/ds/local/go/src/runtime/mgcmark.go:319 +0x28b
runtime.gcphasework(0xc209680780)
        /data2/ds/local/go/src/runtime/mgcmark.go:270 +0x5a
runtime.stopg(0xc209680780, 0x1)
        /data2/ds/local/go/src/runtime/proc1.go:395 +0x91
runtime.markroot(0xc20801a060, 0x359)
        /data2/ds/local/go/src/runtime/mgcmark.go:138 +0x1f2
runtime.parfordo(0xc20801a060)
        /data2/ds/local/go/src/runtime/parfor.go:95 +0x12d
runtime.gcscan_m()
        /data2/ds/local/go/src/runtime/mgcmark.go:37 +0xe1
runtime.gc.func1()
        /data2/ds/local/go/src/runtime/mgc.go:829 +0x5f
runtime.systemstack(0xc208036000)
        /data2/ds/local/go/src/runtime/asm_amd64.s:262 +0x7c
runtime.mstart()
        /data2/ds/local/go/src/runtime/proc1.go:656

goroutine 82 [garbage collection scan]: 
runtime.systemstack_switch()
        /data2/ds/local/go/src/runtime/asm_amd64.s:216 fp=0xc2081d0590 sp=0xc2081d0588
runtime.gc(0x0)
        /data2/ds/local/go/src/runtime/mgc.go:841 +0x1dc fp=0xc2081d07b0 sp=0xc2081d0590
runtime.backgroundgc()
        /data2/ds/local/go/src/runtime/mgc.go:761 +0x40 fp=0xc2081d07e0 sp=0xc2081d07b0
runtime.goexit()
        /data2/ds/local/go/src/runtime/asm_amd64.s:1670 +0x1 fp=0xc2081d07e8 sp=0xc2081d07e0
created by runtime.startGC
        /data2/ds/local/go/src/runtime/mgc.go:734 +0x14a

$ go version
go version devel +8017ace Sat May 23 17:42:43 2015 +0000 linux/amd64

[methane]

I reproduced it on 8core machine.
It takes 272min 43sec.

fatal error: unexpected signal during runtime execution
[signal 0xb code=0x1 addr=0x53 pc=0x417c0e]

goroutine 519 [running]:
runtime.throw(0x765d70, 0x2a)
        /Users/inada-n/local/go/src/runtime/panic.go:527 +0x96 fp=0xc20801f530 sp=0xc20801f518
runtime.sigpanic()
        /Users/inada-n/local/go/src/runtime/sigpanic_unix.go:12 +0x5d fp=0xc20801f580 sp=0xc20801f530
runtime.clearpools()
        /Users/inada-n/local/go/src/runtime/mgc.go:1439 +0xce fp=0xc20801f590 sp=0xc20801f580
runtime.gc(0x0)
        /Users/inada-n/local/go/src/runtime/mgc.go:812 +0x165 fp=0xc20801f7b0 sp=0xc20801f590
runtime.backgroundgc()
        /Users/inada-n/local/go/src/runtime/mgc.go:761 +0x40 fp=0xc20801f7e0 sp=0xc20801f7b0
runtime.goexit()
        /Users/inada-n/local/go/src/runtime/asm_amd64.s:1670 +0x1 fp=0xc20801f7e8 sp=0xc20801f7e0
created by runtime.startGC
        /Users/inada-n/local/go/src/runtime/mgc.go:734 +0x14a