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

process: reduce the number of internal frames in async stack trace #27392

Closed
wants to merge 3 commits into from

Conversation

Projects
None yet
8 participants
@joyeecheung
Copy link
Member

commented Apr 24, 2019

Previously, we call the JS land runNextTicks implementation
immediately from JS land after evaluating the main module or the
input, so these synchronous JS call frames would show up in the stack
trace of the async errors, which can be confusing. This patch moves
those calls into C++ so that more of these internal scheduler
implementation details can be hidden and the users can see
a cleaner async JS stack trace.

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • commit message follows commit guidelines
process: reduce the number of internal frames in async stack trace
Previously, we call the JS land `runNextTicks` implementation
immediately from JS land after evaluating the main module or the
input, so these synchronous JS call frames would show up in the stack
trace of the async errors, which can be confusing. This patch moves
those calls into C++ so that more of these internal scheduler
implementation details can be hidden and the users can see a cleaner
a cleaner async JS stack trace.
@nodejs-github-bot

This comment has been minimized.

at two (*fixtures*async-error.js:17:9)
at async three (*fixtures*async-error.js:20:3)
at async four (*fixtures*async-error.js:24:3)
at async main ([eval]:7:5)

This comment has been minimized.

Copy link
@joyeecheung

joyeecheung Apr 24, 2019

Author Member

It was previously:

Error: test
    at one (/Users/joyee/projects/node/test/fixtures/async-error.js:4:9)
    at two (/Users/joyee/projects/node/test/fixtures/async-error.js:17:9)
    at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:54:5)
    at evalScript (internal/process/execution.js:87:11)
    at internal/main/eval_string.js:23:3
    at async three (/Users/joyee/projects/node/test/fixtures/async-error.js:20:3)
    at async four (/Users/joyee/projects/node/test/fixtures/async-error.js:24:3)
    at async main ([eval]:7:5)
Error: test
at one (eval:1:2:9)
at two (eval:1:15:9)
at processTicksAndRejections (internal/process/task_queues.js:*:*)

This comment has been minimized.

Copy link
@joyeecheung

joyeecheung Apr 24, 2019

Author Member

We can't totally eliminate this yet because the tick callback is, in the end, implemented in JavaScript to reduce the overhead of calling into JS. (This patch only moves the initial one-off invocation of the tick callback to C++, all subsequent invocations of the tick callback already come from C++, usually through MakeCallback).

To hide this eventually we may need an API from V8 to mark the call site as internal. But it is at least better than

Error: test
    at one (eval:1:2:9)
    at two (eval:1:15:9)
    at processTicksAndRejections (internal/process/task_queues.js:88:5)
    at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:58:3)
    at evalModule (internal/process/execution.js:54:11)
    at internal/main/eval_string.js:21:3
    at async three (eval:1:18:3)
    at async four (eval:1:22:3)
    at async main (eval:1:28:5)`
at two (*fixtures*async-error.js:17:9)
at async three (*fixtures*async-error.js:20:3)
at async four (*fixtures*async-error.js:24:3)
at async main (*message*async_error_microtask_main.js:7:5)

This comment has been minimized.

Copy link
@joyeecheung

joyeecheung Apr 24, 2019

Author Member

It was previously:

Error: test
    at one (/Users/joyee/projects/node/test/fixtures/async-error.js:4:9)
    at two (/Users/joyee/projects/node/test/fixtures/async-error.js:17:9)
    at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:54:5)
    at Function.Module.runMain (internal/modules/cjs/loader.js:828:11)
    at internal/main/run_main_module.js:17:11
    at async three (/Users/joyee/projects/node/test/fixtures/async-error.js:20:3)
    at async four (/Users/joyee/projects/node/test/fixtures/async-error.js:24:3)
    at async main (/Users/joyee/projects/node/test/message/async_error_microtask_main.js:7:5)
@nodejs-github-bot

This comment has been minimized.

@BridgeAR
Copy link
Member

left a comment

LGTM. I guess we might want to try to reduce a couple of our internal frames in general. The current default frames are ten and especially with async stack traces it is important not to exceed those just with internal frames that are not important to the user.

@silverwind

This comment has been minimized.

Copy link
Contributor

commented Apr 24, 2019

reduce a couple of our internal frames in general

I'm thinking that all internal frames should be hidden by default and optionally exposable via NODE_SHOW_INTERNAL_STACKFRAMES or similar variable.

Maybe even re-purpose the --expose-internals flag for it.

@nodejs-github-bot

This comment has been minimized.

@joyeecheung

This comment has been minimized.

Copy link
Member Author

commented Apr 25, 2019

Fixed the test for windows, it's a bit tricky to get the path right so I just went with concatenating the fixture in the string being eval'ed.

I'm thinking that all internal frames should be hidden by default and optionally exposable via NODE_SHOW_INTERNAL_STACKFRAMES or similar variable.

See #11893 - there are a few solutions for this that I can think of.

  1. Use a special protocol like node-internals:// for internal scripts in the error resource URL (I did it here with a black box test a while back) - this would be a breaking change for the error messages, or otherwise we need to hijack every error in from Node.js (caught and uncaught, thrown and unthrown) to hide the frames (is that feasible? Or I think the implementation would be quite messy without something like #23926)
  2. Add a special script type to V8's API and use that - like v8::internal::Script::TYPE_NATIVE - but to make them still debuggable we either need some corresponding DevTools changes to make sure we can still turn the debugging on, or we need to turn it off in the API call when --expose-internals is passed, but then we need to have a way to bailout and recompile everything instead of using the scripts living inside the snapshot (those would be compiled as internal scripts in the build step).

For improving error stack traces, I would prefer 2, but for inspector debugging I'd prefer 1 (which means you can turn the black boxing on/off any time by simply updating the black box patterns)

@BridgeAR

This comment has been minimized.

Copy link
Member

commented Apr 25, 2019

I'm thinking that all internal frames should be hidden by default and optionally exposable via NODE_SHOW_INTERNAL_STACKFRAMES or similar variable.

I am definitely against that. We do "hide" the internal frames by marking them grey when inspecting errors since the last version. I also want to expand that to fatal exceptions: #27243. For me the main issue with internal frames is that we have a very limited frame size (ten by default) and that fills up quickly. But hiding the internal frames would not allow to collect more userland frames (the internal ones would still count, even if we filter them). Or at least there's no good solution that I am currently aware of.

@benjamingr
Copy link
Member

left a comment

Very much in favor of this change!

@nodejs-github-bot

This comment has been minimized.

@joyeecheung

This comment has been minimized.

Copy link
Member Author

commented Apr 28, 2019

Landed in 757f3f8

joyeecheung added a commit that referenced this pull request Apr 28, 2019

process: reduce the number of internal frames in async stack trace
Previously, we call the JS land `runNextTicks` implementation
immediately from JS land after evaluating the main module or the
input, so these synchronous JS call frames would show up in the stack
trace of the async errors, which can be confusing. This patch moves
those calls into C++ so that more of these internal scheduler
implementation details can be hidden and the users can see a cleaner
a cleaner async JS stack trace.

PR-URL: #27392
Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de>
Reviewed-By: Gus Caplan <me@gus.host>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>

targos added a commit that referenced this pull request Apr 29, 2019

process: reduce the number of internal frames in async stack trace
Previously, we call the JS land `runNextTicks` implementation
immediately from JS land after evaluating the main module or the
input, so these synchronous JS call frames would show up in the stack
trace of the async errors, which can be confusing. This patch moves
those calls into C++ so that more of these internal scheduler
implementation details can be hidden and the users can see a cleaner
a cleaner async JS stack trace.

PR-URL: #27392
Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de>
Reviewed-By: Gus Caplan <me@gus.host>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.