process: reduce the number of internal frames in async stack trace by joyeecheung · Pull Request #27392 · nodejs/node

joyeecheung · 2019-04-24T19:17:12Z

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

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 · 2019-04-24T19:17:14Z

Lite-CI: https://ci.nodejs.org/job/node-test-pull-request-lite-pipeline/3355

…race

joyeecheung · 2019-04-24T19:18:22Z

test/message/async_error_eval_cjs.out

+    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)


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)

joyeecheung · 2019-04-24T19:20:25Z

test/message/async_error_eval_esm.out

+Error: test
+    at one (eval:1:2:9)
+    at two (eval:1:15:9)
+    at processTicksAndRejections (internal/process/task_queues.js:*:*)


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)`

joyeecheung · 2019-04-24T19:22:13Z

test/message/async_error_microtask_main.out

+    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)


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 · 2019-04-24T19:28:26Z

CI: https://ci.nodejs.org/job/node-test-pull-request/22690/

BridgeAR

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 · 2019-04-24T20:19:50Z

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.

test/message/async_error_eval_cjs.js

…stack trace

nodejs-github-bot · 2019-04-25T07:26:47Z

CI: https://ci.nodejs.org/job/node-test-pull-request/22716/

joyeecheung · 2019-04-25T07:36:53Z

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.

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 take ownership of prepareStackTrace for upstream v8 changes #23926)
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 · 2019-04-25T07:47:08Z

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

Very much in favor of this change!

nodejs-github-bot · 2019-04-28T06:58:39Z

CI: https://ci.nodejs.org/job/node-test-pull-request/22751/

joyeecheung · 2019-04-28T07:36:48Z

Landed in 757f3f8

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>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Apr 24, 2019

fixup! process: reduce the number of internal frames in async stack t…

3def28d

…race

joyeecheung commented Apr 24, 2019

View reviewed changes

BridgeAR approved these changes Apr 24, 2019

View reviewed changes

devsnek approved these changes Apr 24, 2019

View reviewed changes

gengjiawen reviewed Apr 25, 2019

View reviewed changes

test/message/async_error_eval_cjs.js Show resolved Hide resolved

gengjiawen approved these changes Apr 25, 2019

View reviewed changes

fixup! fixup! process: reduce the number of internal frames in async …

c354c2c

…stack trace

JungMinu approved these changes Apr 25, 2019

View reviewed changes

benjamingr approved these changes Apr 25, 2019

View reviewed changes

joyeecheung added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Apr 26, 2019

joyeecheung closed this Apr 28, 2019

molllyn1 mentioned this pull request Apr 15, 2024

[Snyk] Security upgrade gatsby from 2.18.18 to 2.24.80 molllyn1/node#110

Open

ron-a20 mentioned this pull request Apr 15, 2024

[Snyk] Security upgrade gatsby from 2.18.18 to 2.24.80 ron-a20/node#124

Open

kissofire mentioned this pull request Apr 15, 2024

[Snyk] Security upgrade gatsby from 2.13.73 to 2.24.80 kissofire/node#127

Open

137717unity mentioned this pull request Apr 15, 2024

[Snyk] Security upgrade gatsby from 2.18.18 to 2.24.80 137717unity/node#126

Open

aliceUnhinged613 mentioned this pull request Apr 15, 2024

[Snyk] Security upgrade gatsby from 2.18.18 to 2.24.80 aliceUnhinged613/node#126

Open

wedataintelligence mentioned this pull request Apr 16, 2024

[Snyk] Security upgrade gatsby from 2.18.18 to 2.24.80 wedataintelligence/node#109

Open

Uh oh!

Conversation

joyeecheung commented Apr 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Checklist

Uh oh!

nodejs-github-bot commented Apr 24, 2019

Uh oh!

joyeecheung Apr 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

joyeecheung Apr 24, 2019

Choose a reason for hiding this comment

Uh oh!

joyeecheung Apr 24, 2019

Choose a reason for hiding this comment

Uh oh!

nodejs-github-bot commented Apr 24, 2019

Uh oh!

BridgeAR left a comment

Choose a reason for hiding this comment

Uh oh!

silverwind commented Apr 24, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

nodejs-github-bot commented Apr 25, 2019

Uh oh!

joyeecheung commented Apr 25, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

BridgeAR commented Apr 25, 2019

Uh oh!

benjamingr left a comment

Choose a reason for hiding this comment

Uh oh!

nodejs-github-bot commented Apr 28, 2019

Uh oh!

joyeecheung commented Apr 28, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

8 participants

joyeecheung commented Apr 24, 2019 •

edited

Loading

joyeecheung Apr 24, 2019 •

edited

Loading

silverwind commented Apr 24, 2019 •

edited

Loading

joyeecheung commented Apr 25, 2019 •

edited

Loading