Closed mholt closed 4 years ago
This looks like a scheduling problem somehow - I wonder if it is related to the go1.14 preemptive scheduling?
Can you reproduce this on a different OS than macOS?
Can you reproduce it with go1.13? If you can't then it would be worth doing a git bisect
to find the exact breakage.
(interested bystander only :-)
Thanks @ncw! I haven't been able to reproduce it on other OSes, nor have I heard of it surfacing from others using other OSes. However, one other team member @whitestrake has reported this happening on his Mac. I don't know what version or what version of Go, though.
I'll see about doing a Go downgrade but since it requires Go 1.14 I'll have to make some changes to get it to work, first. And it does take some time to get the bug to surface through repeated trials, but I'll post any updates here.
Just a thought... if this is a scheduler problem then you'll likely be able to make it happen quicker with GOMAXPROCS=1
We wonder if you can pull out more info about the goroutine 1
using dlv
. It seems like the goroutine 1
was the only one running (unless go's select
is busted), and unfortunately there is no stack trace.
Couple minor updates: I put the program in a bash loop and am able to easily reproduce it...
FWIW, it's the code on this branch, and I'm running this command (after go build
):
for i in $(seq 1000); ./caddy version; sleep 1; done
If you see any output, the bug didn't manifest. When the bug manifests, there is no output and Activity Monitor shows 100% CPU use for anywhere between 5s to 50s (or maybe longer)
@ncw Nice idea! But after putting GOMAXPROCS=1
, I still see the bug with about the same frequency.
I am really beginning to wonder if it's a bug in Go on macOS. I still need to downgrade to Go 1.13 and try again...
Edit: Simplified reproduce instructions
@mknyszek @heschik suggested GOTRACEBACK=crash
@hyangah Never heard of that... thanks - lots of output!
SIGABRT: abort
PC=0x7fff653cfbba m=2 sigcode=0
goroutine 0 [idle]:
runtime.usleep(0x63fec00002710)
/usr/local/go/src/runtime/sys_darwin.go:239 +0x31 fp=0x700009b78ea8 sp=0x700009b78e80 pc=0x1055c01
runtime.sysmon()
/usr/local/go/src/runtime/proc.go:4473 +0x8d fp=0x700009b78f20 sp=0x700009b78ea8 pc=0x1042f9d
runtime.mstart1()
/usr/local/go/src/runtime/proc.go:1097 +0xc3 fp=0x700009b78f48 sp=0x700009b78f20 pc=0x103ad13
runtime.mstart()
/usr/local/go/src/runtime/proc.go:1062 +0x66 fp=0x700009b78f68 sp=0x700009b78f48 pc=0x103ac36
goroutine 1 [running, locked to thread]:
goroutine running on other thread; stack unavailable
goroutine 2 [force gc (idle)]:
runtime.gopark(0x21497c0, 0x2dac400, 0x1411, 0x1)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc00007afb0 sp=0xc00007af90 pc=0x10387d0
runtime.goparkunlock(...)
/usr/local/go/src/runtime/proc.go:310
runtime.forcegchelper()
/usr/local/go/src/runtime/proc.go:253 +0xb7 fp=0xc00007afe0 sp=0xc00007afb0 pc=0x1038687
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00007afe8 sp=0xc00007afe0 pc=0x1068791
created by runtime.init.6
/usr/local/go/src/runtime/proc.go:242 +0x35
goroutine 3 [GC sweep wait]:
runtime.gopark(0x21497c0, 0x2dad7c0, 0x140c, 0x1)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc00007b7a8 sp=0xc00007b788 pc=0x10387d0
runtime.goparkunlock(...)
/usr/local/go/src/runtime/proc.go:310
runtime.bgsweep(0xc0000a2000)
/usr/local/go/src/runtime/mgcsweep.go:70 +0x9c fp=0xc00007b7d8 sp=0xc00007b7a8 pc=0x102498c
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00007b7e0 sp=0xc00007b7d8 pc=0x1068791
created by runtime.gcenable
/usr/local/go/src/runtime/mgc.go:214 +0x5c
goroutine 4 [GC scavenge wait]:
runtime.gopark(0x21497c0, 0x2dad780, 0x140d, 0x1)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc00007bf78 sp=0xc00007bf58 pc=0x10387d0
runtime.goparkunlock(...)
/usr/local/go/src/runtime/proc.go:310
runtime.bgscavenge(0xc0000a2000)
/usr/local/go/src/runtime/mgcscavenge.go:237 +0xd0 fp=0xc00007bfd8 sp=0xc00007bf78 pc=0x1022f80
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00007bfe0 sp=0xc00007bfd8 pc=0x1068791
created by runtime.gcenable
/usr/local/go/src/runtime/mgc.go:215 +0x7e
goroutine 5 [finalizer wait]:
runtime.gopark(0x21497c0, 0x2ddabf8, 0x71410, 0x1)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc00007a758 sp=0xc00007a738 pc=0x10387d0
runtime.goparkunlock(...)
/usr/local/go/src/runtime/proc.go:310
runtime.runfinq()
/usr/local/go/src/runtime/mfinal.go:175 +0xa3 fp=0xc00007a7e0 sp=0xc00007a758 pc=0x101a623
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00007a7e8 sp=0xc00007a7e0 pc=0x1068791
created by runtime.createfing
/usr/local/go/src/runtime/mfinal.go:156 +0x61
goroutine 19 [select]:
runtime.gopark(0x2149898, 0x0, 0x1809, 0x1)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc00007c5e0 sp=0xc00007c5c0 pc=0x10387d0
runtime.selectgo(0xc00007c750, 0xc00007c734, 0x3, 0x13471c0, 0x206ac01)
/usr/local/go/src/runtime/select.go:316 +0xc73 fp=0xc00007c708 sp=0xc00007c5e0 pc=0x10489b3
go.opencensus.io/stats/view.(*worker).start(0xc000138fa0)
/Users/matt/go/pkg/mod/go.opencensus.io@v0.22.2/stats/view/worker.go:154 +0x100 fp=0xc00007c7d8 sp=0xc00007c708 pc=0x17f0620
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00007c7e0 sp=0xc00007c7d8 pc=0x1068791
created by go.opencensus.io/stats/view.init.0
/Users/matt/go/pkg/mod/go.opencensus.io@v0.22.2/stats/view/worker.go:32 +0x57
goroutine 20 [select]:
runtime.gopark(0x2149898, 0x0, 0x1809, 0x1)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000076520 sp=0xc000076500 pc=0x10387d0
runtime.selectgo(0xc000076688, 0xc000076674, 0x3, 0x0, 0x0)
/usr/local/go/src/runtime/select.go:316 +0xc73 fp=0xc000076648 sp=0xc000076520 pc=0x10489b3
github.com/caddyserver/certmagic.(*RingBufferRateLimiter).permit(0xc000139270)
/Users/matt/Dev/certmagic/ratelimiter.go:192 +0xe1 fp=0xc000076710 sp=0xc000076648 pc=0x14c4061
github.com/caddyserver/certmagic.(*RingBufferRateLimiter).loop(0xc000139270)
/Users/matt/Dev/certmagic/ratelimiter.go:65 +0x7a fp=0xc0000767d8 sp=0xc000076710 pc=0x14c36ca
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000767e0 sp=0xc0000767d8 pc=0x1068791
created by github.com/caddyserver/certmagic.NewRateLimiter
/Users/matt/Dev/certmagic/ratelimiter.go:29 +0x145
goroutine 34 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc00020a030, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000636760 sp=0xc000636740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc00004e000)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0006367d8 sp=0xc000636760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0006367e0 sp=0xc0006367d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 21 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc0003e7410, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000076f60 sp=0xc000076f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000050800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000076fd8 sp=0xc000076f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000076fe0 sp=0xc000076fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 22 [GC worker (idle)]:
runtime.systemstack_switch()
/usr/local/go/src/runtime/asm_amd64.s:330 fp=0xc000077708 sp=0xc000077700 pc=0x10666a0
runtime.gcMarkDone()
/usr/local/go/src/runtime/mgc.go:1441 +0xbb fp=0xc000077760 sp=0xc000077708 pc=0x101d0bb
runtime.gcBgMarkWorker(0xc000053000)
/usr/local/go/src/runtime/mgc.go:1992 +0x29e fp=0xc0000777d8 sp=0xc000077760 pc=0x101e17e
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000777e0 sp=0xc0000777d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 50 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc0003e7420, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000632760 sp=0xc000632740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000055800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0006327d8 sp=0xc000632760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0006327e0 sp=0xc0006327d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 23 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc000291020, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000077f60 sp=0xc000077f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000058000)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000077fd8 sp=0xc000077f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000077fe0 sp=0xc000077fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 51 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc00020a040, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000632f60 sp=0xc000632f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc00005a800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000632fd8 sp=0xc000632f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000632fe0 sp=0xc000632fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 52 [semacquire]:
runtime.gopark(0x21497c0, 0x2db4680, 0xc000781912, 0x4)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc0006336a0 sp=0xc000633680 pc=0x10387d0
runtime.goparkunlock(...)
/usr/local/go/src/runtime/proc.go:310
runtime.semacquire1(0x2daf134, 0xc000700000, 0x0, 0x0)
/usr/local/go/src/runtime/sema.go:144 +0x1c0 fp=0xc000633708 sp=0xc0006336a0 pc=0x10494f0
runtime.semacquire(...)
/usr/local/go/src/runtime/sema.go:95
runtime.gcMarkDone()
/usr/local/go/src/runtime/mgc.go:1425 +0x3e fp=0xc000633760 sp=0xc000633708 pc=0x101d03e
runtime.gcBgMarkWorker(0xc00005d000)
/usr/local/go/src/runtime/mgc.go:1992 +0x29e fp=0xc0006337d8 sp=0xc000633760 pc=0x101e17e
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0006337e0 sp=0xc0006337d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 53 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc0003e7430, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000633f60 sp=0xc000633f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc00005f800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000633fd8 sp=0xc000633f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000633fe0 sp=0xc000633fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 24 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc000291040, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000078760 sp=0xc000078740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000062000)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0000787d8 sp=0xc000078760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000787e0 sp=0xc0000787d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 54 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc000291050, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000634760 sp=0xc000634740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000064800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0006347d8 sp=0xc000634760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0006347e0 sp=0xc0006347d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 35 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc0003e7440, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000636f60 sp=0xc000636f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000067000)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000636fd8 sp=0xc000636f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000636fe0 sp=0xc000636fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 55 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc00020a050, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000634f60 sp=0xc000634f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000069800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000634fd8 sp=0xc000634f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000634fe0 sp=0xc000634fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 56 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc00020a060, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000635760 sp=0xc000635740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc00006c000)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0006357d8 sp=0xc000635760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0006357e0 sp=0xc0006357d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 25 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc0003e7450, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000078f60 sp=0xc000078f40 pc=0x10387d0
runtime.gcBgMarkWorker(0xc00006e800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc000078fd8 sp=0xc000078f60 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000078fe0 sp=0xc000078fd8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 26 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc00020a070, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000079760 sp=0xc000079740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000071000)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0000797d8 sp=0xc000079760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000797e0 sp=0xc0000797d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
goroutine 36 [GC worker (idle)]:
runtime.gopark(0x2149610, 0xc000291060, 0x1418, 0x0)
/usr/local/go/src/runtime/proc.go:304 +0xe0 fp=0xc000637760 sp=0xc000637740 pc=0x10387d0
runtime.gcBgMarkWorker(0xc000073800)
/usr/local/go/src/runtime/mgc.go:1865 +0xff fp=0xc0006377d8 sp=0xc000637760 pc=0x101dfdf
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0006377e0 sp=0xc0006377d8 pc=0x1068791
created by runtime.gcBgMarkStartWorkers
/usr/local/go/src/runtime/mgc.go:1813 +0x77
rax 0x4
rbx 0x0
rcx 0x700009b78d88
rdx 0x1
rdi 0x1403
rsi 0x0
rbp 0x700009b78dc0
rsp 0x700009b78d88
r8 0x0
r9 0x989680
r10 0x1
r11 0x246
r12 0x0
r13 0x0
r14 0x0
r15 0x700009b78dd0
rip 0x7fff653cfbba
rflags 0x247
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=3 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_timedwait_relative_np(0xc00007eb88, 0xc00007eb48, 0x700009bfbe18, 0x0)
/usr/local/go/src/runtime/sys_darwin.go:397 +0x39 fp=0x700009bfbdf0 sp=0x700009bfbdc8 pc=0x1056229
runtime.semasleep(0x186a0, 0x117c3dc0)
/usr/local/go/src/runtime/os_darwin.go:57 +0x10c fp=0x700009bfbe48 sp=0x700009bfbdf0 pc=0x1032c2c
runtime.notetsleep_internal(0x2daed30, 0x186a0, 0xc000000d80, 0x63fecf64f3739, 0xc00004c000)
/usr/local/go/src/runtime/lock_sema.go:224 +0x10d fp=0x700009bfbe78 sp=0x700009bfbe48 pc=0x100d13d
runtime.notetsleep(0x2daed30, 0x186a0, 0x7fffffffffffff00)
/usr/local/go/src/runtime/lock_sema.go:275 +0x58 fp=0x700009bfbeb0 sp=0x700009bfbe78 pc=0x100d2f8
runtime.forEachP(0x2149620)
/usr/local/go/src/runtime/proc.go:1292 +0x2fc fp=0x700009bfbf18 sp=0x700009bfbeb0 pc=0x103b33c
runtime.gcMarkDone.func1()
/usr/local/go/src/runtime/mgc.go:1448 +0x5e fp=0x700009bfbf40 sp=0x700009bfbf18 pc=0x106357e
runtime.systemstack(0x3300000)
/usr/local/go/src/runtime/asm_amd64.s:370 +0x66 fp=0x700009bfbf48 sp=0x700009bfbf40 pc=0x1066716
runtime.mstart()
/usr/local/go/src/runtime/proc.go:1041 fp=0x700009bfbf50 sp=0x700009bfbf48 pc=0x103abd0
rax 0x104
rbx 0x2000
rcx 0x700009bfbc98
rdx 0x2000
rdi 0xc00007eb88
rsi 0xc9e30100c9e400
rbp 0x700009bfbd30
rsp 0x700009bfbc98
r8 0x0
r9 0xa0
r10 0x0
r11 0x246
r12 0xc00007eb88
r13 0x16
r14 0xc9e30100c9e400
r15 0xc9e400
rip 0x7fff653cfce6
rflags 0x247
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=4 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc00007ef88, 0xc00007ef48, 0x0)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x700009c7ed08 sp=0x700009c7ece0 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x200)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x700009c7ed60 sp=0x700009c7ed08 pc=0x1032ba5
runtime.notesleep(0xc00007ed48)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x700009c7ed98 sp=0x700009c7ed60 pc=0x100cfd0
runtime.stopm()
/usr/local/go/src/runtime/proc.go:1828 +0xc0 fp=0x700009c7edc0 sp=0x700009c7ed98 pc=0x103c0d0
runtime.findrunnable(0xc00004e000, 0x0)
/usr/local/go/src/runtime/proc.go:2360 +0xa0d fp=0x700009c7eea8 sp=0x700009c7edc0 pc=0x103d6ed
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x700009c7ef10 sp=0x700009c7eea8 pc=0x103e22c
runtime.park_m(0xc0002f2180)
/usr/local/go/src/runtime/proc.go:2690 +0x9d fp=0x700009c7ef40 sp=0x700009c7ef10 pc=0x103e7ad
runtime.mcall(0x80000)
/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b fp=0x700009c7ef50 sp=0x700009c7ef40 pc=0x106668b
rax 0x104
rbx 0x2
rcx 0x700009c7eba8
rdx 0x3100
rdi 0xc00007ef88
rsi 0x310100003200
rbp 0x700009c7ec40
rsp 0x700009c7eba8
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc00007ef88
r13 0x16
r14 0x310100003200
r15 0x700009c7f000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=0 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0x2dafbc8, 0x2dafb88, 0x7ffe00000000)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x7ffeefbff628 sp=0x7ffeefbff600 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x7ffeefbff6a8)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x7ffeefbff680 sp=0x7ffeefbff628 pc=0x1032ba5
runtime.notesleep(0x2daf988)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x7ffeefbff6b8 sp=0x7ffeefbff680 pc=0x100cfd0
runtime.stoplockedm()
/usr/local/go/src/runtime/proc.go:1971 +0x88 fp=0x7ffeefbff6f8 sp=0x7ffeefbff6b8 pc=0x103c768
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2454 +0x4a6 fp=0x7ffeefbff760 sp=0x7ffeefbff6f8 pc=0x103e3d6
runtime.goschedImpl(0xc000000180)
/usr/local/go/src/runtime/proc.go:2705 +0xd6 fp=0x7ffeefbff798 sp=0x7ffeefbff760 pc=0x103e9a6
runtime.gopreempt_m(0xc000000180)
/usr/local/go/src/runtime/proc.go:2733 +0x34 fp=0x7ffeefbff7d0 sp=0x7ffeefbff798 pc=0x103ebf4
runtime.newstack()
/usr/local/go/src/runtime/stack.go:1025 +0x1ae fp=0x7ffeefbff960 sp=0x7ffeefbff7d0 pc=0x104fd4e
runtime.morestack()
/usr/local/go/src/runtime/asm_amd64.s:449 +0x8f fp=0x7ffeefbff968 sp=0x7ffeefbff960 pc=0x10667ef
rax 0x104
rbx 0x2
rcx 0x7ffeefbff4c8
rdx 0x3900
rdi 0x2dafbc8
rsi 0x390100003a00
rbp 0x7ffeefbff560
rsp 0x7ffeefbff4c8
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0x2dafbc8
r13 0x16
r14 0x390100003a00
r15 0x117c3dc0
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=5 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc000100388, 0xc000100348, 0x0)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x700009d01d08 sp=0x700009d01ce0 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x103e675)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x700009d01d60 sp=0x700009d01d08 pc=0x1032ba5
runtime.notesleep(0xc000100148)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x700009d01d98 sp=0x700009d01d60 pc=0x100cfd0
runtime.stopm()
/usr/local/go/src/runtime/proc.go:1828 +0xc0 fp=0x700009d01dc0 sp=0x700009d01d98 pc=0x103c0d0
runtime.findrunnable(0xc000050800, 0x0)
/usr/local/go/src/runtime/proc.go:2360 +0xa0d fp=0x700009d01ea8 sp=0x700009d01dc0 pc=0x103d6ed
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x700009d01f10 sp=0x700009d01ea8 pc=0x103e22c
runtime.park_m(0xc000102900)
/usr/local/go/src/runtime/proc.go:2690 +0x9d fp=0x700009d01f40 sp=0x700009d01f10 pc=0x103e7ad
runtime.mcall(0x80000)
/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b fp=0x700009d01f50 sp=0x700009d01f40 pc=0x106668b
rax 0x104
rbx 0x2
rcx 0x700009d01ba8
rdx 0x3000
rdi 0xc000100388
rsi 0x300100003100
rbp 0x700009d01c40
rsp 0x700009d01ba8
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc000100388
r13 0x16
r14 0x300100003100
r15 0x700009d02000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=6 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc00007f388, 0xc00007f348, 0x700000000000)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x700009d84e70 sp=0x700009d84e48 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x700009d84ef8)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x700009d84ec8 sp=0x700009d84e70 pc=0x1032ba5
runtime.notesleep(0x2ddb4b8)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x700009d84f00 sp=0x700009d84ec8 pc=0x100cfd0
runtime.templateThread()
/usr/local/go/src/runtime/proc.go:1806 +0xf2 fp=0x700009d84f20 sp=0x700009d84f00 pc=0x103bff2
runtime.mstart1()
/usr/local/go/src/runtime/proc.go:1097 +0xc3 fp=0x700009d84f48 sp=0x700009d84f20 pc=0x103ad13
runtime.mstart()
/usr/local/go/src/runtime/proc.go:1062 +0x66 fp=0x700009d84f68 sp=0x700009d84f48 pc=0x103ac36
rax 0x104
rbx 0x2
rcx 0x700009d84d18
rdx 0x0
rdi 0xc00007f388
rsi 0x100000100
rbp 0x700009d84db0
rsp 0x700009d84d18
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc00007f388
r13 0x16
r14 0x100000100
r15 0x700009d85000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653d1bce m=7 sigcode=0
goroutine 0 [idle]:
runtime.kevent(0x5, 0x0, 0x0, 0x700009e075b0, 0x40, 0x700009e07588, 0x0)
/usr/local/go/src/runtime/sys_darwin.go:355 +0x39 fp=0x700009e07538 sp=0x700009e07510 pc=0x1056049
runtime.netpoll(0x253fe3399, 0x63feb66166c01)
/usr/local/go/src/runtime/netpoll_kqueue.go:120 +0xae fp=0x700009e07dc0 sp=0x700009e07538 pc=0x103277e
runtime.findrunnable(0xc000053000, 0x0)
/usr/local/go/src/runtime/proc.go:2323 +0x72b fp=0x700009e07ea8 sp=0x700009e07dc0 pc=0x103d40b
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x700009e07f10 sp=0x700009e07ea8 pc=0x103e22c
runtime.park_m(0xc000001980)
/usr/local/go/src/runtime/proc.go:2690 +0x9d fp=0x700009e07f40 sp=0x700009e07f10 pc=0x103e7ad
runtime.mcall(0x80000)
/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b fp=0x700009e07f50 sp=0x700009e07f40 pc=0x106668b
rax 0x4
rbx 0x700009e07538
rcx 0x700009e07478
rdx 0x0
rdi 0x5
rsi 0x0
rbp 0x700009e07480
rsp 0x700009e07478
r8 0x40
r9 0x700009e07588
r10 0x700009e075b0
r11 0x206
r12 0x3
r13 0xc000102480
r14 0x2301928
r15 0x0
rip 0x7fff653d1bce
rflags 0x207
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=8 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc000216388, 0xc000216348, 0x700000000000)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x700009e8ad08 sp=0x700009e8ace0 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x103e675)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x700009e8ad60 sp=0x700009e8ad08 pc=0x1032ba5
runtime.notesleep(0xc000216148)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x700009e8ad98 sp=0x700009e8ad60 pc=0x100cfd0
runtime.stopm()
/usr/local/go/src/runtime/proc.go:1828 +0xc0 fp=0x700009e8adc0 sp=0x700009e8ad98 pc=0x103c0d0
runtime.findrunnable(0xc000058000, 0x0)
/usr/local/go/src/runtime/proc.go:2360 +0xa0d fp=0x700009e8aea8 sp=0x700009e8adc0 pc=0x103d6ed
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x700009e8af10 sp=0x700009e8aea8 pc=0x103e22c
runtime.park_m(0xc000102c00)
/usr/local/go/src/runtime/proc.go:2690 +0x9d fp=0x700009e8af40 sp=0x700009e8af10 pc=0x103e7ad
runtime.mcall(0x80000)
/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b fp=0x700009e8af50 sp=0x700009e8af40 pc=0x106668b
rax 0x104
rbx 0x2
rcx 0x700009e8aba8
rdx 0x0
rdi 0xc000216388
rsi 0x100000100
rbp 0x700009e8ac40
rsp 0x700009e8aba8
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc000216388
r13 0x16
r14 0x100000100
r15 0x700009e8b000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=9 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc0006c0388, 0xc0006c0348, 0x700000000000)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x700009f0dd08 sp=0x700009f0dce0 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x10010101)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x700009f0dd60 sp=0x700009f0dd08 pc=0x1032ba5
runtime.notesleep(0xc0006c0148)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x700009f0dd98 sp=0x700009f0dd60 pc=0x100cfd0
runtime.stopm()
/usr/local/go/src/runtime/proc.go:1828 +0xc0 fp=0x700009f0ddc0 sp=0x700009f0dd98 pc=0x103c0d0
runtime.findrunnable(0xc00005a800, 0x0)
/usr/local/go/src/runtime/proc.go:2360 +0xa0d fp=0x700009f0dea8 sp=0x700009f0ddc0 pc=0x103d6ed
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x700009f0df10 sp=0x700009f0dea8 pc=0x103e22c
runtime.park_m(0xc000214180)
/usr/local/go/src/runtime/proc.go:2690 +0x9d fp=0x700009f0df40 sp=0x700009f0df10 pc=0x103e7ad
runtime.mcall(0x80000)
/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b fp=0x700009f0df50 sp=0x700009f0df40 pc=0x106668b
rax 0x104
rbx 0x2
rcx 0x700009f0dba8
rdx 0x0
rdi 0xc0006c0388
rsi 0x100000100
rbp 0x700009f0dc40
rsp 0x700009f0dba8
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc0006c0388
r13 0x16
r14 0x100000100
r15 0x700009f0e000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=11 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc000642388, 0xc000642348, 0x7fff00000000)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x700009f90d18 sp=0x700009f90cf0 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0x103e675)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x700009f90d70 sp=0x700009f90d18 pc=0x1032ba5
runtime.notesleep(0xc000642148)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x700009f90da8 sp=0x700009f90d70 pc=0x100cfd0
runtime.stopm()
/usr/local/go/src/runtime/proc.go:1828 +0xc0 fp=0x700009f90dd0 sp=0x700009f90da8 pc=0x103c0d0
runtime.findrunnable(0xc00005f800, 0x0)
/usr/local/go/src/runtime/proc.go:2360 +0xa0d fp=0x700009f90eb8 sp=0x700009f90dd0 pc=0x103d6ed
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x700009f90f20 sp=0x700009f90eb8 pc=0x103e22c
runtime.mstart1()
/usr/local/go/src/runtime/proc.go:1104 +0x8e fp=0x700009f90f48 sp=0x700009f90f20 pc=0x103acde
runtime.mstart()
/usr/local/go/src/runtime/proc.go:1062 +0x66 fp=0x700009f90f68 sp=0x700009f90f48 pc=0x103ac36
rax 0x104
rbx 0x2
rcx 0x700009f90bb8
rdx 0x100
rdi 0xc000642388
rsi 0x10100000200
rbp 0x700009f90c50
rsp 0x700009f90bb8
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc000642388
r13 0x16
r14 0x10100000200
r15 0x700009f91000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
\-----
SIGQUIT: quit
PC=0x7fff653cfce6 m=10 sigcode=0
goroutine 0 [idle]:
runtime.pthread_cond_wait(0xc000700388, 0xc000700348, 0x0)
/usr/local/go/src/runtime/sys_darwin.go:390 +0x39 fp=0x70000a013ce0 sp=0x70000a013cb8 pc=0x10561d9
runtime.semasleep(0xffffffffffffffff, 0xc000700000)
/usr/local/go/src/runtime/os_darwin.go:63 +0x85 fp=0x70000a013d38 sp=0x70000a013ce0 pc=0x1032ba5
runtime.notesleep(0xc000700148)
/usr/local/go/src/runtime/lock_sema.go:173 +0xe0 fp=0x70000a013d70 sp=0x70000a013d38 pc=0x100cfd0
runtime.stopm()
/usr/local/go/src/runtime/proc.go:1828 +0xc0 fp=0x70000a013d98 sp=0x70000a013d70 pc=0x103c0d0
runtime.gcstopm()
/usr/local/go/src/runtime/proc.go:2028 +0xb4 fp=0x70000a013dc0 sp=0x70000a013d98 pc=0x103cb14
runtime.findrunnable(0xc00005d000, 0x0)
/usr/local/go/src/runtime/proc.go:2085 +0x82b fp=0x70000a013ea8 sp=0x70000a013dc0 pc=0x103d50b
runtime.schedule()
/usr/local/go/src/runtime/proc.go:2520 +0x2fc fp=0x70000a013f10 sp=0x70000a013ea8 pc=0x103e22c
runtime.park_m(0xc000214300)
/usr/local/go/src/runtime/proc.go:2690 +0x9d fp=0x70000a013f40 sp=0x70000a013f10 pc=0x103e7ad
runtime.mcall(0x80000)
/usr/local/go/src/runtime/asm_amd64.s:318 +0x5b fp=0x70000a013f50 sp=0x70000a013f40 pc=0x106668b
rax 0x104
rbx 0x2
rcx 0x70000a013b88
rdx 0x100
rdi 0xc000700388
rsi 0x10100000200
rbp 0x70000a013c20
rsp 0x70000a013b88
r8 0x0
r9 0xa0
r10 0x0
r11 0x202
r12 0xc000700388
r13 0x16
r14 0x10100000200
r15 0x70000a014000
rip 0x7fff653cfce6
rflags 0x203
cs 0x7
fs 0x0
gs 0x0
I've also updated my instructions above to make it much simpler and faster to reproduce, using caddy version
. /cc @maraino
Here's what it looks like when it happens
Strange. If goroutine 1 is running, I don't know why only g0s are showing up in the crash traceback. Maybe there really is a scheduler bug??
I'm now running my loop on a build that does not depend on smallstep or, by extension, opencensus -- and it has run hundreds of times now and not triggered the bug. Re-adding it, and re-building, I can trigger it in about 30-60 seconds using that loop.
So far, I'm fairly convinced that it's a bug in opencensus or smallstep, my dependency that depends on opencensus. There's a chance that it's a bug in the way smallstep is using/initializing opencensus? but I don't know much about that.
If it is a Go bug, it seems dependent on importing smallstep+opencensus.
Upon downgrading to Go 1.13(.8) and recompiling and running the loop again, the bug does not manifest after hundreds of trials.
When I switch back to the binary built by Go 1.14, the bug manifests in about 10 iterations or so.
So, this might very well be a bug in Go.
Anyone know what to do now?
Sorry if this isn't directly related to your repo -- I was led here because of a stray goroutine in the stack trace -- I dunno, maybe Go is spinning on the select
when it shouldn't be? Anyway, thanks for the help, this is a new one to me.
If it only happens in 1.14, what happens if you set GODEBUG=asyncpreemptoff=1
to disable the new async preemption?
@zikaeroh Interesting! I switched back to Go 1.14. And the bug does not manifest when using GODEBUG=asyncpreemptoff=1
.
I have now run the loop several times with and without that variable set.
Makes sense. Should probably mirror that feedback on the Go tracker (as I assume that's where they will actually want to discuss things if this is definitely another item on the async preemption bug tail).
Okay, this is probably not a bug in opencensus after all -- it's still unclear why importing this package and/or smallstep seems necessary to trigger the bug, but since the bug is being discussed upstream in the Go issue tracker, I will close this. (Noting, however, that some original evidence appears in this issue, so it should still be linked to.)
Please answer these questions before submitting a bug report.
What version of OpenCensus are you using?
v0.22.2
What version of Go are you using?
What did you do?
I'm using a dependency that uses a dependency that apparently uses opencensus-go.
It seems that importing the package
go.opencensus.io@v0.22.2/stats/view
is enough to trigger the bug. I noticed that mymain()
is never called, the CPU is spinning at 100%, and memory usage seems stable.By running
pkill -ABRT main
during the spin, I can get a stack trace:What did you expect to see?
The CPU to not spin at
init()
time, and the program to run.What did you see instead?
Sometimes, the CPU spins at 100% and my
main()
is never called. The program is stuck in the goroutine described by the stack trace above.Additional context
I cannot reliably reproduce it, just have to run the program a bunch of times, but it faithfully appears often enough.
I can't explain why this is happening, but I can only draw conclusions from the stack trace I pasted above. (They all look like that.)
When I eliminate the dependency that depends on this package, I cannot reproduce the spin anymore after many dozens of trials. (Usually it appears after about 10-20.
Related to #1074.
Edit: I have just noticed that the only goroutine that is
running
at the time of the dump isgoroutine 1
, according to the stack trace. Unfortunately it has no information as to what is being executed there... but when I no longer depend on opencensus-go, the problem disappears...init()
function, is there any package-level variable initializations (var ... = ...) that could possibly cause the CPU to spin?