Asyncify produces very deep stacktraces

[RReverser]

Consider a simplified example like this that makes use of Asyncify repeatedly somewhere in the callstack:

#include <emscripten.h>

void a() {
	for (int i = 0; i < 10; i++) {
		EM_ASM({ console.warn('log') });
		emscripten_sleep(100);
	}
}

void b() {
	a();
}

void c() {
	b();
}

int main() {
	c();
}

I'm compiling it with -s ASYNCIFY -g2 (just preserving function names, not even using DWARF to reduce scope of discussion):

$ emcc temp.c -o temp.html -s ASYNCIFY -g2

Now when I run it in DevTools, each console.warn gets an attached stacktrace. The first log will have an expected stacktrace:

log
1028	@	temp.js:1734
_emscripten_asm_const_int	@	temp.js:1825
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x40f
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
(anonymous)	@	temp.js:1561
callMain	@	temp.js:2451
doRun	@	temp.js:2521
(anonymous)	@	temp.js:2532
setTimeout (async)		
run	@	temp.js:2528
runCaller	@	temp.js:2429
removeRunDependency	@	temp.js:1471
receiveInstance	@	temp.js:1652
receiveInstantiationResult	@	temp.js:1669
Promise.then (async)		
(anonymous)	@	temp.js:1696
Promise.then (async)		
instantiateAsync	@	temp.js:1694
createWasm	@	temp.js:1723
(anonymous)	@	temp.js:2112

The second one, however, resumes from the same place and appends the whole rewinding done by Asyncify as new stackframes:

log
1028	@	temp.js:1734
_emscripten_asm_const_int	@	temp.js:1825
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x40f
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739               <-- main again
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739                <-- first main
ret.<computed>	@	temp.js:1932
(anonymous)	@	temp.js:1561
callMain	@	temp.js:2451
doRun	@	temp.js:2521
(anonymous)	@	temp.js:2532
setTimeout (async)		
run	@	temp.js:2528
runCaller	@	temp.js:2429
removeRunDependency	@	temp.js:1471
receiveInstance	@	temp.js:1652
receiveInstantiationResult	@	temp.js:1669
Promise.then (async)		
(anonymous)	@	temp.js:1696
Promise.then (async)		
instantiateAsync	@	temp.js:1694
createWasm	@	temp.js:1723
(anonymous)	@	temp.js:2112

By the time we reach 10th execution, stackframe becomes huge, with main -> __original_main -> a -> b -> c -> ... repeated 10 times:

temp.js:1734 log
1028	@	temp.js:1734
_emscripten_asm_const_int	@	temp.js:1825
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x40f
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
doRewind	@	temp.js:1994
(anonymous)	@	temp.js:2025
callUserCallback	@	temp.js:1869
(anonymous)	@	temp.js:1841
setTimeout (async)		
safeSetTimeout	@	temp.js:1839
(anonymous)	@	temp.js:1846
handleSleep	@	temp.js:2005
_emscripten_sleep	@	temp.js:1845
imports.<computed>	@	temp.js:1908
a	@	temp.wasm:0x461
b	@	temp.wasm:0x57e
c	@	temp.wasm:0x604
__original_main	@	temp.wasm:0x68a
main	@	temp.wasm:0x739
ret.<computed>	@	temp.js:1932
(anonymous)	@	temp.js:1561
callMain	@	temp.js:2451
doRun	@	temp.js:2521
(anonymous)	@	temp.js:2532
setTimeout (async)		
run	@	temp.js:2528
runCaller	@	temp.js:2429
removeRunDependency	@	temp.js:1471
receiveInstance	@	temp.js:1652
receiveInstantiationResult	@	temp.js:1669
Promise.then (async)		
(anonymous)	@	temp.js:1696
Promise.then (async)		
instantiateAsync	@	temp.js:1694
createWasm	@	temp.js:1723
(anonymous)	@	temp.js:2112

The original reason I've noticed this is because DevTools was rendering Console items very slowly in a real-world app using Asyncify - this occured because all those duplicate entries were being resolved against debug info.

However it affects not only Console but makes step-by-step debugging pretty complicated as well, since the DevTools stackframes also show lots of repeated entries instead of the actual stacktrace.

The reason this happens is because Asyncify rewinds the stack by actually calling into each function again on its way down. Even though we unwind before that, I suspect there's no way for V8 / DevTools to connect the dots and understand that this is a simple rewinding and not actual new calls, so it displays them as new frame entries. (@bmeurer correct me if I'm wrong, as you worked on async stacktraces for JS - maybe there is a way to improve this? also cc @pfaffe)

Instead, perhaps it's something we could fix on Emscripten side. One idea I had is that when user calls Asyncify.handleSleep, perhaps we could unwind the stack first, and only then invoke the callback - this way it would get a stacktrace at the top of JS glue instead of somewhere deep inside Wasm, and this way rewinding would naturally add each function only once. However, I'm not sure if this might break some real-world use-cases - does any code in the wild rely on the callback being invoked before unwinding?

[bmeurer]

I guess unwinding on the Emscripten side could help to fix this. Although I have to admit that I've seen this before in Emscripten projects that weren't even using Asyncify.

Maybe we should add some logic to the V8 inspector to detect and remove cycles in async stack traces. Currently the inspector is sort of dumb and just records and stitches together async task stacks.

cc @hashseed

[RReverser]

Maybe we should add some logic to the V8 inspector to detect and remove cycles in async stack traces.

If it's possible, that would solve the problem yeah.