Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: panic: non-empty mark queue after concurrent mark (Go1.14, Go1.15) #41303

Open
navytux opened this issue Sep 9, 2020 · 19 comments
Open

runtime: panic: non-empty mark queue after concurrent mark (Go1.14, Go1.15) #41303

navytux opened this issue Sep 9, 2020 · 19 comments

Comments

@navytux
Copy link
Contributor

@navytux navytux commented Sep 9, 2020

Hello up there.

Today, while working on wendelin.core I've got panic: non-empty mark queue after concurrent mark several times while running unit tests. It is hard for me to find time to try to reduce the problem to minimal example, but I just cannot ignore such garbage collector kind of bug, so I decided to report at least what I can. Please find details about GC crash below. I also attach dumped core in case it could be useful to analyse what was going on (no confidential data in there).

Thanks beforehand,
Kirill

What version of Go are you using (go version)?

$ go version
go version go1.15.2 linux/amd64

Does this issue reproduce with the latest release?

No data

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE="off"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/kirr/.cache/go-build"
GOENV="/home/kirr/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/kirr/src/neo/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/kirr/src/neo:/home/kirr/src/tools/go/g.env"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/kirr/src/tools/go/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/kirr/src/tools/go/go/pkg/tool/linux_amd64"
GCCGO="/usr/bin/gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build670581309=/tmp/go-build -gno-record-gcc-switches"
GOROOT/bin/go version: go version go1.15.2 linux/amd64
GOROOT/bin/go tool compile -V: compile version go1.15.2
uname -sr: Linux 5.7.0-3-amd64
Distributor ID:	Debian
Description:	Debian GNU/Linux bullseye/sid
Release:	testing
Codename:	bullseye
/lib/x86_64-linux-gnu/libc.so.6: GNU C Library (Debian GLIBC 2.31-3) stable release version 2.31.
gdb --version: GNU gdb (Debian 9.2-1) 9.2

What did you do?

What did you expect to see?

No Go runtime crashes

What did you see instead?

Go runtime crashed with

runtime: full=0xc0003d3800000e next=167 jobs=164 nDataRoots=1 nBSSRoots=1 nSpanRoots=16 nStackRoots=144
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack
full output

...
=== RUN   TestZBlk
2020/09/09 22:29:15 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestZBlk (0.02s)
=== RUN   TestΔBTail
2020/09/09 22:29:16 zodb: FIXME: open /tmp/δBTail797036932/1.fs: raw cache is not ready for invalidations -> NoCache forced
runtime: full=0xc0003d3800000e next=167 jobs=164 nDataRoots=1 nBSSRoots=1 nSpanRoots=16 nStackRoots=144
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack

runtime stack:
runtime.throw(0x79c93c, 0x15)
        /home/kirr/src/tools/go/go/src/runtime/panic.go:1116 +0x72 fp=0x7f0ea311cd10 sp=0x7f0ea311cce0 pc=0x43abf2
panic(0x70d360, 0x7f4070)
        /home/kirr/src/tools/go/go/src/runtime/panic.go:895 +0x750 fp=0x7f0ea311cdc8 sp=0x7f0ea311cd10 pc=0x43aaf0
runtime.gcMark(0x2036b5d1c005)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:2064 +0x539 fp=0x7f0ea311ce60 sp=0x7f0ea311cdc8 pc=0x421239
runtime.gcMarkTermination.func1()
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1656 +0x2a fp=0x7f0ea311ce78 sp=0x7f0ea311ce60 pc=0x46868a
runtime.systemstack(0x7f0e98000020)
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:370 +0x66 fp=0x7f0ea311ce80 sp=0x7f0ea311ce78 pc=0x4701a6
runtime.mstart()
        /home/kirr/src/tools/go/go/src/runtime/proc.go:1116 fp=0x7f0ea311ce88 sp=0x7f0ea311ce80 pc=0x43fdc0
goroutine 99 [garbage collection]:
runtime.systemstack_switch()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:330 fp=0xc00002e548 sp=0xc00002e540 pc=0x470120
runtime.gcMarkTermination(0x3ff699bb8842651e)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1655 +0x17b fp=0xc00002e708 sp=0xc00002e548 pc=0x41fcfb
runtime.gcMarkDone()
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1630 +0x275 fp=0xc00002e760 sp=0xc00002e708 pc=0x41fab5
runtime.gcBgMarkWorker(0xc00002b800)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:2018 +0x2af fp=0xc00002e7d8 sp=0xc00002e760 pc=0x420acf
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00002e7e0 sp=0xc00002e7d8 pc=0x471f01
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 1 [chan receive]:
runtime.gopark(0x7af8c0, 0xc000224118, 0x50170e, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0000a4b58 sp=0xc0000a4b38 pc=0x43d7e5
runtime.chanrecv(0xc0002240c0, 0xc0000a4c57, 0xc000000101, 0x5032e6)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:567 +0x365 fp=0xc0000a4be8 sp=0xc0000a4b58 pc=0x409d45
runtime.chanrecv1(0xc0002240c0, 0xc0000a4c57)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:434 +0x2b fp=0xc0000a4c18 sp=0xc0000a4be8 pc=0x40998b
testing.(*T).Run(0xc000082d80, 0x798700, 0xb, 0x7aeb88, 0x493c01)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1179 +0x3ad fp=0xc0000a4cb0 sp=0xc0000a4c18 pc=0x50330d
testing.runTests.func1(0xc000001b00)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1449 +0x78 fp=0xc0000a4d00 sp=0xc0000a4cb0 pc=0x507718
testing.tRunner(0xc000001b00, 0xc000141de0)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1127 +0xef fp=0xc0000a4d50 sp=0xc0000a4d00 pc=0x502ecf
testing.runTests(0xc00000e9c0, 0x99f2a0, 0x6, 0x6, 0xbfce69b8da4fa4a3, 0x8bb2dad0e0, 0x9d3580, 0x410e30)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1447 +0x2e8 fp=0xc0000a4e10 sp=0xc0000a4d50 pc=0x504b28
testing.(*M).Run(0xc00015c080, 0x0)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1357 +0x245 fp=0xc0000a4f20 sp=0xc0000a4e10 pc=0x5038c5
main.main()
        _testmain.go:53 +0x138 fp=0xc0000a4f88 sp=0xc0000a4f20 pc=0x6dd4b8
runtime.main()
        /home/kirr/src/tools/go/go/src/runtime/proc.go:204 +0x209 fp=0xc0000a4fe0 sp=0xc0000a4f88 pc=0x43d3e9
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000a4fe8 sp=0xc0000a4fe0 pc=0x471f01

goroutine 2 [force gc (idle)]:
runtime.gopark(0x7afad8, 0x9d2c00, 0x1411, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000032fb0 sp=0xc000032f90 pc=0x43d7e5
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.forcegchelper()
        /home/kirr/src/tools/go/go/src/runtime/proc.go:255 +0xc5 fp=0xc000032fe0 sp=0xc000032fb0 pc=0x43d685
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000032fe8 sp=0xc000032fe0 pc=0x471f01
created by runtime.init.6
        /home/kirr/src/tools/go/go/src/runtime/proc.go:243 +0x35

goroutine 3 [GC sweep wait]:
runtime.gopark(0x7afad8, 0x9d2dc0, 0x140c, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0000337a8 sp=0xc000033788 pc=0x43d7e5
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.bgsweep(0xc00005a000)
        /home/kirr/src/tools/go/go/src/runtime/mgcsweep.go:182 +0x13b fp=0xc0000337d8 sp=0xc0000337a8 pc=0x427f1b
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000337e0 sp=0xc0000337d8 pc=0x471f01
created by runtime.gcenable
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:217 +0x5c

goroutine 4 [sleep]:
runtime.gopark(0x7afad8, 0x9d31e0, 0x1313, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000033f20 sp=0xc000033f00 pc=0x43d7e5
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.scavengeSleep(0x11015e, 0x40804)
        /home/kirr/src/tools/go/go/src/runtime/mgcscavenge.go:241 +0xc5 fp=0xc000033f78 sp=0xc000033f20 pc=0x425da5
runtime.bgscavenge(0xc00005a000)
        /home/kirr/src/tools/go/go/src/runtime/mgcscavenge.go:366 +0x1e5 fp=0xc000033fd8 sp=0xc000033f78 pc=0x425fc5
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000033fe0 sp=0xc000033fd8 pc=0x471f01
created by runtime.gcenable
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:218 +0x7e

goroutine 5 [finalizer wait]:
runtime.gopark(0x7afad8, 0xa05678, 0xc000221410, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000034758 sp=0xc000034738 pc=0x43d7e5
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.runfinq()
        /home/kirr/src/tools/go/go/src/runtime/mfinal.go:175 +0xa9 fp=0xc0000347e0 sp=0xc000034758 pc=0x41cca9
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000347e8 sp=0xc0000347e0 pc=0x471f01
created by runtime.createfing
        /home/kirr/src/tools/go/go/src/runtime/mfinal.go:156 +0x65

goroutine 6 [chan receive]:
runtime.gopark(0x7af8c0, 0xc00008e058, 0x170e, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0000326d0 sp=0xc0000326b0 pc=0x43d7e5
runtime.chanrecv(0xc00008e000, 0xc0000327b0, 0xc000092001, 0xc00008e000)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:567 +0x365 fp=0xc000032760 sp=0xc0000326d0 pc=0x409d45
runtime.chanrecv2(0xc00008e000, 0xc0000327b0, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:439 +0x2b fp=0xc000032790 sp=0xc000032760 pc=0x4099cb
github.com/golang/glog.(*loggingT).flushDaemon(0x9d3840)
        /home/kirr/src/neo/src/github.com/golang/glog/glog.go:882 +0x8b fp=0xc0000327d8 sp=0xc000032790 pc=0x548d4b
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000327e0 sp=0xc0000327d8 pc=0x471f01
created by github.com/golang/glog.init.0
        /home/kirr/src/neo/src/github.com/golang/glog/glog.go:410 +0x274

goroutine 83 [semacquire]:
runtime.gopark(0x7afad8, 0x9da260, 0xc000441912, 0x4)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0002def08 sp=0xc0002deee8 pc=0x43d7e5
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.semacquire1(0xc0004fc668, 0x445800, 0x1, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/sema.go:144 +0x1c5 fp=0xc0002def70 sp=0xc0002def08 pc=0x44e185
sync.runtime_Semacquire(0xc0004fc668)
        /home/kirr/src/tools/go/go/src/runtime/sema.go:56 +0x45 fp=0xc0002defa0 sp=0xc0002def70 pc=0x46e5c5
sync.(*WaitGroup).Wait(0xc0004fc660)
        /home/kirr/src/tools/go/go/src/sync/waitgroup.go:130 +0x65 fp=0xc0002defc8 sp=0xc0002defa0 pc=0x47c7e5
lab.nexedi.com/kirr/neo/go/transaction.(*transaction).Abort(0xc000120540)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/transaction/transaction.go:120 +0x113 fp=0xc0002df040 sp=0xc0002defc8 pc=0x56a2b3
_/home/kirr/src/wendelin/wendelin.core/wcfs.(*ΔBtail).Update(0xc0002df4a8, 0xc000345b80, 0x3da809146177299, 0xc0003aa9c0, 0x0, 0x0)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail.go:577 +0x5d5 fp=0xc0002df1d8 sp=0xc0002df040 pc=0x6b4235
_/home/kirr/src/wendelin/wendelin.core/wcfs.xverifyΔBTail1(0xc000082d80, 0xc0001f8200, 0x38, 0xc00011c200, 0xc, 0x3da80914603abcc, 0x3da809146177299, 0xc0002d00f8, 0x1, 0x1, ...)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:695 +0x9d1 fp=0xc0002df668 sp=0xc0002df1d8 pc=0x6c3bb1
_/home/kirr/src/wendelin/wendelin.core/wcfs.xverifyΔBTail(0xc000082d80, 0xc0001f8200, 0x38, 0xc00011c200, 0xc, 0x3da80914603abcc, 0x3da809146177299, 0xc0002d00f8, 0x1, 0x1, ...)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:599 +0xeff fp=0xc0002dfb28 sp=0xc0002df668 pc=0x6c2fff
_/home/kirr/src/wendelin/wendelin.core/wcfs.testΔBTail(0xc000082d80, 0xc000224240)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:854 +0x5ff fp=0xc0002dfd38 sp=0xc0002dfb28 pc=0x6c5b7f
_/home/kirr/src/wendelin/wendelin.core/wcfs.TestΔBTail(0xc000082d80)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1081 +0x3408 fp=0xc0002dff80 sp=0xc0002dfd38 pc=0x6c9108
testing.tRunner(0xc000082d80, 0x7aeb88)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1127 +0xef fp=0xc0002dffd0 sp=0xc0002dff80 pc=0x502ecf
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0002dffd8 sp=0xc0002dffd0 pc=0x471f01
created by testing.(*T).Run
        /home/kirr/src/tools/go/go/src/testing/testing.go:1178 +0x386

goroutine 84 [chan send]:
runtime.gopark(0x7af8c0, 0xc000224298, 0xc00003160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000035690 sp=0xc000035670 pc=0x43d7e5
runtime.chansend(0xc000224240, 0xc000035788, 0x46f001, 0x6cf1e7, 0x1bbd5c01)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:253 +0x23c fp=0xc000035710 sp=0xc000035690 pc=0x40907c
runtime.chansend1(0xc000224240, 0xc000035788)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc000035748 sp=0xc000035710 pc=0x408e35
_/home/kirr/src/wendelin/wendelin.core/wcfs.TestΔBTail.func3(0xc000224240, 0xc000160700, 0x69, 0x70)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1078 +0xc7 fp=0xc0000357c0 sp=0xc000035748 pc=0x6cf1e7
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000357c8 sp=0xc0000357c0 pc=0x471f01
created by _/home/kirr/src/wendelin/wendelin.core/wcfs.TestΔBTail
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1075 +0x33ed

goroutine 17451 [runnable]:
lab.nexedi.com/kirr/neo/go/transaction.(*transaction).Abort.func2(0xc0004fc660, 0xc0004ff560, 0x0, 0xc000120540)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/transaction/transaction.go:113 fp=0xc00002ffc0 sp=0xc00002ffb8 pc=0x56aac0
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00002ffc8 sp=0xc00002ffc0 pc=0x471f01
created by lab.nexedi.com/kirr/neo/go/transaction.(*transaction).Abort
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/transaction/transaction.go:113 +0xf1

goroutine 82 [GC worker (idle)]:
runtime.gopark(0x7af960, 0xc000017ba0, 0x1418, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000035f60 sp=0xc000035f40 pc=0x43d7e5
runtime.gcBgMarkWorker(0xc000024000)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1891 +0xff fp=0xc000035fd8 sp=0xc000035f60 pc=0x42091f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000035fe0 sp=0xc000035fd8 pc=0x471f01
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 17240 [chan send]:
runtime.gopark(0x7af8c0, 0xc000439fd8, 0x7f0ecad4160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000276e50 sp=0xc000276e30 pc=0x43d7e5
runtime.chansend(0xc000439f80, 0xc000276fa0, 0x70ed01, 0x6ca5bd, 0xc0004167c0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:253 +0x23c fp=0xc000276ed0 sp=0xc000276e50 pc=0x40907c
runtime.chansend1(0xc000439f80, 0xc000276fa0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc000276f08 sp=0xc000276ed0 pc=0x408e35
_/home/kirr/src/wendelin/wendelin.core/wcfs.intSets(0xc000439f80, 0x2, 0x8)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1197 +0xdd fp=0xc000276fc8 sp=0xc000276f08 pc=0x6ca5bd
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000276fd0 sp=0xc000276fc8 pc=0x471f01
created by _/home/kirr/src/wendelin/wendelin.core/wcfs.intSets
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1195 +0x229

goroutine 114 [runnable]:
runtime.gopark(0x7afad8, 0x9d8be0, 0xc000441912, 0x4)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc00025bea0 sp=0xc00025be80 pc=0x43d7e5
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.semacquire1(0x9d3e94, 0xbfa5398e8180a000, 0x0, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/sema.go:144 +0x1c5 fp=0xc00025bf08 sp=0xc00025bea0 pc=0x44e185
runtime.semacquire(...)
        /home/kirr/src/tools/go/go/src/runtime/sema.go:95
runtime.gcMarkDone()
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1447 +0x3e fp=0xc00025bf60 sp=0xc00025bf08 pc=0x41f87e
runtime.gcBgMarkWorker(0xc000029000)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:2018 +0x2af fp=0xc00025bfd8 sp=0xc00025bf60 pc=0x420acf
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00025bfe0 sp=0xc00025bfd8 pc=0x471f01
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 98 [GC worker (idle)]:
runtime.gopark(0x7af960, 0xc0000b6160, 0x1418, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000255760 sp=0xc000255740 pc=0x43d7e5
runtime.gcBgMarkWorker(0xc000026800)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1891 +0xff fp=0xc0002557d8 sp=0xc000255760 pc=0x42091f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0002557e0 sp=0xc0002557d8 pc=0x471f01
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 17452 [runnable]:
lab.nexedi.com/kirr/neo/go/transaction.(*transaction).Abort.func2(0xc0004fc660, 0xc0004ff560, 0x1, 0xc000120540)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/transaction/transaction.go:113 fp=0xc0005b6fc0 sp=0xc0005b6fb8 pc=0x56aac0
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0005b6fc8 sp=0xc0005b6fc0 pc=0x471f01
created by lab.nexedi.com/kirr/neo/go/transaction.(*transaction).Abort
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/transaction/transaction.go:113 +0xf1

goroutine 15832 [chan send]:
runtime.gopark(0x7af8c0, 0xc0002251f8, 0x7f0ecad4160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0005b7650 sp=0xc0005b7630 pc=0x43d7e5
runtime.chansend(0xc0002251a0, 0xc0005b77a0, 0x70ed01, 0x6ca5bd, 0xc0004545d0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:253 +0x23c fp=0xc0005b76d0 sp=0xc0005b7650 pc=0x40907c
runtime.chansend1(0xc0002251a0, 0xc0005b77a0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc0005b7708 sp=0xc0005b76d0 pc=0x408e35
_/home/kirr/src/wendelin/wendelin.core/wcfs.intSets(0xc0002251a0, 0x0, 0x8)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1197 +0xdd fp=0xc0005b77c8 sp=0xc0005b7708 pc=0x6ca5bd
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0005b77d0 sp=0xc0005b77c8 pc=0x471f01
created by _/home/kirr/src/wendelin/wendelin.core/wcfs.IntSets
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1184 +0x6b

goroutine 153 [select]:
runtime.gopark(0x7afb28, 0x0, 0x1809, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000215858 sp=0xc000215838 pc=0x43d7e5
runtime.selectgo(0xc000215e80, 0xc000215a50, 0x4, 0xc000048001, 0x7fa100)
        /home/kirr/src/tools/go/go/src/runtime/select.go:319 +0xce5 fp=0xc000215980 sp=0xc000215858 pc=0x44d7c5
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage)._watcher(0xc00011e000, 0xc0000920f0, 0x0, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:537 +0x1073 fp=0xc000215f30 sp=0xc000215980 pc=0x5b4cd3
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).watcher(0xc00011e000, 0xc0000920f0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:465 +0xa5 fp=0xc000215fc8 sp=0xc000215f30 pc=0x5b3985
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000215fd0 sp=0xc000215fc8 pc=0x471f01
created by lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.Open
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:906 +0x6a5

goroutine 155 [select]:
runtime.gopark(0x7afb28, 0x0, 0x1809, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000046cf8 sp=0xc000046cd8 pc=0x43d7e5
runtime.selectgo(0xc000046ef0, 0xc000046e88, 0x2, 0x3da808746177299, 0x197e7162)
        /home/kirr/src/tools/go/go/src/runtime/select.go:319 +0xce5 fp=0xc000046e20 sp=0xc000046cf8 pc=0x44d7c5
lab.nexedi.com/kirr/neo/go/zodb.(*DB).watcher(0xc00011c200, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/db.go:234 +0x3b4 fp=0xc000046fc8 sp=0xc000046e20 pc=0x594db4
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000046fd0 sp=0xc000046fc8 pc=0x471f01
created by lab.nexedi.com/kirr/neo/go/zodb.NewDB
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/db.go:142 +0x167

goroutine 154 [select]:
runtime.gopark(0x7afb28, 0x0, 0x1809, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000043c10 sp=0xc000043bf0 pc=0x43d7e5
runtime.selectgo(0xc000043ed8, 0xc000043d98, 0x2, 0x0, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/select.go:319 +0xce5 fp=0xc000043d38 sp=0xc000043c10 pc=0x44d7c5
lab.nexedi.com/kirr/neo/go/zodb.(*storage)._watcher(0xc00011c180, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage.go:310 +0x1ce fp=0xc000043fb0 sp=0xc000043d38 pc=0x59d02e
lab.nexedi.com/kirr/neo/go/zodb.(*storage).watcher(0xc00011c180)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage.go:249 +0x2b fp=0xc000043fd8 sp=0xc000043fb0 pc=0x59ce2b
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000043fe0 sp=0xc000043fd8 pc=0x471f01
created by lab.nexedi.com/kirr/neo/go/zodb.Open
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage.go:148 +0x23e

goroutine 152 [syscall]:
syscall.Syscall6(0xe8, 0xb, 0xc00018fb6c, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x2, 0x4, 0x0)
        /home/kirr/src/tools/go/go/src/syscall/asm_linux_amd64.s:41 +0x5 fp=0xc00018faa0 sp=0xc00018fa98 pc=0x4871e5
golang.org/x/sys/unix.EpollWait(0xb, 0xc00018fb6c, 0x7, 0x7, 0xffffffffffffffff, 0xc00018fc44, 0xc000552d00, 0x0)
        /home/kirr/src/tools/go/g.env/src/golang.org/x/sys/unix/zsyscall_linux_amd64.go:76 +0x72 fp=0xc00018fb10 sp=0xc00018faa0 pc=0x54fc92
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc0001fa100, 0xc00018fc00, 0x2, 0x0)
        /home/kirr/src/neo/src/github.com/fsnotify/fsnotify/inotify_poller.go:86 +0x91 fp=0xc00018fbd8 sp=0xc00018fb10 pc=0x5ab551
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc0000920f0)
        /home/kirr/src/neo/src/github.com/fsnotify/fsnotify/inotify.go:192 +0x206 fp=0xc00019ffd8 sp=0xc00018fbd8 pc=0x5aa6c6
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00019ffe0 sp=0xc00019ffd8 pc=0x471f01
created by github.com/fsnotify/fsnotify.NewWatcher
        /home/kirr/src/neo/src/github.com/fsnotify/fsnotify/inotify.go:59 +0x1a8

goroutine 17413 [chan send]:
runtime.gopark(0x7af8c0, 0xc00022f918, 0x10000000000160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0001a5e50 sp=0xc0001a5e30 pc=0x43d7e5
runtime.chansend(0xc00022f8c0, 0xc0001a5fa0, 0x70ed01, 0x6ca5bd, 0xc0000b7080)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:253 +0x23c fp=0xc0001a5ed0 sp=0xc0001a5e50 pc=0x40907c
runtime.chansend1(0xc00022f8c0, 0xc0001a5fa0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc0001a5f08 sp=0xc0001a5ed0 pc=0x408e35
_/home/kirr/src/wendelin/wendelin.core/wcfs.intSets(0xc00022f8c0, 0x5, 0x8)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1197 +0xdd fp=0xc0001a5fc8 sp=0xc0001a5f08 pc=0x6ca5bd
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0001a5fd0 sp=0xc0001a5fc8 pc=0x471f01
created by _/home/kirr/src/wendelin/wendelin.core/wcfs.intSets
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1195 +0x229

goroutine 17241 [chan send]:
runtime.gopark(0x7af8c0, 0xc000496058, 0x7f0ecad4160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0001a4650 sp=0xc0001a4630 pc=0x43d7e5
runtime.chansend(0xc000496000, 0xc0001a47a0, 0x70ed01, 0x6ca5bd, 0xc0004167e0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:253 +0x23c fp=0xc0001a46d0 sp=0xc0001a4650 pc=0x40907c
runtime.chansend1(0xc000496000, 0xc0001a47a0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc0001a4708 sp=0xc0001a46d0 pc=0x408e35
_/home/kirr/src/wendelin/wendelin.core/wcfs.intSets(0xc000496000, 0x3, 0x8)
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1197 +0xdd fp=0xc0001a47c8 sp=0xc0001a4708 pc=0x6ca5bd
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0001a47d0 sp=0xc0001a47c8 pc=0x471f01
created by _/home/kirr/src/wendelin/wendelin.core/wcfs.intSets
        /home/kirr/src/wendelin/wendelin.core/wcfs/δbtail_test.go:1195 +0x229
signal: aborted (core dumped)
FAIL    _/home/kirr/src/wendelin/wendelin.core/wcfs     1.114s

core.zip

@navytux
Copy link
Contributor Author

@navytux navytux commented Sep 9, 2020

( wcfs go unit tests are just regular go unit tests - they do not play with virtual memory at all, , and, to my knowledge, there is no Cgo involved. At that level FUSE is also not used. )

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Sep 9, 2020

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 13, 2020

Unfortunately our test system hit a similar crash with go1.14.9:

runtime: full=0xc000560000000f next=103 jobs=102 nDataRoots=1 nBSSRoots=1 nSpanRoots=2 nStackRoots=96
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack
full output
cd wcfs && go test -count=1 ./... # -count=1 disables tests caching
2020/10/12 23:37:30 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
2020/10/12 23:37:30 zodb: FIXME: open /tmp/δBTail215797129/1.fs: raw cache is not ready for invalidations -> NoCache forced
2020/10/12 23:37:37 zodb: FIXME: open /tmp/δBTail399187796/1.fs: raw cache is not ready for invalidations -> NoCache forced
runtime: full=0xc000560000000f next=103 jobs=102 nDataRoots=1 nBSSRoots=1 nSpanRoots=2 nStackRoots=96
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack

runtime stack:
runtime.throw(0x8b423b, 0x15)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/panic.go:1116 +0x72 fp=0x7fb0ff5d5d90 sp=0x7fb0ff5d5d60 pc=0x437fe2
panic(0x7f7680, 0x93e510)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/panic.go:895 +0x72e fp=0x7fb0ff5d5e48 sp=0x7fb0ff5d5d90 pc=0x437ebe
runtime.gcMark(0x7717e8738701)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2046 +0x4ca fp=0x7fb0ff5d5ec0 sp=0x7fb0ff5d5e48 pc=0x41fe4a
runtime.gcMarkTermination.func1()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1636 +0x2a fp=0x7fb0ff5d5ed8 sp=0x7fb0ff5d5ec0 pc=0x46511a
runtime.systemstack(0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:370 +0x66 fp=0x7fb0ff5d5ee0 sp=0x7fb0ff5d5ed8 pc=0x468266
runtime.mstart()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:1056 fp=0x7fb0ff5d5ee8 sp=0x7fb0ff5d5ee0 pc=0x43ce40

goroutine 60 [garbage collection]:
runtime.systemstack_switch()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:330 fp=0xc0001fb548 sp=0xc0001fb540 pc=0x4681f0
runtime.gcMarkTermination(0x3ffccc919af0ce79)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1635 +0x17b fp=0xc0001fb708 sp=0xc0001fb548 pc=0x41ea3b
runtime.gcMarkDone()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1610 +0x200 fp=0xc0001fb760 sp=0xc0001fb708 pc=0x41e800
runtime.gcBgMarkWorker(0xc000036000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2000 +0x29e fp=0xc0001fb7d8 sp=0xc0001fb760 pc=0x41f76e
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001fb7e0 sp=0xc0001fb7d8 pc=0x46a301
created by runtime.gcBgMarkStartWorkers
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1821 +0x77

goroutine 1 [chan receive]:
runtime.gopark(0x8ccc18, 0xc0003d8f58, 0x170e, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000054b88 sp=0xc000054b68 pc=0x43aa10
runtime.chanrecv(0xc0003d8f00, 0xc000054c87, 0xc000000301, 0x4f6c42)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:525 +0x2e7 fp=0xc000054c18 sp=0xc000054b88 pc=0x4094d7
runtime.chanrecv1(0xc0003d8f00, 0xc000054c87)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:407 +0x2b fp=0xc000054c48 sp=0xc000054c18 pc=0x40919b
testing.(*T).Run(0xc0000b7440, 0x8b3fc5, 0x15, 0x8cc750, 0x48c501)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1106 +0x399 fp=0xc000054ce0 sp=0xc000054c48 pc=0x4f6c69
testing.runTests.func1(0xc00013e7e0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1349 +0x78 fp=0xc000054d30 sp=0xc000054ce0 pc=0x4fac58
testing.tRunner(0xc00013e7e0, 0xc00014fe10)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1054 +0xdc fp=0xc000054d80 sp=0xc000054d30 pc=0x4f685c
testing.runTests(0xc000102900, 0xbf05c0, 0x6, 0x6, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1347 +0x2a7 fp=0xc000054e40 sp=0xc000054d80 pc=0x4f8267
testing.(*M).Run(0xc00017c080, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1264 +0x1b7 fp=0xc000054f20 sp=0xc000054e40 pc=0x4f7117
main.main()
	_testmain.go:54 +0x135 fp=0xc000054f88 sp=0xc000054f20 pc=0x7b5f95
runtime.main()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:203 +0x1fa fp=0xc000054fe0 sp=0xc000054f88 pc=0x43a64a
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000054fe8 sp=0xc000054fe0 pc=0x46a301

goroutine 2 [force gc (idle)]:
runtime.gopark(0x8cce18, 0xc2fa70, 0x1411, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000044fb0 sp=0xc000044f90 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.forcegchelper()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:253 +0xb7 fp=0xc000044fe0 sp=0xc000044fb0 pc=0x43a8c7
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000044fe8 sp=0xc000044fe0 pc=0x46a301
created by runtime.init.6
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:242 +0x35

goroutine 3 [GC sweep wait]:
runtime.gopark(0x8cce18, 0xc2fc60, 0x140c, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000457a8 sp=0xc000045788 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.bgsweep(0xc0000261c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcsweep.go:89 +0x131 fp=0xc0000457d8 sp=0xc0000457a8 pc=0x4260d1
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000457e0 sp=0xc0000457d8 pc=0x46a301
created by runtime.gcenable
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:214 +0x5c

goroutine 4 [GC scavenge wait]:
runtime.gopark(0x8cce18, 0xc2fc20, 0x140d, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000045f78 sp=0xc000045f58 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.bgscavenge(0xc0000261c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcscavenge.go:285 +0x290 fp=0xc000045fd8 sp=0xc000045f78 pc=0x424760
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000045fe0 sp=0xc000045fd8 pc=0x46a301
created by runtime.gcenable
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:215 +0x7e

goroutine 5 [finalizer wait]:
runtime.gopark(0x8cce18, 0xc5ca40, 0xc0004a1410, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000044758 sp=0xc000044738 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.runfinq()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mfinal.go:175 +0xa3 fp=0xc0000447e0 sp=0xc000044758 pc=0x41bc03
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000447e8 sp=0xc0000447e0 pc=0x46a301
created by runtime.createfing
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mfinal.go:156 +0x61

goroutine 6 [chan receive]:
runtime.gopark(0x8ccc18, 0xc000100058, 0x170e, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000466d0 sp=0xc0000466b0 pc=0x43aa10
runtime.chanrecv(0xc000100000, 0xc0000467b0, 0xc000104001, 0xc000100000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:525 +0x2e7 fp=0xc000046760 sp=0xc0000466d0 pc=0x4094d7
runtime.chanrecv2(0xc000100000, 0xc0000467b0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:412 +0x2b fp=0xc000046790 sp=0xc000046760 pc=0x4091db
github.com/golang/glog.(*loggingT).flushDaemon(0xc307a0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:882 +0x8b fp=0xc0000467d8 sp=0xc000046790 pc=0x540f8b
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000467e0 sp=0xc0000467d8 pc=0x46a301
created by github.com/golang/glog.init.0
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:410 +0x26f

goroutine 71692 [IO wait]:
runtime.gopark(0x8ccde8, 0x7fb0ffe1bb90, 0xc000181b02, 0x5)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc00056f620 sp=0xc00056f600 pc=0x43aa10
runtime.netpollblock(0x7fb0ffe1bb68, 0x72, 0xc000322000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/netpoll.go:419 +0x9a fp=0xc00056f658 sp=0xc00056f620 pc=0x43373a
internal/poll.runtime_pollWait(0x7fb0ffe1bb68, 0x72, 0xffffffffffffffff)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/netpoll.go:203 +0x55 fp=0xc00056f680 sp=0xc00056f658 pc=0x432ca5
internal/poll.(*pollDesc).wait(0xc0003ab5d8, 0x72, 0x1001, 0x1000, 0xffffffffffffffff)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/internal/poll/fd_poll_runtime.go:87 +0x45 fp=0xc00056f6b0 sp=0xc00056f680 pc=0x492a15
internal/poll.(*pollDesc).waitRead(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0003ab5c0, 0xc000322000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/internal/poll/fd_unix.go:169 +0x19b fp=0xc00056f720 sp=0xc00056f6b0 pc=0x49341b
os.(*File).read(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/os/file_unix.go:263
os.(*File).Read(0xc000106178, 0xc000322000, 0x1000, 0x1000, 0xc00056f830, 0x498617, 0xc0003ab500)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/os/file.go:116 +0x71 fp=0xc00056f790 sp=0xc00056f720 pc=0x497fc1
bufio.(*Reader).fill(0xc0003ab680)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/bufio/bufio.go:100 +0x103 fp=0xc00056f7e0 sp=0xc00056f790 pc=0x4fb533
bufio.(*Reader).ReadSlice(0xc0003ab680, 0xc00056f80a, 0x498baf, 0xc000106170, 0xc00056f878, 0x11, 0x20)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/bufio/bufio.go:359 +0x3d fp=0xc00056f828 sp=0xc00056f7e0 pc=0x4fc22d
bufio.(*Reader).ReadBytes(0xc0003ab680, 0xc0003c0f0a, 0xc0003c4c60, 0x11, 0x11, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/bufio/bufio.go:438 +0x7a fp=0xc00056f8f0 sp=0xc00056f828 pc=0x4fc6da
bufio.(*Reader).ReadString(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/bufio/bufio.go:475
lab.nexedi.com/nexedi/wendelin.core/wcfs.(*TreeSrv).Commit(0xc0003c0ff0, 0xc000532e00, 0x10, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:223 +0x248 fp=0xc00056f9e0 sp=0xc00056f8f0 pc=0x798e68
lab.nexedi.com/nexedi/wendelin.core/wcfs.testΔBTail.func5(0xc000532e00, 0x10, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:829 +0x1c3 fp=0xc00056faf8 sp=0xc00056f9e0 pc=0x7a87c3
lab.nexedi.com/nexedi/wendelin.core/wcfs.testΔBTail(0xc0000b7440, 0xc000483920)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:848 +0x3d3 fp=0xc00056fd10 sp=0xc00056faf8 pc=0x79f613
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs(0xc0000b7440)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1173 +0x8dd fp=0xc00056ff80 sp=0xc00056fd10 pc=0x7a3ded
testing.tRunner(0xc0000b7440, 0x8cc750)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1054 +0xdc fp=0xc00056ffd0 sp=0xc00056ff80 pc=0x4f685c
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00056ffd8 sp=0xc00056ffd0 pc=0x46a301
created by testing.(*T).Run
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1105 +0x372

goroutine 71728 [runnable]:
syscall.Syscall6(0xe8, 0x18, 0xc0001adb74, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x1, 0x7, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/syscall/asm_linux_amd64.s:41 +0x5 fp=0xc0001adaa8 sp=0xc0001adaa0 pc=0x480235
golang.org/x/sys/unix.EpollWait(0x18, 0xc0001adb74, 0x7, 0x7, 0xffffffffffffffff, 0x0, 0xc0001adc4c, 0xc0001adb90)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/golang.org/x/sys@v0.0.0-20200803210538-64077c9b5642/unix/zsyscall_linux_amd64.go:76 +0x72 fp=0xc0001adb18 sp=0xc0001adaa8 pc=0x547ad2
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc00041a8c0, 0xc0001adc00, 0x2, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify_poller.go:86 +0x91 fp=0xc0001adbe0 sp=0xc0001adb18 pc=0x5ab1e1
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc00035a9b0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify.go:192 +0x1f8 fp=0xc0001bdfd8 sp=0xc0001adbe0 pc=0x5aa3e8
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001bdfe0 sp=0xc0001bdfd8 pc=0x46a301
created by github.com/fsnotify/fsnotify.NewWatcher
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify.go:59 +0x1a5

goroutine 61 [runnable]:
runtime.gopark(0x8cce18, 0xc37200, 0xc0003a1912, 0x4)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000426a0 sp=0xc000042680 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.semacquire1(0xc30f74, 0x3ff29ca84001e100, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/sema.go:144 +0x1c0 fp=0xc000042708 sp=0xc0000426a0 pc=0x44b7c0
runtime.semacquire(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/sema.go:95
runtime.gcMarkDone()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1433 +0x3e fp=0xc000042760 sp=0xc000042708 pc=0x41e63e
runtime.gcBgMarkWorker(0xc000038800)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2000 +0x29e fp=0xc0000427d8 sp=0xc000042760 pc=0x41f76e
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000427e0 sp=0xc0000427d8 pc=0x46a301
created by runtime.gcBgMarkStartWorkers
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1821 +0x77

goroutine 71729 [select]:
runtime.gopark(0x8cce68, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000057858 sp=0xc000057838 pc=0x43aa10
runtime.selectgo(0xc000057e80, 0xc000057a50, 0x4, 0xc000034001, 0x946200)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:316 +0xc73 fp=0xc000057980 sp=0xc000057858 pc=0x44ac83
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage)._watcher(0xc00012c1c0, 0xc00035a9b0, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:537 +0x1031 fp=0xc000057f30 sp=0xc000057980 pc=0x5b5851
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).watcher(0xc00012c1c0, 0xc00035a9b0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:465 +0xa4 fp=0xc000057fc8 sp=0xc000057f30 pc=0x5b4554
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000057fd0 sp=0xc000057fc8 pc=0x46a301
created by lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.Open
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:906 +0x688

goroutine 71730 [select]:
runtime.gopark(0x8cce68, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000052bf8 sp=0xc000052bd8 pc=0x43aa10
runtime.selectgo(0xc000052ed8, 0xc000052d80, 0x2, 0xc00011e778, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:316 +0xc73 fp=0xc000052d20 sp=0xc000052bf8 pc=0x44ac83
lab.nexedi.com/kirr/neo/go/zodb.(*storage)._watcher(0xc00017c480, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:310 +0x1ce fp=0xc000052fb0 sp=0xc000052d20 pc=0x59d05e
lab.nexedi.com/kirr/neo/go/zodb.(*storage).watcher(0xc00017c480)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:249 +0x2b fp=0xc000052fd8 sp=0xc000052fb0 pc=0x59ce6b
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000052fe0 sp=0xc000052fd8 pc=0x46a301
created by lab.nexedi.com/kirr/neo/go/zodb.Open
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:148 +0x23a

goroutine 71727 [chan send]:
runtime.gopark(0x8ccc18, 0xc000483978, 0xc0000a160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000a9bb8 sp=0xc0000a9b98 pc=0x43aa10
runtime.chansend(0xc000483920, 0xc0000a9d38, 0xc0000a9b01, 0x7a92f7, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:236 +0x22d fp=0xc0000a9c38 sp=0xc0000a9bb8 pc=0x4088bd
runtime.chansend1(0xc000483920, 0xc0000a9d38)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc0000a9c70 sp=0xc0000a9c38 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs.func5(0xc000483920, 0xc000320000, 0x20, 0x20, 0xc000320300, 0x20, 0x20, 0xc0003d7b00, 0xc0003c0f00, 0xc000106160, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1167 +0x437 fp=0xc0000a9f70 sp=0xc0000a9c70 pc=0x7a92f7
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000a9f78 sp=0xc0000a9f70 pc=0x46a301
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1148 +0x8bf

goroutine 71731 [select]:
runtime.gopark(0x8cce68, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000058cf8 sp=0xc000058cd8 pc=0x43aa10
runtime.selectgo(0xc000058ef0, 0xc000058e88, 0x2, 0x3db4047a64cfc77, 0x3a37c322)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:316 +0xc73 fp=0xc000058e20 sp=0xc000058cf8 pc=0x44ac83
lab.nexedi.com/kirr/neo/go/zodb.(*DB).watcher(0xc00017c500, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/db.go:234 +0x3a8 fp=0xc000058fc8 sp=0xc000058e20 pc=0x594fd8
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000058fd0 sp=0xc000058fc8 pc=0x46a301
created by lab.nexedi.com/kirr/neo/go/zodb.NewDB
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/db.go:142 +0x162
Traceback (most recent call last):
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/bin/python", line 70, in <module>
    pymain(sys.argv[1:])
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/develop-eggs/pygolang-0.0.7-py2.7-linux-x86_64.egg/gpython/__init__.py", line 207, in pymain
    run()
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/develop-eggs/pygolang-0.0.7-py2.7-linux-x86_64.egg/gpython/__init__.py", line 126, in run
    _execfile(filepath, g)
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/develop-eggs/pygolang-0.0.7-py2.7-linux-x86_64.egg/gpython/__init__.py", line 216, in _execfile
    six.exec_(code, globals, locals)
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/eggs/six-1.12.0-py2.7.egg/six.py", line 709, in exec_
    exec("""exec _code_ in _globs_, _locs_""")
  File "<string>", line 1, in <module>
  File "./testprog/treegen.py", line 511, in <module>
    main()
  File "./testprog/treegen.py", line 507, in main
    cmd(argv)
  File "<decorator-gen-23>", line 2, in cmd_trees
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/develop-eggs/pygolang-0.0.7-py2.7-linux-x86_64.egg/golang/__init__.py", line 103, in _
    return f(*argv, **kw)
  File "./testprog/treegen.py", line 483, in cmd_trees
    TreesSrv(zstor, r)
  File "<decorator-gen-16>", line 2, in TreesSrv
  File "/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/develop-eggs/pygolang-0.0.7-py2.7-linux-x86_64.egg/golang/__init__.py", line 103, in _
    return f(*argv, **kw)
  File "./testprog/treegen.py", line 244, in TreesSrv
    xprint("%s" % ashex(head))
  File "./testprog/treegen.py", line 488, in xprint
    print(msg)
IOError: [Errno 32] Broken pipe
FAIL	lab.nexedi.com/nexedi/wendelin.core/wcfs	9.070s
?   	lab.nexedi.com/nexedi/wendelin.core/wcfs/internal/pycompat	[no test files]
FAIL
Makefile:190: recipe for target 'test.go' failed

(internal link)

Unfortunately I don't have core this time.

@navytux navytux changed the title runtime: panic: non-empty mark queue after concurrent mark runtime: panic: non-empty mark queue after concurrent mark (Go1.14, Go1.15) Oct 13, 2020
@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 13, 2020

go1.14.9 crash was on:

go env, go version, uname, lsb_release
$ ./bin/go version
go version go1.14.9 linux/amd64
$ ./bin/go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/srv/slapgrid/slappart9/.cache/go-build"
GOENV="/srv/slapgrid/slappart9/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/srv/slapgrid/slappart9/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build900932195=/tmp/go-build -gno-record-gcc-switches"
$ uname -a
Linux kubu 4.4.0-190-generic #220-Ubuntu SMP Fri Aug 28 23:02:15 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 16.04.7 LTS
Release:        16.04
Codename:       xenial

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 13, 2020

(again with go1.14.9)

runtime: full=0xc0003c5800000b next=113 jobs=111 nDataRoots=1 nBSSRoots=1 nSpanRoots=2 nStackRoots=105
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack
full output
cd wcfs && go test -count=1 ./... # -count=1 disables tests caching
2020/10/13 11:00:20 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
2020/10/13 11:00:21 zodb: FIXME: open /tmp/δBTail942857642/1.fs: raw cache is not ready for invalidations -> NoCache forced
2020/10/13 11:00:28 zodb: FIXME: open /tmp/δBTail015724801/1.fs: raw cache is not ready for invalidations -> NoCache forced
runtime: full=0xc0003c5800000b next=113 jobs=111 nDataRoots=1 nBSSRoots=1 nSpanRoots=2 nStackRoots=105
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack

runtime stack:
runtime.throw(0x8b423b, 0x15)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/panic.go:1116 +0x72 fp=0x7fe8777fdd90 sp=0x7fe8777fdd60 pc=0x437fe2
panic(0x7f7680, 0x93e510)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/panic.go:895 +0x72e fp=0x7fe8777fde48 sp=0x7fe8777fdd90 pc=0x437ebe
runtime.gcMark(0x9c686123ca6f)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2046 +0x4ca fp=0x7fe8777fdec0 sp=0x7fe8777fde48 pc=0x41fe4a
runtime.gcMarkTermination.func1()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1636 +0x2a fp=0x7fe8777fded8 sp=0x7fe8777fdec0 pc=0x46511a
runtime.systemstack(0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:370 +0x66 fp=0x7fe8777fdee0 sp=0x7fe8777fded8 pc=0x468266
runtime.mstart()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:1056 fp=0x7fe8777fdee8 sp=0x7fe8777fdee0 pc=0x43ce40

goroutine 91 [garbage collection]:
runtime.systemstack_switch()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:330 fp=0xc00022cd48 sp=0xc00022cd40 pc=0x4681f0
runtime.gcMarkTermination(0x3fe758715a33e157)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1635 +0x17b fp=0xc00022cf08 sp=0xc00022cd48 pc=0x41ea3b
runtime.gcMarkDone()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1610 +0x200 fp=0xc00022cf60 sp=0xc00022cf08 pc=0x41e800
runtime.gcBgMarkWorker(0xc000036000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2000 +0x29e fp=0xc00022cfd8 sp=0xc00022cf60 pc=0x41f76e
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00022cfe0 sp=0xc00022cfd8 pc=0x46a301
created by runtime.gcBgMarkStartWorkers
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1821 +0x77

goroutine 1 [chan receive]:
runtime.gopark(0x8ccc18, 0xc0003b7c78, 0x170e, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000059b88 sp=0xc000059b68 pc=0x43aa10
runtime.chanrecv(0xc0003b7c20, 0xc000059c87, 0xc000000301, 0x4f6c42)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:525 +0x2e7 fp=0xc000059c18 sp=0xc000059b88 pc=0x4094d7
runtime.chanrecv1(0xc0003b7c20, 0xc000059c87)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:407 +0x2b fp=0xc000059c48 sp=0xc000059c18 pc=0x40919b
testing.(*T).Run(0xc0004225a0, 0x8b3fc5, 0x15, 0x8cc750, 0x48c501)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1106 +0x399 fp=0xc000059ce0 sp=0xc000059c48 pc=0x4f6c69
testing.runTests.func1(0xc00013c6c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1349 +0x78 fp=0xc000059d30 sp=0xc000059ce0 pc=0x4fac58
testing.tRunner(0xc00013c6c0, 0xc00014de10)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1054 +0xdc fp=0xc000059d80 sp=0xc000059d30 pc=0x4f685c
testing.runTests(0xc000102900, 0xbf05c0, 0x6, 0x6, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1347 +0x2a7 fp=0xc000059e40 sp=0xc000059d80 pc=0x4f8267
testing.(*M).Run(0xc00017c080, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1264 +0x1b7 fp=0xc000059f20 sp=0xc000059e40 pc=0x4f7117
main.main()
	_testmain.go:54 +0x135 fp=0xc000059f88 sp=0xc000059f20 pc=0x7b5f95
runtime.main()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:203 +0x1fa fp=0xc000059fe0 sp=0xc000059f88 pc=0x43a64a
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000059fe8 sp=0xc000059fe0 pc=0x46a301

goroutine 2 [force gc (idle), 1 minutes]:
runtime.gopark(0x8cce18, 0xc2fa70, 0x1411, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000044fb0 sp=0xc000044f90 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.forcegchelper()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:253 +0xb7 fp=0xc000044fe0 sp=0xc000044fb0 pc=0x43a8c7
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000044fe8 sp=0xc000044fe0 pc=0x46a301
created by runtime.init.6
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:242 +0x35

goroutine 3 [GC sweep wait]:
runtime.gopark(0x8cce18, 0xc2fc60, 0x140c, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000457a8 sp=0xc000045788 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.bgsweep(0xc0000261c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcsweep.go:89 +0x131 fp=0xc0000457d8 sp=0xc0000457a8 pc=0x4260d1
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000457e0 sp=0xc0000457d8 pc=0x46a301
created by runtime.gcenable
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:214 +0x5c

goroutine 4 [sleep]:
runtime.gopark(0x8cce18, 0xc2fc20, 0x1313, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000045f28 sp=0xc000045f08 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.scavengeSleep(0xe994b0c, 0xe18f64)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcscavenge.go:214 +0xbf fp=0xc000045f78 sp=0xc000045f28 pc=0x42449f
runtime.bgscavenge(0xc0000261c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcscavenge.go:337 +0x1db fp=0xc000045fd8 sp=0xc000045f78 pc=0x4246ab
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000045fe0 sp=0xc000045fd8 pc=0x46a301
created by runtime.gcenable
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:215 +0x7e

goroutine 5 [finalizer wait]:
runtime.gopark(0x8cce18, 0xc5ca40, 0xc000451410, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000044758 sp=0xc000044738 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.runfinq()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mfinal.go:175 +0xa3 fp=0xc0000447e0 sp=0xc000044758 pc=0x41bc03
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000447e8 sp=0xc0000447e0 pc=0x46a301
created by runtime.createfing
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mfinal.go:156 +0x61

goroutine 6 [chan receive]:
runtime.gopark(0x8ccc18, 0xc000100058, 0x170e, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000466d0 sp=0xc0000466b0 pc=0x43aa10
runtime.chanrecv(0xc000100000, 0xc0000467b0, 0xc000104001, 0xc307b8)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:525 +0x2e7 fp=0xc000046760 sp=0xc0000466d0 pc=0x4094d7
runtime.chanrecv2(0xc000100000, 0xc0000467b0, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:412 +0x2b fp=0xc000046790 sp=0xc000046760 pc=0x4091db
github.com/golang/glog.(*loggingT).flushDaemon(0xc307a0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:882 +0x8b fp=0xc0000467d8 sp=0xc000046790 pc=0x540f8b
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000467e0 sp=0xc0000467d8 pc=0x46a301
created by github.com/golang/glog.init.0
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:410 +0x26f

goroutine 71691 [runnable]:
runtime.asyncPreempt2()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/preempt.go:308 +0x62 fp=0xc0002fd948 sp=0xc0002fd928 pc=0x4390b2
runtime.asyncPreempt()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/preempt_amd64.s:50 +0xdb fp=0xc0002fdad0 sp=0xc0002fd948 pc=0x46bc4b
syscall.Pread(0x18, 0xc0001760f0, 0x2a, 0x2a, 0x1643e4, 0x2a, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/syscall/zsyscall_linux_amd64.go:1214 +0xa0 fp=0xc0002fdb40 sp=0xc0002fdad0 pc=0x47ed50
internal/poll.(*FD).Pread(0xc0004bbbc0, 0xc0001760f0, 0x2a, 0x2a, 0x1643e4, 0x2a, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/internal/poll/fd_unix.go:196 +0xa1 fp=0xc0002fdba8 sp=0xc0002fdb40 pc=0x493651
os.(*File).pread(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/os/file_unix.go:272
os.(*File).ReadAt(0xc000010830, 0xc0001760f0, 0x2a, 0x2a, 0x1643e4, 0x2a, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/os/file.go:134 +0x103 fp=0xc0002fdc48 sp=0xc0002fdba8 pc=0x4982a3
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).Load(0xc0001760c0, 0x946b60, 0xc000010830, 0x1643e4, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/format.go:477 +0x8d fp=0xc0002fdd60 sp=0xc0002fdc48 pc=0x5b9eed
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).loadPrevRev(0xc0001760c0, 0x946b60, 0xc000010830, 0x1643e4, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/format.go:548 +0x79 fp=0xc0002fde38 sp=0xc0002fdd60 pc=0x5baa99
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).LoadPrevRev(0xc0001760c0, 0x946b60, 0xc000010830, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/format.go:534 +0x5d fp=0xc0002fdea0 sp=0xc0002fde38 pc=0x5ba88d
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).load(0xc00012a1c0, 0x3db42fd70fece66, 0xb4b, 0x0, 0x0, 0x3db42fd71273f99, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:202 +0x20e fp=0xc0002fdf30 sp=0xc0002fdea0 pc=0x5b2fce
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).Load_XXXWithNextSerialXXX(0xc00012a1c0, 0x0, 0x0, 0x3db42fd70fece66, 0xb4b, 0xc0002fe028, 0x59e8b4, 0x0, 0xc000289b00, 0xc5ca00)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:168 +0x5a fp=0xc0002fdfd8 sp=0xc0002fdf30 pc=0x5b2bda
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).Load(0xc00012a1c0, 0x94df60, 0xc000737380, 0x3db42fd70fece66, 0xb4b, 0x818e80, 0xc5caf8, 0xc5caf8, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:159 +0x4a fp=0xc0002fe038 sp=0xc0002fdfd8 pc=0x5b2b2a
lab.nexedi.com/kirr/neo/go/zodb.(*storage).Load(0xc000301200, 0x94df60, 0xc000737380, 0x3db42fd70fece66, 0xb4b, 0x20, 0x83d8e0, 0x938894, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:219 +0x12a fp=0xc0002fe0d0 sp=0xc0002fe038 pc=0x59cbda
lab.nexedi.com/kirr/neo/go/zodb.(*Connection).load(0xc000077db0, 0x94df60, 0xc000737380, 0xb4b, 0xc000038800, 0xc0002fe1b0, 0x4175da, 0xc000718e10)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/connection.go:363 +0xb2 fp=0xc0002fe128 sp=0xc0002fe0d0 pc=0x594572
lab.nexedi.com/kirr/neo/go/zodb.(*Persistent).PActivate(0xc00017eaf0, 0x94df60, 0xc000737380, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/persistent.go:200 +0x184 fp=0xc0002fe320 sp=0xc0002fe128 pc=0x597254
lab.nexedi.com/nexedi/wendelin.core/wcfs.diffT(0x94df60, 0xc000737380, 0xc000388d90, 0xc000388a80, 0xc0007372c0, 0xc000736d20, 0xc000736fc0, 0xc0007373e0, 0xc000718db0, 0x0, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail.go:977 +0xa14 fp=0xc0002fea38 sp=0xc0002fe320 pc=0x791894
lab.nexedi.com/nexedi/wendelin.core/wcfs.diffX(0x94df60, 0xc000737380, 0x951ae0, 0xc000388d90, 0x951ae0, 0xc000388a80, 0xc0007372c0, 0xc000736d20, 0xc000736fc0, 0xc000182000, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail.go:897 +0x1df fp=0xc0002feb90 sp=0xc0002fea38 pc=0x79083f
lab.nexedi.com/nexedi/wendelin.core/wcfs.treediff(0x94df60, 0xc000737380, 0xc, 0xc000737320, 0xc0007372c0, 0xc000736d20, 0xc000736fc0, 0xc000077db0, 0xc000077c20, 0xc0007373b0, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail.go:809 +0x54b fp=0xc0002feff0 sp=0xc0002feb90 pc=0x78ffeb
lab.nexedi.com/nexedi/wendelin.core/wcfs.(*ΔBtail).Update(0xc0002ff478, 0xc000500060, 0x0, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail.go:542 +0x49d fp=0xc0002ff198 sp=0xc0002feff0 pc=0x78dffd
lab.nexedi.com/nexedi/wendelin.core/wcfs.xverifyΔBTail1(0xc0004225a0, 0xc00037c000, 0x30, 0xc000301280, 0xc, 0x3db42fd70fece66, 0x3db42fd71273f99, 0xc00010ce50, 0x2, 0x2, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:695 +0x9e5 fp=0xc0002ff638 sp=0xc0002ff198 pc=0x79d825
lab.nexedi.com/nexedi/wendelin.core/wcfs.xverifyΔBTail(0xc0004225a0, 0xc00037c000, 0x30, 0xc000301280, 0xc, 0x3db42fd70fece66, 0x3db42fd71273f99, 0xc00010ce50, 0x2, 0x2, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:598 +0xeb5 fp=0xc0002ffaf8 sp=0xc0002ff638 pc=0x79cc65
lab.nexedi.com/nexedi/wendelin.core/wcfs.testΔBTail(0xc0004225a0, 0xc000289860)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:854 +0x5f4 fp=0xc0002ffd10 sp=0xc0002ffaf8 pc=0x79f834
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs(0xc0004225a0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1173 +0x8dd fp=0xc0002fff80 sp=0xc0002ffd10 pc=0x7a3ded
testing.tRunner(0xc0004225a0, 0x8cc750)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1054 +0xdc fp=0xc0002fffd0 sp=0xc0002fff80 pc=0x4f685c
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0002fffd8 sp=0xc0002fffd0 pc=0x46a301
created by testing.(*T).Run
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1105 +0x372

goroutine 71729 [syscall]:
syscall.Syscall6(0xe8, 0x2e, 0xc000517b74, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x2, 0x2000000000004, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/syscall/asm_linux_amd64.s:41 +0x5 fp=0xc000517aa8 sp=0xc000517aa0 pc=0x480235
golang.org/x/sys/unix.EpollWait(0x2e, 0xc000517b74, 0x7, 0x7, 0xffffffffffffffff, 0xc00053b4e8, 0xc000517c4c, 0xc0000e6000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/golang.org/x/sys@v0.0.0-20200803210538-64077c9b5642/unix/zsyscall_linux_amd64.go:76 +0x72 fp=0xc000517b18 sp=0xc000517aa8 pc=0x547ad2
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc00032ae80, 0xc000517c00, 0x2, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify_poller.go:86 +0x91 fp=0xc000517be0 sp=0xc000517b18 pc=0x5ab1e1
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc000077b80)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify.go:192 +0x1f8 fp=0xc000527fd8 sp=0xc000517be0 pc=0x5aa3e8
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000527fe0 sp=0xc000527fd8 pc=0x46a301
created by github.com/fsnotify/fsnotify.NewWatcher
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify.go:59 +0x1a5

goroutine 71732 [select]:
runtime.gopark(0x8cce68, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000d9cf8 sp=0xc0000d9cd8 pc=0x43aa10
runtime.selectgo(0xc0000d9ef0, 0xc0000d9e88, 0x2, 0x3db42f371273f99, 0x1f034529)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:316 +0xc73 fp=0xc0000d9e20 sp=0xc0000d9cf8 pc=0x44ac83
lab.nexedi.com/kirr/neo/go/zodb.(*DB).watcher(0xc000301280, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/db.go:234 +0x3a8 fp=0xc0000d9fc8 sp=0xc0000d9e20 pc=0x594fd8
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000d9fd0 sp=0xc0000d9fc8 pc=0x46a301
created by lab.nexedi.com/kirr/neo/go/zodb.NewDB
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/db.go:142 +0x162

goroutine 71730 [select]:
runtime.gopark(0x8cce68, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000058858 sp=0xc000058838 pc=0x43aa10
runtime.selectgo(0xc000058e80, 0xc000058a50, 0x4, 0xc000034001, 0x946200)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:316 +0xc73 fp=0xc000058980 sp=0xc000058858 pc=0x44ac83
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage)._watcher(0xc00012a1c0, 0xc000077b80, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:537 +0x1031 fp=0xc000058f30 sp=0xc000058980 pc=0x5b5851
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).watcher(0xc00012a1c0, 0xc000077b80, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:465 +0xa4 fp=0xc000058fc8 sp=0xc000058f30 pc=0x5b4554
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000058fd0 sp=0xc000058fc8 pc=0x46a301
created by lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.Open
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:906 +0x688

goroutine 92 [runnable]:
runtime.gopark(0x8cce18, 0xc37200, 0xc000531912, 0x4)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc00022c6a0 sp=0xc00022c680 pc=0x43aa10
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.semacquire1(0xc30f74, 0x3ff3428e112c9100, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/sema.go:144 +0x1c0 fp=0xc00022c708 sp=0xc00022c6a0 pc=0x44b7c0
runtime.semacquire(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/sema.go:95
runtime.gcMarkDone()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1433 +0x3e fp=0xc00022c760 sp=0xc00022c708 pc=0x41e63e
runtime.gcBgMarkWorker(0xc000038800)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2000 +0x29e fp=0xc00022c7d8 sp=0xc00022c760 pc=0x41f76e
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00022c7e0 sp=0xc00022c7d8 pc=0x46a301
created by runtime.gcBgMarkStartWorkers
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1821 +0x77

goroutine 71728 [chan send]:
runtime.gopark(0x8ccc18, 0xc0002898b8, 0xc00005160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000054bb8 sp=0xc000054b98 pc=0x43aa10
runtime.chansend(0xc000289860, 0xc000054d38, 0xc000054b01, 0x7a92f7, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:236 +0x22d fp=0xc000054c38 sp=0xc000054bb8 pc=0x4088bd
runtime.chansend1(0xc000289860, 0xc000054d38)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc000054c70 sp=0xc000054c38 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs.func5(0xc000289860, 0xc000324000, 0x20, 0x20, 0xc000324300, 0x20, 0x20, 0xc000311680, 0xc0002f7800, 0xc0000107f8, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1167 +0x437 fp=0xc000054f70 sp=0xc000054c70 pc=0x7a92f7
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000054f78 sp=0xc000054f70 pc=0x46a301
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1148 +0x8bf

goroutine 71731 [select]:
runtime.gopark(0x8cce68, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000052bf8 sp=0xc000052bd8 pc=0x43aa10
runtime.selectgo(0xc000052ed8, 0xc000052d80, 0x2, 0x0, 0x7fe87eb61601)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:316 +0xc73 fp=0xc000052d20 sp=0xc000052bf8 pc=0x44ac83
lab.nexedi.com/kirr/neo/go/zodb.(*storage)._watcher(0xc000301200, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:310 +0x1ce fp=0xc000052fb0 sp=0xc000052d20 pc=0x59d05e
lab.nexedi.com/kirr/neo/go/zodb.(*storage).watcher(0xc000301200)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:249 +0x2b fp=0xc000052fd8 sp=0xc000052fb0 pc=0x59ce6b
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000052fe0 sp=0xc000052fd8 pc=0x46a301
created by lab.nexedi.com/kirr/neo/go/zodb.Open
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:148 +0x23a

goroutine 593857 [runnable]:
runtime.gopark(0x8ccc18, 0xc0002883b8, 0x7fe8a5f3160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc00039b650 sp=0xc00039b630 pc=0x43aa10
runtime.chansend(0xc000288360, 0xc00039b7a0, 0x7fb101, 0x7a4169, 0xc00072cba0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:236 +0x22d fp=0xc00039b6d0 sp=0xc00039b650 pc=0x4088bd
runtime.chansend1(0xc000288360, 0xc00039b7a0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc00039b708 sp=0xc00039b6d0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc000288360, 0x0, 0x5)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc00039b7c8 sp=0xc00039b708 pc=0x7a4169
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00039b7d0 sp=0xc00039b7c8 pc=0x46a301
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.IntSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1184 +0x6b
FAIL	lab.nexedi.com/nexedi/wendelin.core/wcfs	66.336s
?   	lab.nexedi.com/nexedi/wendelin.core/wcfs/internal/pycompat	[no test files]
FAIL
Makefile:190: recipe for target 'test.go' failed

@aclements, @mknyszek, do you think this is related to #40641 / #40642 / #40643 ?

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 14, 2020

I'm sorry to say that the GC crash also happened with go1.14.9-7-geadc935 - latest commit in release-branch.go1.14 that includes 878da0b (go1.14 backport from #40642):

runtime: full=0xc0005070024f69 next=86 jobs=85 nDataRoots=1 nBSSRoots=1 nSpanRoots=2 nStackRoots=79
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack
full output
cd wcfs && go test -count=1 ./... # -count=1 disables tests caching
2020/10/14 10:49:49 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
2020/10/14 10:49:50 zodb: FIXME: open /tmp/δBTail275497037/1.fs: raw cache is not ready for invalidations -> NoCache forced
runtime: full=0xc0005070024f69 next=86 jobs=85 nDataRoots=1 nBSSRoots=1 nSpanRoots=2 nStackRoots=79
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack

runtime stack:
runtime.throw(0x8b425f, 0x15)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/panic.go:1116 +0x72 fp=0x7fd7b4923d90 sp=0x7fd7b4923d60 pc=0x438032
panic(0x7f76a0, 0x93d5f0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/panic.go:895 +0x72e fp=0x7fd7b4923e48 sp=0x7fd7b4923d90 pc=0x437f0e
runtime.gcMark(0xea5b6d9fad8c)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2046 +0x4ca fp=0x7fd7b4923ec0 sp=0x7fd7b4923e48 pc=0x41fe7a
runtime.gcMarkTermination.func1()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1636 +0x2a fp=0x7fd7b4923ed8 sp=0x7fd7b4923ec0 pc=0x4651fa
runtime.systemstack(0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:370 +0x66 fp=0x7fd7b4923ee0 sp=0x7fd7b4923ed8 pc=0x468346
runtime.mstart()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:1056 fp=0x7fd7b4923ee8 sp=0x7fd7b4923ee0 pc=0x43ce90

goroutine 88 [garbage collection]:
runtime.systemstack_switch()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:330 fp=0xc000126548 sp=0xc000126540 pc=0x4682d0
runtime.gcMarkTermination(0x3ffb1ac2e01dab07)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1635 +0x17b fp=0xc000126708 sp=0xc000126548 pc=0x41ea6b
runtime.gcMarkDone()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1610 +0x200 fp=0xc000126760 sp=0xc000126708 pc=0x41e830
runtime.gcBgMarkWorker(0xc000036000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2000 +0x29e fp=0xc0001267d8 sp=0xc000126760 pc=0x41f79e
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001267e0 sp=0xc0001267d8 pc=0x46a3e1
created by runtime.gcBgMarkStartWorkers
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1821 +0x77

goroutine 1 [chan receive]:
runtime.gopark(0x8ccc68, 0xc00002a238, 0x170e, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000054b78 sp=0xc000054b58 pc=0x43aa60
runtime.chanrecv(0xc00002a1e0, 0xc000054c7f, 0xc000000301, 0x4f6d4b)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:535 +0x2f5 fp=0xc000054c08 sp=0xc000054b78 pc=0x4094f5
runtime.chanrecv1(0xc00002a1e0, 0xc000054c7f)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:412 +0x2b fp=0xc000054c38 sp=0xc000054c08 pc=0x4091ab
testing.(*T).Run(0xc0000ca480, 0x8afa9a, 0xb, 0x8cc788, 0x48c601)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1096 +0x2b2 fp=0xc000054cd0 sp=0xc000054c38 pc=0x4f6d72
testing.runTests.func1(0xc0000ca6c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1339 +0x78 fp=0xc000054d20 sp=0xc000054cd0 pc=0x4fae88
testing.tRunner(0xc0000ca6c0, 0xc0000dbe10)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1050 +0xdc fp=0xc000054d70 sp=0xc000054d20 pc=0x4f6a4c
testing.runTests(0xc0000908e0, 0xbee5c0, 0x6, 0x6, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1337 +0x2c3 fp=0xc000054e40 sp=0xc000054d70 pc=0x4f83c3
testing.(*M).Run(0xc000186080, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1252 +0x15f fp=0xc000054f20 sp=0xc000054e40 pc=0x4f728f
main.main()
	_testmain.go:54 +0x135 fp=0xc000054f88 sp=0xc000054f20 pc=0x7b6205
runtime.main()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:203 +0x1fa fp=0xc000054fe0 sp=0xc000054f88 pc=0x43a69a
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000054fe8 sp=0xc000054fe0 pc=0x46a3e1

goroutine 2 [force gc (idle)]:
runtime.gopark(0x8cce68, 0xc2da60, 0x1411, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000044fb0 sp=0xc000044f90 pc=0x43aa60
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.forcegchelper()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:253 +0xb7 fp=0xc000044fe0 sp=0xc000044fb0 pc=0x43a917
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000044fe8 sp=0xc000044fe0 pc=0x46a3e1
created by runtime.init.6
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:242 +0x35

goroutine 3 [GC sweep wait]:
runtime.gopark(0x8cce68, 0xc2dc40, 0x140c, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000457a8 sp=0xc000045788 pc=0x43aa60
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.bgsweep(0xc0000261c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcsweep.go:89 +0x131 fp=0xc0000457d8 sp=0xc0000457a8 pc=0x426121
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000457e0 sp=0xc0000457d8 pc=0x46a3e1
created by runtime.gcenable
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:214 +0x5c

goroutine 4 [sleep]:
runtime.gopark(0x8cce68, 0xc2dc00, 0x1313, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000045f28 sp=0xc000045f08 pc=0x43aa60
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.scavengeSleep(0x9a8104, 0x44ad25)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcscavenge.go:214 +0xbf fp=0xc000045f78 sp=0xc000045f28 pc=0x4244ef
runtime.bgscavenge(0xc0000261c0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgcscavenge.go:337 +0x1db fp=0xc000045fd8 sp=0xc000045f78 pc=0x4246fb
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000045fe0 sp=0xc000045fd8 pc=0x46a3e1
created by runtime.gcenable
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:215 +0x7e

goroutine 5 [finalizer wait]:
runtime.gopark(0x8cce68, 0xc5aa20, 0xc000091410, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000044758 sp=0xc000044738 pc=0x43aa60
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.runfinq()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mfinal.go:175 +0xa3 fp=0xc0000447e0 sp=0xc000044758 pc=0x41bc33
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000447e8 sp=0xc0000447e0 pc=0x46a3e1
created by runtime.createfing
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mfinal.go:156 +0x61

goroutine 6 [chan receive]:
runtime.gopark(0x8ccc68, 0xc00008e058, 0x170e, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0000466d0 sp=0xc0000466b0 pc=0x43aa60
runtime.chanrecv(0xc00008e000, 0xc0000467b0, 0xc000092001, 0xc00008e000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:535 +0x2f5 fp=0xc000046760 sp=0xc0000466d0 pc=0x4094f5
runtime.chanrecv2(0xc00008e000, 0xc0000467b0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:417 +0x2b fp=0xc000046790 sp=0xc000046760 pc=0x4091eb
github.com/golang/glog.(*loggingT).flushDaemon(0xc2e780)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:882 +0x8b fp=0xc0000467d8 sp=0xc000046790 pc=0x5411fb
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000467e0 sp=0xc0000467d8 pc=0x46a3e1
created by github.com/golang/glog.init.0
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/golang/glog@v0.0.0-20160126235308-23def4e6c14b/glog.go:410 +0x26f

goroutine 154 [runnable]:
syscall.Syscall6(0x11, 0xd, 0xc0002fc390, 0x2a, 0xbb35, 0x0, 0x0, 0x2a, 0x2a, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/syscall/asm_linux_amd64.s:41 +0x5 fp=0xc0000b6888 sp=0xc0000b6880 pc=0x480315
syscall.Pread(0xd, 0xc0002fc390, 0x2a, 0x2a, 0xbb35, 0x954780, 0x862200, 0x862200)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/syscall/zsyscall_linux_amd64.go:1211 +0x72 fp=0xc0000b68f8 sp=0xc0000b6888 pc=0x47ee02
internal/poll.(*FD).Pread(0xc00006c300, 0xc0002fc390, 0x2a, 0x2a, 0xbb35, 0x598a93, 0x8149c0, 0xc00009c2a0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/internal/poll/fd_unix.go:196 +0xa1 fp=0xc0000b6960 sp=0xc0000b68f8 pc=0x493731
os.(*File).pread(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/os/file_unix.go:272
os.(*File).ReadAt(0xc000010028, 0xc0002fc390, 0x2a, 0x2a, 0xbb35, 0xc0004dbf40, 0x8b4ebe, 0x17)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/os/file.go:134 +0x103 fp=0xc0000b6a00 sp=0xc0000b6960 pc=0x498383
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).Load(0xc0002fc360, 0x945c60, 0xc000010028, 0xbb35, 0x807ac0, 0xc000080000)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/format.go:477 +0x8d fp=0xc0000b6b18 sp=0xc0000b6a00 pc=0x5ba15d
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).loadPrevRev(0xc0002fc360, 0x945c60, 0xc000010028, 0xbb35, 0xbe9920, 0xc000425180)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/format.go:548 +0x79 fp=0xc0000b6bf0 sp=0xc0000b6b18 pc=0x5bad09
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*DataHeader).LoadPrevRev(0xc0002fc360, 0x945c60, 0xc000010028, 0x1, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/format.go:534 +0x5d fp=0xc0000b6c58 sp=0xc0000b6bf0 pc=0x5baafd
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).load(0xc0000ba000, 0x3db4891e1229e44, 0x62, 0x0, 0x0, 0x7fffffffffffffff, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:202 +0x20e fp=0xc0000b6ce8 sp=0xc0000b6c58 pc=0x5b323e
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).Load_XXXWithNextSerialXXX(0xc0000ba000, 0x0, 0x0, 0x3db4891e1229e44, 0x62, 0xc0000b6de0, 0x59eb24, 0x0, 0xc0001808a0, 0xc5aa00)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:168 +0x5a fp=0xc0000b6d90 sp=0xc0000b6ce8 pc=0x5b2e4a
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).Load(0xc0000ba000, 0x94d060, 0xc0004fa660, 0x3db4891e1229e44, 0x62, 0x818ea0, 0xc5aad8, 0xc5aad8, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:159 +0x4a fp=0xc0000b6df0 sp=0xc0000b6d90 pc=0x5b2d9a
lab.nexedi.com/kirr/neo/go/zodb.(*storage).Load(0xc000186280, 0x94d060, 0xc0004fa660, 0x3db4891e1229e44, 0x62, 0x20, 0x83d900, 0x937984, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:219 +0x12a fp=0xc0000b6e88 sp=0xc0000b6df0 pc=0x59ce4a
lab.nexedi.com/kirr/neo/go/zodb.(*Connection).load(0xc0000aa5a0, 0x94d060, 0xc0004fa660, 0x62, 0x84faa0, 0x40c8ab, 0xc000012000, 0x820c60)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/connection.go:363 +0xb2 fp=0xc0000b6ee0 sp=0xc0000b6e88 pc=0x5947e2
lab.nexedi.com/kirr/neo/go/zodb.(*Persistent).PActivate(0xc0000b84d0, 0x94d060, 0xc0004fa660, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/persistent.go:200 +0x184 fp=0xc0000b70d8 sp=0xc0000b6ee0 pc=0x5974c4
lab.nexedi.com/kirr/neo/go/zodb/btree.(*LOBTree).VGet(0xc000283650, 0x94d060, 0xc0004fa660, 0x2, 0xc0000b7380, 0x0, 0x0, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/btree/zlobtree.go:204 +0x297 fp=0xc0000b71c0 sp=0xc0000b70d8 pc=0x5a5e37
lab.nexedi.com/nexedi/wendelin.core/wcfs.xverifyΔBTail1(0xc0000ca480, 0xc00039fc80, 0x35, 0xc000186400, 0xc, 0x3db4891e1229e44, 0x3db4891e142bf11, 0xc000540440, 0x2, 0x2, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:645 +0x4f2 fp=0xc0000b7660 sp=0xc0000b71c0 pc=0x79d5a2
lab.nexedi.com/nexedi/wendelin.core/wcfs.xverifyΔBTail(0xc0000ca480, 0xc00039fc80, 0x35, 0xc000186400, 0xc, 0x3db4891e1229e44, 0x3db4891e142bf11, 0xc000540440, 0x2, 0x2, ...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:598 +0xeb5 fp=0xc0000b7b20 sp=0xc0000b7660 pc=0x79ced5
lab.nexedi.com/nexedi/wendelin.core/wcfs.testΔBTail(0xc0000ca480, 0xc00002a240)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:854 +0x5f4 fp=0xc0000b7d38 sp=0xc0000b7b20 pc=0x79faa4
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTail(0xc0000ca480)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1081 +0x33a5 fp=0xc0000b7f80 sp=0xc0000b7d38 pc=0x7a2fb5
testing.tRunner(0xc0000ca480, 0x8cc788)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1050 +0xdc fp=0xc0000b7fd0 sp=0xc0000b7f80 pc=0x4f6a4c
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000b7fd8 sp=0xc0000b7fd0 pc=0x46a3e1
created by testing.(*T).Run
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/testing/testing.go:1095 +0x28b

goroutine 155 [chan send]:
runtime.gopark(0x8ccc68, 0xc00002a298, 0xc00004160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000042690 sp=0xc000042670 pc=0x43aa60
runtime.chansend(0xc00002a240, 0xc000042788, 0x459e01, 0x7a8e27, 0xe2ce101)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc000042710 sp=0xc000042690 pc=0x4088cb
runtime.chansend1(0xc00002a240, 0xc000042788)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc000042748 sp=0xc000042710 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTail.func3(0xc00002a240, 0xc0000f0700, 0x69, 0x70)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1078 +0xc7 fp=0xc0000427c0 sp=0xc000042748 pc=0x7a8e27
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0000427c8 sp=0xc0000427c0 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTail
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1075 +0x338a

goroutine 38009 [chan send]:
runtime.gopark(0x8ccc68, 0xc0002596d8, 0x7fd7dee9160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0001d3e50 sp=0xc0001d3e30 pc=0x43aa60
runtime.chansend(0xc000259680, 0xc0001d3fa0, 0x7fb101, 0x7a43d9, 0xc000476420)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc0001d3ed0 sp=0xc0001d3e50 pc=0x4088cb
runtime.chansend1(0xc000259680, 0xc0001d3fa0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc0001d3f08 sp=0xc0001d3ed0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc000259680, 0x2, 0x9)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc0001d3fc8 sp=0xc0001d3f08 pc=0x7a43d9
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001d3fd0 sp=0xc0001d3fc8 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1195 +0x21d

goroutine 38008 [chan send]:
runtime.gopark(0x8ccc68, 0xc000259678, 0x7fd7dee9160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0001d5e50 sp=0xc0001d5e30 pc=0x43aa60
runtime.chansend(0xc000259620, 0xc0001d5fa0, 0x7fb101, 0x7a43d9, 0xc000476400)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc0001d5ed0 sp=0xc0001d5e50 pc=0x4088cb
runtime.chansend1(0xc000259620, 0xc0001d5fa0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc0001d5f08 sp=0xc0001d5ed0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc000259620, 0x1, 0x9)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc0001d5fc8 sp=0xc0001d5f08 pc=0x7a43d9
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001d5fd0 sp=0xc0001d5fc8 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1195 +0x21d

goroutine 127 [syscall]:
syscall.Syscall6(0xe8, 0x1d, 0xc0001b7b74, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x2, 0x4, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/syscall/asm_linux_amd64.s:41 +0x5 fp=0xc0001b7aa8 sp=0xc0001b7aa0 pc=0x480315
golang.org/x/sys/unix.EpollWait(0x1d, 0xc0001b7b74, 0x7, 0x7, 0xffffffffffffffff, 0x0, 0xc0001b7c4c, 0xc0001b7b90)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/golang.org/x/sys@v0.0.0-20200803210538-64077c9b5642/unix/zsyscall_linux_amd64.go:76 +0x72 fp=0xc0001b7b18 sp=0xc0001b7aa8 pc=0x547d42
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc0000241e0, 0xc0001b7c00, 0x2, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify_poller.go:86 +0x91 fp=0xc0001b7be0 sp=0xc0001b7b18 pc=0x5ab451
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc0000aa280)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify.go:192 +0x1f8 fp=0xc0001c7fd8 sp=0xc0001b7be0 pc=0x5aa658
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001c7fe0 sp=0xc0001c7fd8 pc=0x46a3e1
created by github.com/fsnotify/fsnotify.NewWatcher
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/github.com/fsnotify/fsnotify@v1.4.10-0.20200417215612-7f4cf4dd2b52/inotify.go:59 +0x1a5

goroutine 128 [select]:
runtime.gopark(0x8cceb8, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc00037a858 sp=0xc00037a838 pc=0x43aa60
runtime.selectgo(0xc00037ae80, 0xc00037aa50, 0x4, 0xc000034001, 0x945300)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:335 +0xc81 fp=0xc00037a980 sp=0xc00037a858 pc=0x44acf1
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage)._watcher(0xc0000ba000, 0xc0000aa280, 0x0, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:537 +0x1031 fp=0xc00037af30 sp=0xc00037a980 pc=0x5b5ac1
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).watcher(0xc0000ba000, 0xc0000aa280, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:465 +0xa4 fp=0xc00037afc8 sp=0xc00037af30 pc=0x5b47c4
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00037afd0 sp=0xc00037afc8 pc=0x46a3e1
created by lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.Open
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage/fs1/filestorage.go:906 +0x688

goroutine 129 [select]:
runtime.gopark(0x8cceb8, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc00037bbf8 sp=0xc00037bbd8 pc=0x43aa60
runtime.selectgo(0xc00037bed8, 0xc00037bd80, 0x2, 0x0, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:335 +0xc81 fp=0xc00037bd20 sp=0xc00037bbf8 pc=0x44acf1
lab.nexedi.com/kirr/neo/go/zodb.(*storage)._watcher(0xc000186280, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:310 +0x1ce fp=0xc00037bfb0 sp=0xc00037bd20 pc=0x59d2ce
lab.nexedi.com/kirr/neo/go/zodb.(*storage).watcher(0xc000186280)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:249 +0x2b fp=0xc00037bfd8 sp=0xc00037bfb0 pc=0x59d0db
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00037bfe0 sp=0xc00037bfd8 pc=0x46a3e1
created by lab.nexedi.com/kirr/neo/go/zodb.Open
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/storage.go:148 +0x23a

goroutine 162 [select]:
runtime.gopark(0x8cceb8, 0x0, 0x1809, 0x1)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000058cf8 sp=0xc000058cd8 pc=0x43aa60
runtime.selectgo(0xc000058ef0, 0xc000058e88, 0x2, 0x3db4887e142bf11, 0x2f6a1be7)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/select.go:335 +0xc81 fp=0xc000058e20 sp=0xc000058cf8 pc=0x44acf1
lab.nexedi.com/kirr/neo/go/zodb.(*DB).watcher(0xc000186400, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/db.go:234 +0x3a8 fp=0xc000058fc8 sp=0xc000058e20 pc=0x595248
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000058fd0 sp=0xc000058fc8 pc=0x46a3e1
created by lab.nexedi.com/kirr/neo/go/zodb.NewDB
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/go.work/pkg/mod/lab.nexedi.com/kirr/neo/go@v0.0.0-20201012044742-28494187df87/zodb/db.go:142 +0x162

goroutine 38011 [chan send]:
runtime.gopark(0x8ccc68, 0xc000259798, 0x7fd7dee9160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0001d1e50 sp=0xc0001d1e30 pc=0x43aa60
runtime.chansend(0xc000259740, 0xc0001d1fa0, 0x7fb101, 0x7a43d9, 0xc000476460)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc0001d1ed0 sp=0xc0001d1e50 pc=0x4088cb
runtime.chansend1(0xc000259740, 0xc0001d1fa0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc0001d1f08 sp=0xc0001d1ed0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc000259740, 0x4, 0x9)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc0001d1fc8 sp=0xc0001d1f08 pc=0x7a43d9
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001d1fd0 sp=0xc0001d1fc8 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1195 +0x21d

goroutine 38132 [chan send]:
runtime.gopark(0x8ccc68, 0xc00002a598, 0x7fd7dee9160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0001d0e50 sp=0xc0001d0e30 pc=0x43aa60
runtime.chansend(0xc00002a540, 0xc0001d0fa0, 0x7fb101, 0x7a43d9, 0xc000420370)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc0001d0ed0 sp=0xc0001d0e50 pc=0x4088cb
runtime.chansend1(0xc00002a540, 0xc0001d0fa0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc0001d0f08 sp=0xc0001d0ed0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc00002a540, 0x6, 0x9)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc0001d0fc8 sp=0xc0001d0f08 pc=0x7a43d9
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001d0fd0 sp=0xc0001d0fc8 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1195 +0x21d

goroutine 89 [runnable]:
runtime.gopark(0x8cce68, 0xc34be0, 0xc000481912, 0x4)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc00012dea0 sp=0xc00012de80 pc=0x43aa60
runtime.goparkunlock(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:310
runtime.semacquire1(0xc2ef54, 0x400ac2f90b6cb700, 0x0, 0x0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/sema.go:144 +0x1c0 fp=0xc00012df08 sp=0xc00012dea0 pc=0x44b830
runtime.semacquire(...)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/sema.go:95
runtime.gcMarkDone()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1433 +0x3e fp=0xc00012df60 sp=0xc00012df08 pc=0x41e66e
runtime.gcBgMarkWorker(0xc000038800)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:2000 +0x29e fp=0xc00012dfd8 sp=0xc00012df60 pc=0x41f79e
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc00012dfe0 sp=0xc00012dfd8 pc=0x46a3e1
created by runtime.gcBgMarkStartWorkers
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/mgc.go:1821 +0x77

goroutine 38007 [runnable]:
runtime.gopark(0x8ccc68, 0xc000259618, 0x7fd7dee9160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc000162e50 sp=0xc000162e30 pc=0x43aa60
runtime.chansend(0xc0002595c0, 0xc000162fa0, 0x7fb101, 0x7a43d9, 0xc0000e6420)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc000162ed0 sp=0xc000162e50 pc=0x4088cb
runtime.chansend1(0xc0002595c0, 0xc000162fa0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc000162f08 sp=0xc000162ed0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc0002595c0, 0x0, 0x9)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc000162fc8 sp=0xc000162f08 pc=0x7a43d9
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000162fd0 sp=0xc000162fc8 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.IntSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1184 +0x6b

goroutine 38010 [chan send]:
runtime.gopark(0x8ccc68, 0xc000259738, 0x7fd7dee9160f, 0x2)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/proc.go:304 +0xe0 fp=0xc0001d4650 sp=0xc0001d4630 pc=0x43aa60
runtime.chansend(0xc0002596e0, 0xc0001d47a0, 0x7fb101, 0x7a43d9, 0xc000476440)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:241 +0x23b fp=0xc0001d46d0 sp=0xc0001d4650 pc=0x4088cb
runtime.chansend1(0xc0002596e0, 0xc0001d47a0)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/chan.go:127 +0x35 fp=0xc0001d4708 sp=0xc0001d46d0 pc=0x408685
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc0002596e0, 0x3, 0x9)
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1197 +0xd9 fp=0xc0001d47c8 sp=0xc0001d4708 pc=0x7a43d9
runtime.goexit()
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/golang1.14/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc0001d47d0 sp=0xc0001d47c8 pc=0x46a3e1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets
	/srv/slapgrid/slappart9/srv/testnode/dfo/soft/f1448e1fa9992105b6bef3961ac44dc9/parts/wendelin.core-dev/wcfs/δbtail_test.go:1195 +0x21d
FAIL	lab.nexedi.com/nexedi/wendelin.core/wcfs	3.710s
?   	lab.nexedi.com/nexedi/wendelin.core/wcfs/internal/pycompat	[no test files]
FAIL
Makefile:190: recipe for target 'test.go' failed

In other words #40641 / #40642 / #40643 seem to be unrelated.

/cc @aclements, @mknyszek

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 15, 2020

Sadly, I could also trigger the same crash on 1.15.3 (i.e. go1.15 with #40643 included):

runtime: full=0xc0004f18000006 next=187 jobs=184 nDataRoots=1 nBSSRoots=1 nSpanRoots=16 nStackRoots=164
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack
full output
...
ok      lab.nexedi.com/nexedi/wendelin.core/wcfs        49.448s
=== RUN   TestZBlk
2020/10/15 16:45:34 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestZBlk (0.02s)
=== RUN   TestΔBTail
2020/10/15 16:45:34 zodb: FIXME: open /tmp/δBTail389021863/1.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestΔBTail (2.68s)
=== RUN   TestΔBTreeAllStructs
    δbtail_test.go:1123: # maxdepth=2 maxsplit=1 nkeys=5 n=10 seed=1602769537289632682
2020/10/15 16:45:37 zodb: FIXME: open /tmp/δBTail799600090/1.fs: raw cache is not ready for invalidations -> NoCache forced
runtime: full=0xc0004f18000006 next=187 jobs=184 nDataRoots=1 nBSSRoots=1 nSpanRoots=16 nStackRoots=164
panic: non-empty mark queue after concurrent mark
fatal error: panic on system stack

runtime stack:
runtime.throw(0x79dbab, 0x15)
        /home/kirr/src/tools/go/go/src/runtime/panic.go:1116 +0x72 fp=0x7ffff1fb6728 sp=0x7ffff1fb66f8 pc=0x43ae12
panic(0x70e440, 0x7f4d40)
        /home/kirr/src/tools/go/go/src/runtime/panic.go:895 +0x845 fp=0x7ffff1fb67f0 sp=0x7ffff1fb6728 pc=0x43ad05
runtime.gcMark(0x2f8fa5b99c94)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:2064 +0x539 fp=0x7ffff1fb6888 sp=0x7ffff1fb67f0 pc=0x421279
runtime.gcMarkTermination.func1()
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1656 +0x2a fp=0x7ffff1fb68a0 sp=0x7ffff1fb6888 pc=0x46892a
runtime.systemstack(0x4702b4)
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:370 +0x66 fp=0x7ffff1fb68a8 sp=0x7ffff1fb68a0 pc=0x470466
runtime.mstart()
        /home/kirr/src/tools/go/go/src/runtime/proc.go:1116 fp=0x7ffff1fb68b0 sp=0x7ffff1fb68a8 pc=0x43ffe0

goroutine 82 [garbage collection]:
runtime.systemstack_switch()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:330 fp=0xc0001f9d48 sp=0xc0001f9d40 pc=0x4703e0
runtime.gcMarkTermination(0x3ffef5e2ff977c8b)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1655 +0x17b fp=0xc0001f9f08 sp=0xc0001f9d48 pc=0x41fd3b
runtime.gcMarkDone()
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1630 +0x275 fp=0xc0001f9f60 sp=0xc0001f9f08 pc=0x41faf5
runtime.gcBgMarkWorker(0xc000026000)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:2018 +0x2af fp=0xc0001f9fd8 sp=0xc0001f9f60 pc=0x420b0f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0001f9fe0 sp=0xc0001f9fd8 pc=0x4721c1
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 1 [chan receive]:
runtime.gopark(0x7b0bc8, 0xc0004bfaf8, 0x170e, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000049b48 sp=0xc000049b28 pc=0x43da05
runtime.chanrecv(0xc0004bfaa0, 0xc000049c4f, 0xc000000101, 0x5035b3)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:577 +0x36f fp=0xc000049bd8 sp=0xc000049b48 pc=0x409d6f
runtime.chanrecv1(0xc0004bfaa0, 0xc000049c4f)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:439 +0x2b fp=0xc000049c08 sp=0xc000049bd8 pc=0x4099ab
testing.(*T).Run(0xc0001c3980, 0x79d974, 0x15, 0x7b0848, 0x493d01)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1169 +0x2da fp=0xc000049ca0 sp=0xc000049c08 pc=0x5035da
testing.runTests.func1(0xc000001b00)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1439 +0x78 fp=0xc000049cf0 sp=0xc000049ca0 pc=0x507ad8
testing.tRunner(0xc000001b00, 0xc000143de0)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1123 +0xef fp=0xc000049d40 sp=0xc000049cf0 pc=0x50326f
testing.runTests(0xc00000e9a0, 0x99f2a0, 0x6, 0x6, 0xbfda33158071b429, 0x8bb2da9bde, 0x9d34c0, 0x410e70)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1437 +0x2fe fp=0xc000049e10 sp=0xc000049d40 pc=0x504e3e
testing.(*M).Run(0xc00015c080, 0x0)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1345 +0x1eb fp=0xc000049f20 sp=0xc000049e10 pc=0x503beb
main.main()
        _testmain.go:53 +0x138 fp=0xc000049f88 sp=0xc000049f20 pc=0x6dd8d8
runtime.main()
        /home/kirr/src/tools/go/go/src/runtime/proc.go:204 +0x209 fp=0xc000049fe0 sp=0xc000049f88 pc=0x43d609
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000049fe8 sp=0xc000049fe0 pc=0x4721c1

goroutine 2 [force gc (idle)]:
runtime.gopark(0x7b0de0, 0x9d2ba0, 0x1411, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000034fb0 sp=0xc000034f90 pc=0x43da05
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.forcegchelper()
        /home/kirr/src/tools/go/go/src/runtime/proc.go:255 +0xc5 fp=0xc000034fe0 sp=0xc000034fb0 pc=0x43d8a5
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000034fe8 sp=0xc000034fe0 pc=0x4721c1
created by runtime.init.6
        /home/kirr/src/tools/go/go/src/runtime/proc.go:243 +0x35

goroutine 3 [GC sweep wait]:
runtime.gopark(0x7b0de0, 0x9d2d40, 0x140c, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0000357a8 sp=0xc000035788 pc=0x43da05
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.bgsweep(0xc00005c000)
        /home/kirr/src/tools/go/go/src/runtime/mgcsweep.go:182 +0x13b fp=0xc0000357d8 sp=0xc0000357a8 pc=0x427f9b
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000357e0 sp=0xc0000357d8 pc=0x4721c1
created by runtime.gcenable
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:217 +0x5c

goroutine 4 [sleep]:
runtime.gopark(0x7b0de0, 0x9d3120, 0x1313, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000035f20 sp=0xc000035f00 pc=0x43da05
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.scavengeSleep(0xd35f8, 0xfb058)
        /home/kirr/src/tools/go/go/src/runtime/mgcscavenge.go:241 +0xc5 fp=0xc000035f78 sp=0xc000035f20 pc=0x425e25
runtime.bgscavenge(0xc00005c000)
        /home/kirr/src/tools/go/go/src/runtime/mgcscavenge.go:366 +0x1e5 fp=0xc000035fd8 sp=0xc000035f78 pc=0x426045
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000035fe0 sp=0xc000035fd8 pc=0x4721c1
created by runtime.gcenable
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:218 +0x7e

goroutine 5 [finalizer wait]:
runtime.gopark(0x7b0de0, 0xa05050, 0xc000391410, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000036758 sp=0xc000036738 pc=0x43da05
runtime.goparkunlock(...)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:312
runtime.runfinq()
        /home/kirr/src/tools/go/go/src/runtime/mfinal.go:175 +0xa9 fp=0xc0000367e0 sp=0xc000036758 pc=0x41cce9
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000367e8 sp=0xc0000367e0 pc=0x4721c1
created by runtime.createfing
        /home/kirr/src/tools/go/go/src/runtime/mfinal.go:156 +0x65

goroutine 6 [chan receive]:
runtime.gopark(0x7b0bc8, 0xc00008e058, 0x170e, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0000346d0 sp=0xc0000346b0 pc=0x43da05
runtime.chanrecv(0xc00008e000, 0xc0000347b0, 0xc000092001, 0xc00008e000)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:577 +0x36f fp=0xc000034760 sp=0xc0000346d0 pc=0x409d6f
runtime.chanrecv2(0xc00008e000, 0xc0000347b0, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:444 +0x2b fp=0xc000034790 sp=0xc000034760 pc=0x4099eb
github.com/golang/glog.(*loggingT).flushDaemon(0x9d36e0)
        /home/kirr/src/neo/src/github.com/golang/glog/glog.go:882 +0x8b fp=0xc0000347d8 sp=0xc000034790 pc=0x54914b
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000347e0 sp=0xc0000347d8 pc=0x4721c1
created by github.com/golang/glog.init.0
        /home/kirr/src/neo/src/github.com/golang/glog/glog.go:410 +0x274

goroutine 71677 [runnable]:
runtime.makeslice(0x719360, 0x0, 0x0, 0xc00051c000)
        /home/kirr/src/tools/go/go/src/runtime/slice.go:83 +0xeb fp=0xc0000b2d30 sp=0xc0000b2d28 pc=0x45234b
github.com/kisielk/og-rek.NewDecoderWithConfig(...)
        /home/kirr/src/neo/src/github.com/kisielk/og-rek/ogorek.go:178
lab.nexedi.com/kirr/neo/go/zodb.PyData.decode(0xc00027a100, 0x59, 0x80, 0xc0003bc4b0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/pydata.go:102 +0x28b fp=0xc0000b2e60 sp=0xc0000b2d30 pc=0x59b18b
lab.nexedi.com/kirr/neo/go/zodb.pySetState(0x7fc1dcee3310, 0xc00027ca80, 0x79df3f, 0x16, 0xc0001e4180, 0xc0003bc4b0, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/zodbpy.go:58 +0x65 fp=0xc0000b2ef0 sp=0xc0000b2e60 pc=0x59fc65
lab.nexedi.com/kirr/neo/go/zodb.(*Persistent).PActivate(0xc00027ca80, 0x7fff40, 0xc000337830, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/persistent.go:221 +0x494 fp=0xc0000b30e8 sp=0xc0000b2ef0 pc=0x5976f4
lab.nexedi.com/kirr/neo/go/zodb/btree.(*LOBTree).VGet(0xc0001223f0, 0x7fff40, 0xc000337830, 0x2710, 0xc0000b3380, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/btree/zlobtree.go:204 +0x289 fp=0xc0000b31c0 sp=0xc0000b30e8 pc=0x5a60a9
lab.nexedi.com/nexedi/wendelin.core/wcfs.xverifyΔBTail1(0xc0001c3980, 0xc0004ea450, 0x2a, 0xc0000e3400, 0xc, 0x3db4f59afa66f22, 0x3db4f59afaf5d11, 0xc0002ec000, 0x1, 0x1, ...)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:645 +0x50c fp=0xc0000b3660 sp=0xc0000b31c0 pc=0x6c3acc
lab.nexedi.com/nexedi/wendelin.core/wcfs.xverifyΔBTail(0xc0001c3980, 0xc0004ea450, 0x2a, 0xc0000e3400, 0xc, 0x3db4f59afa66f22, 0x3db4f59afaf5d11, 0xc0002ec000, 0x1, 0x1, ...)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:598 +0xeff fp=0xc0000b3b20 sp=0xc0000b3660 pc=0x6c33df
lab.nexedi.com/nexedi/wendelin.core/wcfs.testΔBTail(0xc0001c3980, 0xc000022c60)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:854 +0x5ff fp=0xc0000b3d30 sp=0xc0000b3b20 pc=0x6c5fff
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs(0xc0001c3980)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1173 +0x8d1 fp=0xc0000b3f80 sp=0xc0000b3d30 pc=0x6ca6d1
testing.tRunner(0xc0001c3980, 0x7b0848)
        /home/kirr/src/tools/go/go/src/testing/testing.go:1123 +0xef fp=0xc0000b3fd0 sp=0xc0000b3f80 pc=0x50326f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000b3fd8 sp=0xc0000b3fd0 pc=0x4721c1
created by testing.(*T).Run
        /home/kirr/src/tools/go/go/src/testing/testing.go:1168 +0x2b3

goroutine 71744 [syscall]:
syscall.Syscall6(0xe8, 0xd, 0xc00018fb6c, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x2, 0x4, 0x0)
        /home/kirr/src/tools/go/go/src/syscall/asm_linux_amd64.s:41 +0x5 fp=0xc00018faa0 sp=0xc00018fa98 pc=0x487325
golang.org/x/sys/unix.EpollWait(0xd, 0xc00018fb6c, 0x7, 0x7, 0xffffffffffffffff, 0xc00018fc44, 0xc0000744e0, 0x0)
        /home/kirr/src/tools/go/g.env/src/golang.org/x/sys/unix/zsyscall_linux_amd64.go:76 +0x72 fp=0xc00018fb10 sp=0xc00018faa0 pc=0x550092
github.com/fsnotify/fsnotify.(*fdPoller).wait(0xc00021a880, 0xc00018fc00, 0x2, 0x0)
        /home/kirr/src/neo/src/github.com/fsnotify/fsnotify/inotify_poller.go:86 +0x91 fp=0xc00018fbd8 sp=0xc00018fb10 pc=0x5ab871
github.com/fsnotify/fsnotify.(*Watcher).readEvents(0xc0000939a0)
        /home/kirr/src/neo/src/github.com/fsnotify/fsnotify/inotify.go:192 +0x206 fp=0xc00019ffd8 sp=0xc00018fbd8 pc=0x5aa9e6
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00019ffe0 sp=0xc00019ffd8 pc=0x4721c1
created by github.com/fsnotify/fsnotify.NewWatcher
        /home/kirr/src/neo/src/github.com/fsnotify/fsnotify/inotify.go:59 +0x1a8

goroutine 71746 [select]:
runtime.gopark(0x7b0e30, 0x0, 0x1809, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000045c10 sp=0xc000045bf0 pc=0x43da05
runtime.selectgo(0xc000045ed8, 0xc000045d98, 0x2, 0x0, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/select.go:338 +0xcef fp=0xc000045d38 sp=0xc000045c10 pc=0x44da0f
lab.nexedi.com/kirr/neo/go/zodb.(*storage)._watcher(0xc0000e3380, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage.go:310 +0x1ce fp=0xc000045fb0 sp=0xc000045d38 pc=0x59d34e
lab.nexedi.com/kirr/neo/go/zodb.(*storage).watcher(0xc0000e3380)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage.go:249 +0x2b fp=0xc000045fd8 sp=0xc000045fb0 pc=0x59d14b
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000045fe0 sp=0xc000045fd8 pc=0x4721c1
created by lab.nexedi.com/kirr/neo/go/zodb.Open
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage.go:148 +0x23e

goroutine 84 [GC worker (idle)]:
runtime.gopark(0x7b0c68, 0xc0002a8100, 0x1418, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000245760 sp=0xc000245740 pc=0x43da05
runtime.gcBgMarkWorker(0xc00002b000)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1891 +0xff fp=0xc0002457d8 sp=0xc000245760 pc=0x42095f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0002457e0 sp=0xc0002457d8 pc=0x4721c1
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 83 [GC worker (idle)]:
runtime.gopark(0x7b0c68, 0xc0002a80f0, 0x1418, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000245f60 sp=0xc000245f40 pc=0x43da05
runtime.gcBgMarkWorker(0xc000028800)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1891 +0xff fp=0xc000245fd8 sp=0xc000245f60 pc=0x42095f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000245fe0 sp=0xc000245fd8 pc=0x4721c1
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 85 [GC worker (idle)]:
runtime.gopark(0x7b0c68, 0xc0002a8110, 0x1418, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc00023e760 sp=0xc00023e740 pc=0x43da05
runtime.gcBgMarkWorker(0xc00002d800)
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1891 +0xff fp=0xc00023e7d8 sp=0xc00023e760 pc=0x42095f
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00023e7e0 sp=0xc00023e7d8 pc=0x4721c1
created by runtime.gcBgMarkStartWorkers
        /home/kirr/src/tools/go/go/src/runtime/mgc.go:1839 +0x77

goroutine 166751 [runnable]:
runtime.gopark(0x7b0bc8, 0xc0004e7d98, 0xc00003160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc0000aae50 sp=0xc0000aae30 pc=0x43da05
runtime.chansend(0xc0004e7d40, 0xc0000aafa0, 0x70ff01, 0x6caa7d, 0xc0006abf40)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:258 +0x24a fp=0xc0000aaed0 sp=0xc0000aae50 pc=0x40908a
runtime.chansend1(0xc0004e7d40, 0xc0000aafa0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc0000aaf08 sp=0xc0000aaed0 pc=0x408e35
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc0004e7d40, 0x0, 0x4)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1197 +0xdd fp=0xc0000aafc8 sp=0xc0000aaf08 pc=0x6caa7d
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc0000aafd0 sp=0xc0000aafc8 pc=0x4721c1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.IntSets
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1184 +0x6b

goroutine 71747 [select]:
runtime.gopark(0x7b0e30, 0x0, 0x1809, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000044d00 sp=0xc000044ce0 pc=0x43da05
runtime.selectgo(0xc000044ef0, 0xc000044e90, 0x2, 0x3db4f4fafaf5d11, 0xa80380c)
        /home/kirr/src/tools/go/go/src/runtime/select.go:338 +0xcef fp=0xc000044e28 sp=0xc000044d00 pc=0x44da0f
lab.nexedi.com/kirr/neo/go/zodb.(*DB).watcher(0xc0000e3400, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/db.go:234 +0x39b fp=0xc000044fc8 sp=0xc000044e28 pc=0x5950db
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000044fd0 sp=0xc000044fc8 pc=0x4721c1
created by lab.nexedi.com/kirr/neo/go/zodb.NewDB
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/db.go:142 +0x167

goroutine 71743 [chan send]:
runtime.gopark(0x7b0bc8, 0xc000022cb8, 0xc00004160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc000042bb8 sp=0xc000042b98 pc=0x43da05
runtime.chansend(0xc000022c60, 0xc000042d38, 0xc000042b01, 0x6cfe11, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:258 +0x24a fp=0xc000042c38 sp=0xc000042bb8 pc=0x40908a
runtime.chansend1(0xc000022c60, 0xc000042d38)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc000042c70 sp=0xc000042c38 pc=0x408e35
lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs.func5(0xc000022c60, 0xc0002a2000, 0x20, 0x20, 0xc0002a2300, 0x20, 0x20, 0xc000310f80, 0xc0001663c0, 0xc0000cc030, ...)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1167 +0x451 fp=0xc000042f70 sp=0xc000042c70 pc=0x6cfe11
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000042f78 sp=0xc000042f70 pc=0x4721c1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.TestΔBTreeAllStructs
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1148 +0x8b3

goroutine 166752 [chan send]:
runtime.gopark(0x7b0bc8, 0xc0004e7df8, 0x10000000000160f, 0x2)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc00043f650 sp=0xc00043f630 pc=0x43da05
runtime.chansend(0xc0004e7da0, 0xc00043f7a0, 0x70ff01, 0x6caa7d, 0xc00036aa90)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:258 +0x24a fp=0xc00043f6d0 sp=0xc00043f650 pc=0x40908a
runtime.chansend1(0xc0004e7da0, 0xc00043f7a0)
        /home/kirr/src/tools/go/go/src/runtime/chan.go:143 +0x35 fp=0xc00043f708 sp=0xc00043f6d0 pc=0x408e35
lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets(0xc0004e7da0, 0x1, 0x4)
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1197 +0xdd fp=0xc00043f7c8 sp=0xc00043f708 pc=0x6caa7d
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00043f7d0 sp=0xc00043f7c8 pc=0x4721c1
created by lab.nexedi.com/nexedi/wendelin.core/wcfs.intSets
        /home/kirr/src/neo/src/lab.nexedi.com/nexedi/wendelin.core/wcfs/δbtail_test.go:1195 +0x229

goroutine 71745 [select]:
runtime.gopark(0x7b0e30, 0x0, 0x1809, 0x1)
        /home/kirr/src/tools/go/go/src/runtime/proc.go:306 +0xe5 fp=0xc00030b858 sp=0xc00030b838 pc=0x43da05
runtime.selectgo(0xc00030be80, 0xc00030ba50, 0x4, 0x0, 0x0)
        /home/kirr/src/tools/go/go/src/runtime/select.go:338 +0xcef fp=0xc00030b980 sp=0xc00030b858 pc=0x44da0f
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage)._watcher(0xc0001201c0, 0xc0000939a0, 0x0, 0x0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:537 +0x1073 fp=0xc00030bf30 sp=0xc00030b980 pc=0x5b4ff3
lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.(*FileStorage).watcher(0xc0001201c0, 0xc0000939a0, 0x0)
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:465 +0xa5 fp=0xc00030bfc8 sp=0xc00030bf30 pc=0x5b3ca5
runtime.goexit()
        /home/kirr/src/tools/go/go/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc00030bfd0 sp=0xc00030bfc8 pc=0x4721c1
created by lab.nexedi.com/kirr/neo/go/zodb/storage/fs1.Open
        /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/fs1/filestorage.go:906 +0x6a5
signal: aborted (core dumped)
FAIL    lab.nexedi.com/nexedi/wendelin.core/wcfs        7.420s
go version, go env, uname, ...
(neo) (z-dev) (g.env) kirr@deco:~/src/neo$ go version
go version go1.15.3 linux/amd64
(neo) (z-dev) (g.env) kirr@deco:~/src/neo$ uname -a
Linux deco 5.8.0-2-amd64 #1 SMP Debian 5.8.10-1 (2020-09-19) x86_64 GNU/Linux
(neo) (z-dev) (g.env) kirr@deco:~/src/neo$ lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux bullseye/sid
Release:        testing
Codename:       bullseye
(neo) (z-dev) (g.env) kirr@deco:~/src/neo$ go env
GO111MODULE="off"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/kirr/.cache/go-build"
GOENV="/home/kirr/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/kirr/src/neo/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/kirr/src/neo:/home/kirr/src/tools/go/g.env"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/kirr/src/tools/go/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/kirr/src/tools/go/go/pkg/tool/linux_amd64"
GCCGO="/usr/bin/gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build559477012=/tmp/go-build -gno-record-gcc-switches"

This time there is the core file.

core.zip

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 15, 2020

Just in case, have you run this test in the race detector?

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 15, 2020

@networkimprov, here you are (this are normal and race runs; there is no GC failue):

.../wcfs$ DBTail_SEED=1602769537289632682 go test -v
=== RUN   TestZBlk
2020/10/15 20:39:04 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestZBlk (0.03s)
=== RUN   TestΔBTail
2020/10/15 20:39:05 zodb: FIXME: open /tmp/δBTail217888886/1.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestΔBTail (2.72s)
=== RUN   TestΔBTreeAllStructs
    δbtail_test.go:1123: # maxdepth=2 maxsplit=1 nkeys=5 n=10 seed=1602769537289632682
2020/10/15 20:39:08 zodb: FIXME: open /tmp/δBTail128030557/1.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestΔBTreeAllStructs (46.42s)
=== RUN   TestIntSets
--- PASS: TestIntSets (0.00s)
=== RUN   TestKVDiff
--- PASS: TestKVDiff (0.00s)
=== RUN   TestKVTxt
--- PASS: TestKVTxt (0.00s)
PASS
ok      lab.nexedi.com/nexedi/wendelin.core/wcfs        49.175s
.../wcfs$ DBTail_SEED=1602769537289632682 go test -v -race
=== RUN   TestZBlk
2020/10/15 20:40:12 zodb: FIXME: open testdata/zblk.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestZBlk (0.10s)
=== RUN   TestΔBTail
2020/10/15 20:40:13 zodb: FIXME: open /tmp/δBTail980323143/1.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestΔBTail (13.17s)
=== RUN   TestΔBTreeAllStructs
    δbtail_test.go:1123: # maxdepth=2 maxsplit=1 nkeys=5 n=10 seed=1602769537289632682
2020/10/15 20:40:27 zodb: FIXME: open /tmp/δBTail188139514/1.fs: raw cache is not ready for invalidations -> NoCache forced
--- PASS: TestΔBTreeAllStructs (220.55s)
=== RUN   TestIntSets
--- PASS: TestIntSets (0.00s)
=== RUN   TestKVDiff
--- PASS: TestKVDiff (0.00s)
=== RUN   TestKVTxt
--- PASS: TestKVTxt (0.00s)
PASS
ok      lab.nexedi.com/nexedi/wendelin.core/wcfs        233.857s

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 16, 2020

I suspect the bug is related to concurrency and in particular sharpy surrounding OS load tend to increase the probability for it to happen. This is likely due to the fact that internal Go scheduling is interdependent here to other processes, becuase the test spawns another python process and communicates with it in synchronous manner.

With this in mind I've found a way to trigger GC crash more quickly via running several instances of the test simultaneously.
Now it happens after something like 3 - 5 - 10 iterations.

Reproduction script: gogccrash.

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 27, 2020

I've digged this down a bit:

  • learned to run the test with GOGC=0 to make GC events more frequent and so the failure to happenn faster;
  • trimmed the whole test program not to use Cgo at all;
  • trimmed the whole test program to have only 1 unsafe place.

I'm currently suspecting that only unsafe place in my code to be the source of this GC crash.
That place is weak reference module, which remembers interface{} into two uintptr words, and later tries to rematerialize that uintptr[2] into interface{} on weak.Ref.Get(). If I change Connection.objtab from map[Oid]*weak.Ref to be just regular map[Oid]IPersistent the crash goes away.

My guess is that rematerializing the object queues more work for GC to mark, but if that catches GC at the time when it things it has finished the marking, that results in the crash. But I have not looked inside for details yet.

https://lab.nexedi.com/kirr/wendelin.core/blob/2de18e8e/wcfs/vendor/lab.nexedi.com/kirr/neo/go/zodb/internal/weak/weak.go#L108-126

I'm pausing my analysis here.
I will try to, hopefully, return to this topic at some time in the future.

@randall77
Copy link
Contributor

@randall77 randall77 commented Oct 27, 2020

remembers interface{} into two uintptr words, and later tries to rematerialize that uintptr[2] into interface{}

That's definitely an unsupported use of unsafe.
I don't see any obvious way in which it breaks, but it is tricky code.

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 27, 2020

@randall77, thanks for feedback. To clarify about "rematerialize": when this happens we know for sure that the object is still alive, because there is synchronization on reference state in between finalizer and Ref.Get: Ref.Get rematerializes the object into Go pointer only until object finalizer marked the reference with .state=objReleased. Ref state changes and the object rematerialization are performed under mutex, so rematerialization and going to released state should be atomic wrt each other. Rematerialization also depends on the "non-moving" property of Go garbage-collector, and this property is verified at runtime(*):

https://lab.nexedi.com/kirr/wendelin.core/blob/2de18e8e/wcfs/vendor/lab.nexedi.com/kirr/neo/go/zodb/internal/weak/weak.go#L69-126

As this issue shows some synchronization is also needed to be done with respect to garbage-collector as well.
I would appreciate any feedback from Go team on how to do it properly here.

(*) yes, stacks can be moved, but on-heap objects are not moved, and weak.Ref is supposed to work for on-heap objects only.

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 27, 2020

That's definitely an unsupported use of unsafe.

Also, maybe I'm missing something, but I don't see any other way to implement weak references.

@randall77
Copy link
Contributor

@randall77 randall77 commented Oct 27, 2020

(*) yes, stacks can be moved, but on-heap objects are not moved, and weak.Ref is supposed to work for on-heap objects only.

Right. This code will force heap allocation because, among other things, passing anything to runtime.SetFinalizer forces heap allocation.

Also, maybe I'm missing something, but I don't see any other way to implement weak references.

I don't either. Go is not designed to support weak references.

Just imagining one possible bug here. See the comment at line 119; it wonders whether we need a write barrier. This code looks like it doesn't, as the write at line 121 is to the stack, not the heap, and stack writes don't need write barriers. But if Get was inlined, that write is no longer necessarily to the stack and might need a write barrier. I don't think Get is small enough to be inlined, but that's the kind of subtlety that makes this code really hard to reason about.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Oct 27, 2020

Weak references and finalizers have the same power. To implement weak references with finalizers, use an intermediate object. The catch is that you need explicit strong pointers as well as explicit weak pointers.

// Package weak manages weak references to pointers.
// In order to use this with a particular pointer, you must use
// strong pointers, defined in this package.
// You may also use weak pointers.
// If all the strong pointers to some value are garbage collected,
// then the value may be collected, even if weak pointers still exist.
package weak

import "runtime"

// Strong is a strong pointer to some object.
// To fetch the pointer, use the Get method.
type Strong struct {
	p *intermediate
}

// Get returns the value to which s points.
func (s *Strong) Get() interface{} {
	return s.p.val
}

// Weak returns a weak reference to the value to which Strong points.
func (s *Strong) Weak() *Weak {
	return &Weak{s.p}
}

// clear is a finalizer for s.
func (s *Strong) clear() {
	s.p.val = nil
}

// Create a strong pointer to an object.
func MakeStrong(val interface{}) *Strong {
	r := &Strong{&intermediate{val}}
	runtime.SetFinalizer(r, func(s *Strong) { s.clear() })
	return r
}

// Weak is a weak reference to some value.
type Weak struct {
	p *intermediate
}

// Get returns the value to which w points.
// If there are no remaining Strong pointers to the value,
// Get may return nil.
func (w *Weak) Get() interface{} {
	return w.p.val
}

// intermediate is used to implement weak references.
type intermediate struct {
	val interface{}
}

@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 28, 2020

@randall77, thanks for feedback and commenting on potential trickiness regarding write barrier.
@ianlancetaylor, thanks a lot for weak package example. There is a race in between Strong.clear finalizer and Weak.Get, but it is easy to fix with adding explicit synchronization.

The catch is that you need explicit strong pointers as well as explicit weak pointers.

Explicitly using Strong is indeed the price for not having to use unsafe. That indeed works; thanks a lot, again, for the example. However the price might be too high: it requires all users of an API to use Strong instead of regular Go pointers. Using Weak + something else only in the place that wants to organize weak references would be ok, but exposing Strong and requiring all users to use it instead of regular Go pointers seem to go too far in my view. In other words the time one would want to add a weak pointer in one - usually well localized and internal - place, he/she has to immediately change all public API that returns T* to return Strong<T*>. Maybe its just me, but I believe this creates unneccessary confusion ("what is the difference in between regular T* and Strong<T*> ?") and unneccessary complication for regular case.

So, still, is there maybe a way to synchronize with the garbage-collector, and notify it properly about rematerialized pointer so that it does not see such rematerialization as marking invariant breakage?

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Oct 28, 2020

Well, technically all that is required is that there be at least one live Strong pointer. Which I think is much the same requirement that your code also has. (Or perhaps I misunderstand your code but I think it must have some requirement along those lines.)

As @randall77 said, your code is an unsupported use of unsafe. If you want to be able to safely rematerialize a pointer other than through the mechanisms documented at https://golang.org/pkg/unsafe, that would be a language change proposal that should go through the proposal process. But I think it is extremely unlikely that any such proposal would be accepted.

@ianlancetaylor ianlancetaylor removed this from the Go1.16 milestone Oct 28, 2020
@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Oct 28, 2020
@navytux
Copy link
Contributor Author

@navytux navytux commented Oct 29, 2020

@ianlancetaylor, thanks for feedback.

Well, technically all that is required is that there be at least one live Strong pointer. Which I think is much the same requirement that your code also has. (Or perhaps I misunderstand your code but I think it must have some requirement along those lines.)

Unfortunately it is not the case: the objects - that Connection.Get returns to users - are returned as regular Go pointers as IPersistent interface. It would require to change every user to use Strong[IPersistent] if we are to use Strong at all. It would also load users to care to manually maintain those Strong[IPersistent] pointers live, after e.g. they upcast that IPersistent to particular type or higher interfaces that implements it. In my view it would create another round of hard to track bugs, where users would fail to notice they have to runtime.KeepAlive(original Strong[IPersistent]) after they upcasted returned object to a particular type.

The bug I'm talking about here is of exactly the same nature that Connection.objtab is trying to avoid via using weak pointers in the first place: if for an object A

  1. Strong is returned,
  2. type of Strong.Get result is checked at runtime, seen as concrete particulat known type, and upcasted to that into regular Go pointer
  3. that upcasted pointer is further used
  4. original Strong is no longer used
  5. original Strong is garbage-collected
  6. Strong.clear is called
  7. this clears Weak.p.val to nil for the weak pointer that is sitting in Connection.objtab[oid]

Now if another object B2 references in the database on disk object A by A's OID, and that object B2 is accessed in the program, when the program will try to access/create live object for A in RAM via B2->A database link, it will look into Connection.objtab[A.oid], see the weak pointer there is nil, and create another in-RAM object for A. This breaks isomorphism in between in-database and in-RAM objects and so eventually leads to database corruption.

The only solution I see is

  1. either use kind of Strong pointers everywhere, or
  2. teach weak references to work without exposing Striong at all.

With 1 by "everywhere" I really mean everywhere - for every pointer that potentially originates from Strong pointer. But then Strongs just replace all regular Go pointers...

As @randall77 said, your code is an unsupported use of unsafe. If you want to be able to safely rematerialize a pointer other than through the mechanisms documented at https://golang.org/pkg/unsafe, that would be a language change proposal that should go through the proposal process. But I think it is extremely unlikely that any such proposal would be accepted.

I see...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants