Deno: Exception throw is VERY slow in Deno

[kevinkassimo]

When running a script that throws an uncaught exception, it takes a few seconds to actually print out the error message and exit.

From @kitsonk

the issue relates to unwinding the stack traces back to their sources

[ry]

Yes I’ve noticed it too - I think there must be a timeout somewhere (tokio?)
I think the way to debug it is to sample the stacks during the delay and see what’s being executed

[kitsonk]

or is the source-map really slow? I guess it should be _that_ slow though.

[ry]

I did a bit of investigation:

tests/error_001.ts is a good example of the slowness. I am debugging with ./out/debug/deno tests/error_001.ts -D

I traced the slowness to a specific call consumer.originalPositionFor() which enters the 3rd party source-maps library.
https://github.com/denoland/deno/blob/2cfa60832496902089b9d73d3954318aa8a1fe2a/js/v8_source_maps.ts#L245-L251

It does not hang on the first call to originalPositionFor().

For error_001.ts, there are six total calls, it hangs on the 4th.

DEBUG JS - originalPositionFor { source: "/Users/rld/src/deno/tests/error_001.ts", line: 2, column: 10 }
DEBUG JS - originalPositionFor { source: "/Users/rld/src/deno/tests/error_001.ts", line: 5, column: 4 }
DEBUG JS - originalPositionFor { source: "/Users/rld/src/deno/tests/error_001.ts", line: 7, column: 0 }
DEBUG JS - compiler.getGeneratedContents gen/bundle/main.js
DEBUG JS - compiler.getGeneratedContents main.js.map
DEBUG JS - originalPositionFor { source: "gen/bundle/main.js", line: 132699, column: 15 } 
# HANGS HERE
DEBUG JS - originalPositionFor { source: "gen/bundle/main.js", line: 132893, column: 19 }
DEBUG JS - originalPositionFor { source: "gen/bundle/main.js", line: 133085, column: 15 }

So it appears that it's the first position decoding inside of main.js.map... which makes sense since it's a 13MB file.

Ideally we would be able to decode main.js.map at compile time...

[ry]

So, the above commit solves the problem but makes incremental builds 3m instead of 30s due to longer decoding the source map during the snapshot process. Additionally it more than doubles binary size...
This is very painful - but I think it's necessary.

[kitsonk]

@ry the source maps include the sources at the moment, part of why it is so large. I suspect they aren't needed for just unwrapping stacks, so I suspect we can eliminate them. If you don't get the chance, I will try today and raise a PR if it works.

[kitsonk]

@ry taking a look at it, rollup is adding sourcesContent to the .map automatically. I can't chase it down, yet, but it does not seem to be "flaggable" at the moment. I think I will raise an issue to get it "flaggable" because not everyone needs it (like us), but I suspect it would take a while to filter through. One possibility it to just "hack" it out during the build process, possibly by rewriting the .map JSON object after deleting the code. I will try to figure out some approach later today.

[ry]

At minimum we need to be tracking this slowness. I add error_001.ts to the benchmark page in the above commit.

@kitsonk Cool thanks for looking into it! Maybe to just evaluate if that will work, manually hack rollup in third_party/node_modules

[kitsonk]

@ry further investigation shows that it is rollup that is specifically inlining the sources, that it isn't optional, but it feels like a fairly clean process to make it optional. I am going to raise an issue and a PR for rollup, but once I have it working I can take our custom build into third_party while it hopefully gets integrated into Rollup. Seems like a very logical feature.

[kitsonk]

I have raised a PR at rollup/rollup#2531 which fixes this and will attempt to integrate the custom build into third_party until the feature is published in Rollup (assuming it is accepted).

[jeromegn]

FWIW we had that problem on fly.rs and we decided to do sourcemaps in Rust instead of inside V8. The first error that needed to print original lines from the source map would take a long long time. The sourcemap crate for Rust seems to handle that much better.

https://github.com/superfly/fly.rs/blob/master/src/runtime.rs#L261-L302

It's not ideal, but it's implemented using a "source map thread" + channel, since the sourcemap crate is not thread-safe. It's a channel accepting a Vec of tuples (line, column, function name, filename) and a oneshot for the "response".

I'm sure there are better ways haha. It could at least be rewritten with a nicer API.

It also had the side-effect of freeing a good chunk of memory inside V8 (from 6-7MB down to 3MB.) I assume that memory was "transferred" to Rust though. (edit: maybe not, looks like that crate is pretty efficient at parsing a source map and doesn't need to load it all in memory)