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 : fatal error: malloc deadlock #41775

Open
finnbear opened this issue Oct 4, 2020 · 2 comments
Open

runtime : fatal error: malloc deadlock #41775

finnbear opened this issue Oct 4, 2020 · 2 comments

Comments

@finnbear
Copy link

@finnbear finnbear commented Oct 4, 2020

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?

The above is the latest release

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

Firefox web browser on Linux

go env Output
$ GOOS=js GOARCH=wasm go env
GO111MODULE=""
GOARCH="wasm"
GOBIN=""
GOCACHE="/home/finnb/.cache/go-build"
GOENV="/home/finnb/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/finnb/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="js"
GOPATH="/home/finnb/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/finnb/sdk/go1.15.2"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/finnb/sdk/go1.15.2/pkg/tool/linux_amd64"
GCCGO="gccgo"
GOWASM=""
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="0"
GOMOD="/home/finnb/git/finnbear/project_name_here/src/client/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build021444874=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I refreshed the page containing my WebAssembly app.

What did you expect to see?

App works properly, neither the new page/instance of the app nor the old page/instance of the app crashes. That is to say that the app starts without error but also exits cleanly when the page is being destroyed.

What did you see instead?

first time (malloc deadlock stack trace)
fatal error: malloc deadlock wasm.js:50:14
 wasm.js:50:14
goroutine 6 [running]: wasm.js:50:14
runtime.throw(0x5dd0f, 0xf) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/panic.go:1116 +0x7 fp=0x1471720 sp=0x14716f8 pc=0x11df0007 wasm.js:50:14
runtime.mallocgc(0x10, 0x37420, 0x16a3001, 0x16cf0007) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:959 +0xd3 fp=0x14717c0 sp=0x1471720 pc=0x109a00d3 wasm.js:50:14
runtime.newobject(0x37420, 0x4042000000000000) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:1195 +0x4 fp=0x14717e8 sp=0x14717c0 pc=0x109c0004 wasm.js:50:14
runtime.handleEvent() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/lock_js.go:232 +0x2 fp=0x1471838 sp=0x14717e8 pc=0x10910002 wasm.js:50:14
runtime.(*mheap).alloc(0x27e820, 0x1, 0x27010c, 0x3f4) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/mheap.go:912 +0xb fp=0x1471880 sp=0x1471838 pc=0x1156000b wasm.js:50:14
runtime.(*mcentral).grow(0x27f8c8, 0x0) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/mcentral.go:506 +0x6 fp=0x14718b8 sp=0x1471880 pc=0x10e80006 wasm.js:50:14
runtime.(*mcentral).cacheSpan(0x27f8c8, 0x18ec968) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/mcentral.go:177 +0x53 fp=0x1471938 sp=0x14718b8 pc=0x10e60053 wasm.js:50:14
runtime.(*mcache).refill(0x2a0108, 0xc) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/mcache.go:142 +0xc fp=0x1471960 sp=0x1471938 pc=0x10e3000c wasm.js:50:14
runtime.(*mcache).nextFree(0x2a0108, 0xc, 0x50, 0x53d20, 0x10cd0016) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:880 +0xa fp=0x1471998 sp=0x1471960 pc=0x1099000a wasm.js:50:14
runtime.mallocgc(0x50, 0x53d20, 0x2a0101, 0x1000400016a3680) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:1061 +0xb0 fp=0x1471a38 sp=0x1471998 pc=0x109a00b0 wasm.js:50:14
runtime.makeslice(0x53d20, 0x5, 0x5, 0x279680) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/slice.go:98 +0xd fp=0x1471a60 sp=0x1471a38 pc=0x1282000d wasm.js:50:14
syscall/js.makeArgs(0x1471b90, 0x5, 0x5, 0x1282000d, 0x10, 0x22ee0, 0x279601, 0x16aa220, 0x16cf0007) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/syscall/js/js.go:362 +0x2 fp=0x1471aa8 sp=0x1471a60 pc=0x16cf0002 wasm.js:50:14
syscall/js.Value.Invoke(0x7ff800040000004a, 0x41aa60, 0x1471b90, 0x5, 0x5, 0x10c70009, 0x16a73e0) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/syscall/js/js.go:411 +0x2 fp=0x1471b58 sp=0x1471aa8 pc=0x16d20002 wasm.js:50:14
mazean/client/renderer/gl.DrawElementsInstancedI(...) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/gl/gl.go:701 wasm.js:50:14
mazean/client/renderer.(*Instances).Draw(0x4e4c00) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/instances.go:157 +0xc fp=0x1471be8 sp=0x1471b58 pc=0x1b4f000c wasm.js:50:14
mazean/client/renderer.(*Instances).BindAndDraw(0x4e4c00) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/instances.go:140 +0x9 fp=0x1471c48 sp=0x1471be8 pc=0x1b4d0009 wasm.js:50:14
mazean/client/renderer.renderScene(0xd580150673af7, 0xd580150673af7, 0xf4f835b5e2d6261, 0x166b900, 0x166b980, 0x169ace0, 0x3fa10a137f38c000, 0x1) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/renderer.go:711 +0x23a fp=0x1472b38 sp=0x1471c48 pc=0x1b6f023a wasm.js:50:14
mazean/client/renderer.renderScene(0xd580150673af7, 0xd580150673af7, 0xf4f835b5e2d6261, 0x166b700, 0x166b680, 0x1473c10, 0x3fa10a137f38c000, 0x0) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/renderer.go:646 +0x193 fp=0x1473a28 sp=0x1472b38 pc=0x1b6f0193 wasm.js:50:14
mazean/client/renderer.Render(0xd580150673af7, 0xf4f835b5e2d6261, 0xf4f835b5e2d0000, 0x3ff0000000000000, 0x4063e5aaa3ad18d2, 0x3fa10a137f38c000, 0x6e320) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/renderer.go:302 +0x4f fp=0x1474468 sp=0x1473a28 pc=0x1b6d004f wasm.js:50:14
main.main.func4(0x7ff800040000000d, 0x1697430, 0x1699c70, 0x1, 0x1, 0x1697438, 0x40001475f00) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/main.go:304 +0xed fp=0x1475ec0 sp=0x1474468 pc=0x1c0d00ed wasm.js:50:14
syscall/js.handleEvent() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/syscall/js/func.go:96 +0x24 fp=0x1475f90 sp=0x1475ec0 pc=0x16c20024 wasm.js:50:14
runtime.handleEvent() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/lock_js.go:238 +0xa fp=0x1475fe0 sp=0x1475f90 pc=0x1091000a wasm.js:50:14
runtime.goexit() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/asm_wasm.s:428 +0x1 fp=0x1475fe8 sp=0x1475fe0 pc=0x13c70001 wasm.js:50:14
created by runtime.beforeIdle wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/lock_js.go:194 +0x11 wasm.js:50:14
 wasm.js:50:14
goroutine 1 [semacquire, 2 minutes]: wasm.js:50:14
sync.runtime_Semacquire(0x574a98) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/sema.go:56 +0x2 wasm.js:50:14
sync.(*WaitGroup).Wait(0x574a90) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/sync/waitgroup.go:130 +0x10 wasm.js:50:14
main.main() wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/main.go:352 +0x1b
```
second time (console log + malloc deadlock stack trace)
Script terminated by timeout at:
runtime.heapBitsSetType@https://mazean.com/client/wasm/client.wasm:wasm-function[243]:0x30c26
runtime.mallocgc@https://mazean.com/client/wasm/client.wasm:wasm-function[177]:0x1b717
runtime.makeslice@https://mazean.com/client/wasm/client.wasm:wasm-function[665]:0x95cb2
syscall_js.makeArgs@https://mazean.com/client/wasm/client.wasm:wasm-function[1766]:0x145d52
syscall_js.Value.Invoke@https://mazean.com/client/wasm/client.wasm:wasm-function[1769]:0x146905
mazean_client_renderer.renderScene@https://mazean.com/client/wasm/client.wasm:wasm-function[2950]:0x2c0ee0
mazean_client_renderer.renderScene@https://mazean.com/client/wasm/client.wasm:wasm-function[2950]:0x2befeb
mazean_client_renderer.Render@https://mazean.com/client/wasm/client.wasm:wasm-function[2948]:0x2b8fd9
main.main.func4@https://mazean.com/client/wasm/client.wasm:wasm-function[3108]:0x336861
syscall_js.handleEvent@https://mazean.com/client/wasm/client.wasm:wasm-function[1753]:0x142f11
runtime.handleEvent@https://mazean.com/client/wasm/client.wasm:wasm-function[168]:0x183da
wasm_export_resume@https://mazean.com/client/wasm/client.wasm:wasm-function[997]:0xcc9c0
_resume@https://mazean.com/client/js/lib/wasm.js:574:23
_makeFuncWrapper/<@https://mazean.com/client/js/lib/wasm.js:586:9
animationFrame@https://mazean.com/client/js/client.min.js:1476:67
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
FrameRequestCallback*animationFrame@https://mazean.com/client/js/client.min.js:1476:205
client.wasm:199718:1
fatal error: malloc deadlock wasm.js:50:14
 wasm.js:50:14
goroutine 6 [running]: wasm.js:50:14
runtime.throw(0x5dd0f, 0xf) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/panic.go:1116 +0x7 fp=0x455900 sp=0x4558d8 pc=0x11df0007 wasm.js:50:14
runtime.mallocgc(0x10, 0x37420, 0x10710001, 0x26cce0) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:959 +0xd3 fp=0x4559a0 sp=0x455900 pc=0x109a00d3 wasm.js:50:14
runtime.newobject(0x37420, 0xb75858) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:1195 +0x4 fp=0x4559c8 sp=0x4559a0 pc=0x109c0004 wasm.js:50:14
runtime.handleEvent() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/lock_js.go:232 +0x2 fp=0x455a18 sp=0x4559c8 pc=0x10910002 wasm.js:50:14
runtime.mallocgc(0x6d94d0, 0x30, 0x30, 0x53d20) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:903 +0x1 fp=0x455ab8 sp=0x455a18 pc=0x109a0001 wasm.js:50:14
runtime.mallocgc(0x30, 0x53d20, 0x1, 0x6e4b60) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:1090 +0x7e fp=0x455b58 sp=0x455ab8 pc=0x109a007e wasm.js:50:14
runtime.makeslice(0x53d20, 0x3, 0x3, 0x0) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/slice.go:98 +0xd fp=0x455b80 sp=0x455b58 pc=0x1282000d wasm.js:50:14
syscall/js.makeArgs(0x456a30, 0x3, 0x3, 0x0, 0x8, 0x4f3310, 0xb7f130, 0x279680, 0x3) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/syscall/js/js.go:362 +0x2 fp=0x455bc8 sp=0x455b80 pc=0x16cf0002 wasm.js:50:14
syscall/js.Value.Invoke(0x7ff8000400000056, 0x41aaf0, 0x456a30, 0x3, 0x3, 0x0, 0x0) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/syscall/js/js.go:411 +0x2 fp=0x455c78 sp=0x455bc8 pc=0x16d20002 wasm.js:50:14
mazean/client/renderer/gl.StencilOp(...) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/gl/gl.go:1021 wasm.js:50:14
mazean/client/renderer.renderScene(0x178d10aa59ee35, 0x178d10aa59ee35, 0x93704aee0040b6f, 0x6d2500, 0x6d2580, 0x6e4660, 0x3fa9c8c9320d9a00, 0x1) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/renderer.go:688 +0x25a fp=0x456b68 sp=0x455c78 pc=0x1b6f025a wasm.js:50:14
mazean/client/renderer.renderScene(0x178d10aa59ee35, 0x178d10aa59ee35, 0x93704aee0040b6f, 0x6d2200, 0x6d2180, 0x457c40, 0x3fa9c8c9320d9a00, 0x0) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/renderer.go:646 +0x193 fp=0x457a58 sp=0x456b68 pc=0x1b6f0193 wasm.js:50:14
mazean/client/renderer.Render(0x178d10aa59ee35, 0x93704aee0040b6f, 0x93704aee0040000, 0x3ff0000000000000, 0x403769b280f12c28, 0x3fa9c8c9320d9a00, 0x6e2f8) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/renderer/renderer.go:302 +0x4f fp=0x458498 sp=0x457a58 pc=0x1b6d004f wasm.js:50:14
main.main.func4(0x7ff800040000000d, 0x41bc08, 0x6bdf30, 0x1, 0x1, 0x41bc10, 0x40000459f00) wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/main.go:303 +0xed fp=0x459ec0 sp=0x458498 pc=0x1c0d00ed wasm.js:50:14
syscall/js.handleEvent() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/syscall/js/func.go:96 +0x24 fp=0x459f90 sp=0x459ec0 pc=0x16c20024 wasm.js:50:14
runtime.handleEvent() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/lock_js.go:238 +0xa fp=0x459fe0 sp=0x459f90 pc=0x1091000a wasm.js:50:14
runtime.goexit() wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/asm_wasm.s:428 +0x1 fp=0x459fe8 sp=0x459fe0 pc=0x13c70001 wasm.js:50:14
created by runtime.beforeIdle wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/lock_js.go:194 +0x11 wasm.js:50:14
 wasm.js:50:14
goroutine 1 [semacquire]: wasm.js:50:14
sync.runtime_Semacquire(0x574a98) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/sema.go:56 +0x2 wasm.js:50:14
sync.(*WaitGroup).Wait(0x574a90) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/sync/waitgroup.go:130 +0x10 wasm.js:50:14
main.main() wasm.js:50:14
	/home/finnb/git/finnbear/mazean/src/client/main.go:351 +0x1b wasm.js:50:14
exit code: 2

I'm not sure whether these logs were from the new (post-browser-refresh) instance of the app or the dying (pre-browser-refresh) instance of the app (both logs were from when I refreshed the page). However, my app was completely unresponsive the first time and totally responsive after the second time, implying that the first logs were from the new instance and the second logs were from the dying instance.

The key issue is that runtime.handleEvent() appears twice in the stack trace, which should be impossible as JS is single threaded, but an exception to that rule may occur when JS is terminating synchronous tasks.

It is important to emphacize that this is a very rare, not easily-reproducible issue. I have been developing this particular app for around 5 months and this is the first time I have experienced an error of this nature. Today is the first time I have seen the issue, and it has happened twice so far. The second time, the console had additional info.

The source code of my project is currently private but I would be willing to grant access to any go developers who are curious.

@finnbear finnbear changed the title js/wasm: Memory deadlock (rare, not reproducible) js/wasm: memory deadlock (rare, not reproducible) Oct 4, 2020
@finnbear finnbear changed the title js/wasm: memory deadlock (rare, not reproducible) js/wasm: malloc deadlock (rare, not reproducible) Oct 4, 2020
@finnbear finnbear changed the title js/wasm: malloc deadlock (rare, not reproducible) js/wasm: malloc deadlock when "script terminated by timeout" Oct 4, 2020
@agnivade
Copy link
Contributor

@agnivade agnivade commented Oct 4, 2020

Interesting. The 2 stack traces are slightly different, but they both stem from the calling of nested mallocgc.

Even more surprising is this:

runtime.mallocgc(0x6d94d0, 0x30, 0x30, 0x53d20) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:903 +0x1 fp=0x455ab8 sp=0x455a18 pc=0x109a0001 wasm.js:50:14
runtime.mallocgc(0x30, 0x53d20, 0x1, 0x6e4b60) wasm.js:50:14
	/home/finnb/sdk/go1.15.2/src/runtime/malloc.go:1090 +0x7e fp=0x455b58 sp=0x455ab8 pc=0x109a007e wasm.js:50:14

/cc @neelance

@agnivade agnivade changed the title js/wasm: malloc deadlock when "script terminated by timeout" runtime : fatal error: malloc deadlock Oct 4, 2020
@agnivade agnivade added this to the Backlog milestone Oct 4, 2020
@neelance
Copy link
Member

@neelance neelance commented Oct 15, 2020

In both traces the call to runtime.handleEvent is bad, because neither runtime.(*mheap).alloc nor runtime.mallocgc can call this function. This can only happen if JS calls into Go code at a point when it is not supposed to.

And it seems like this is exactly what happened in the second trace. It first says:

Script terminated by timeout at:
runtime.heapBitsSetType@https://mazean.com/client/wasm/client.wasm:wasm-function[243]:0x30c26
runtime.mallocgc@https://mazean.com/client/wasm/client.wasm:wasm-function[177]:0x1b717

It seems like the WebAssebly host decided to forcefully terminate the WebAssembly binary and mallocgc was almost at the top of the stack. This left Go's stack in a state that is not safe for returning execution to JS. Afterwards your JS code again invokes a Go callback, which triggers handleEvent, but it now gets executed on top of a broken Go stack. 💥

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
3 participants
You can’t perform that action at this time.