Skip to content

Commit d00014e

Browse files
joyeecheungtargos
joyeecheung
authored and
targos
committed
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>
1 parent dc510fb commit d00014e

22 files changed

+233
-23
lines changed

‎lib/internal/modules/cjs/loader.js

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -819,13 +819,9 @@ Module.runMain = function() {
819819
true /* fromPromise */
820820
);
821821
});
822-
// Handle any nextTicks added in the first tick of the program
823-
process._tickCallback();
824822
return;
825823
}
826824
Module._load(process.argv[1], null, true);
827-
// Handle any nextTicks added in the first tick of the program
828-
process._tickCallback();
829825
};
830826

831827
Module.createRequireFromPath = (filename) => {

‎lib/internal/process/execution.js

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -50,8 +50,6 @@ function evalModule(source, print) {
5050
error(e);
5151
process.exit(1);
5252
});
53-
// Handle any nextTicks added in the first tick of the program.
54-
process._tickCallback();
5553
}
5654

5755
function evalScript(name, body, breakFirstLine, print) {
@@ -83,8 +81,6 @@ function evalScript(name, body, breakFirstLine, print) {
8381
const { log } = require('internal/console/global');
8482
log(result);
8583
}
86-
// Handle any nextTicks added in the first tick of the program.
87-
process._tickCallback();
8884
}
8985

9086
const exceptionHandlerState = { captureFn: null };

‎lib/internal/process/task_queues.js

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,7 @@ function setHasTickScheduled(value) {
4949

5050
const queue = new FixedQueue();
5151

52+
// Should be in sync with RunNextTicksNative in node_task_queue.cc
5253
function runNextTicks() {
5354
if (!hasTickScheduled() && !hasRejectionToWarn())
5455
runMicrotasks();

‎src/node.cc

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -379,9 +379,13 @@ MaybeLocal<Value> StartExecution(Environment* env, const char* main_script_id) {
379379
->GetFunction(env->context())
380380
.ToLocalChecked()};
381381

382-
MaybeLocal<Value> result =
383-
ExecuteBootstrapper(env, main_script_id, &parameters, &arguments);
384-
return scope.EscapeMaybe(result);
382+
Local<Value> result;
383+
if (!ExecuteBootstrapper(env, main_script_id, &parameters, &arguments)
384+
.ToLocal(&result) ||
385+
!task_queue::RunNextTicksNative(env)) {
386+
return MaybeLocal<Value>();
387+
}
388+
return scope.Escape(result);
385389
}
386390

387391
MaybeLocal<Value> StartMainThreadExecution(Environment* env) {

‎src/node_process.h

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,16 @@ v8::MaybeLocal<v8::Object> CreateProcessObject(
3636
const std::vector<std::string>& args,
3737
const std::vector<std::string>& exec_args);
3838
void PatchProcessObject(const v8::FunctionCallbackInfo<v8::Value>& args);
39+
40+
namespace task_queue {
41+
// Handle any nextTicks added in the first tick of the program.
42+
// We use the native version here for once so that any microtasks
43+
// created by the main module is then handled from C++, and
44+
// the call stack of the main script does not show up in the async error
45+
// stack trace.
46+
bool RunNextTicksNative(Environment* env);
47+
} // namespace task_queue
48+
3949
} // namespace node
4050
#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
4151
#endif // SRC_NODE_PROCESS_H_

‎src/node_task_queue.cc

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
#include "node.h"
33
#include "node_errors.h"
44
#include "node_internals.h"
5+
#include "node_process.h"
56
#include "v8.h"
67

78
#include <atomic>
@@ -38,6 +39,20 @@ static void EnqueueMicrotask(const FunctionCallbackInfo<Value>& args) {
3839
isolate->EnqueueMicrotask(args[0].As<Function>());
3940
}
4041

42+
// Should be in sync with runNextTicks in internal/process/task_queues.js
43+
bool RunNextTicksNative(Environment* env) {
44+
TickInfo* tick_info = env->tick_info();
45+
if (!tick_info->has_tick_scheduled() && !tick_info->has_rejection_to_warn())
46+
env->isolate()->RunMicrotasks();
47+
if (!tick_info->has_tick_scheduled() && !tick_info->has_rejection_to_warn())
48+
return true;
49+
50+
Local<Function> callback = env->tick_callback_function();
51+
CHECK(!callback.IsEmpty());
52+
return !callback->Call(env->context(), env->process_object(), 0, nullptr)
53+
.IsEmpty();
54+
}
55+
4156
static void RunMicrotasks(const FunctionCallbackInfo<Value>& args) {
4257
args.GetIsolate()->RunMicrotasks();
4358
}

‎test/fixtures/async-error.js

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
'use strict';
2+
3+
async function one() {
4+
throw new Error('test');
5+
}
6+
7+
async function breaker() {
8+
return true;
9+
}
10+
11+
async function stack() {
12+
await breaker();
13+
}
14+
15+
async function two() {
16+
await stack();
17+
await one();
18+
}
19+
async function three() {
20+
await two();
21+
}
22+
23+
async function four() {
24+
await three();
25+
}
26+
27+
module.exports = four;

‎test/message/async_error_eval_cjs.js

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,39 @@
1+
'use strict';
2+
3+
require('../common');
4+
const { spawnSync } = require('child_process');
5+
6+
const four = require('../common/fixtures')
7+
.readSync('async-error.js')
8+
.toString()
9+
.split('\n')
10+
.slice(2, -2)
11+
.join('\n');
12+
13+
const main = `${four}
14+
15+
async function main() {
16+
try {
17+
await four();
18+
} catch (e) {
19+
console.log(e);
20+
}
21+
}
22+
23+
main();
24+
`;
25+
26+
// --eval CJS
27+
{
28+
const child = spawnSync(process.execPath, [
29+
'-e',
30+
main
31+
], {
32+
env: { ...process.env }
33+
});
34+
35+
if (child.status !== 0) {
36+
console.error(child.stderr.toString());
37+
}
38+
console.error(child.stdout.toString());
39+
}

‎test/message/async_error_eval_cjs.out

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
Error: test
2+
at one ([eval]:2:9)
3+
at two ([eval]:15:9)
4+
at async three ([eval]:18:3)
5+
at async four ([eval]:22:3)
6+
at async main ([eval]:28:5)

‎test/message/async_error_eval_esm.js

Lines changed: 42 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,42 @@
1+
'use strict';
2+
3+
require('../common');
4+
const { spawnSync } = require('child_process');
5+
6+
const four = require('../common/fixtures')
7+
.readSync('async-error.js')
8+
.toString()
9+
.split('\n')
10+
.slice(2, -2)
11+
.join('\n');
12+
13+
const main = `${four}
14+
15+
async function main() {
16+
try {
17+
await four();
18+
} catch (e) {
19+
console.log(e);
20+
}
21+
}
22+
23+
main();
24+
`;
25+
26+
// --eval ESM
27+
{
28+
const child = spawnSync(process.execPath, [
29+
'--experimental-modules',
30+
'--input-type',
31+
'module',
32+
'-e',
33+
main
34+
], {
35+
env: { ...process.env }
36+
});
37+
38+
if (child.status !== 0) {
39+
console.error(child.stderr.toString());
40+
}
41+
console.error(child.stdout.toString());
42+
}

‎test/message/async_error_eval_esm.out

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
Error: test
2+
at one (eval:1:2:9)
3+
at two (eval:1:15:9)
4+
at processTicksAndRejections (internal/process/task_queues.js:*:*)
5+
at async three (eval:1:18:3)
6+
at async four (eval:1:22:3)
7+
at async main (eval:1:28:5)

‎test/message/async_error_microtask_main.js

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
'use strict';
2+
require('../common');
3+
const four = require('../fixtures/async-error');
4+
5+
async function main() {
6+
try {
7+
await four();
8+
} catch (e) {
9+
console.error(e);
10+
}
11+
}
12+
13+
queueMicrotask(main);

‎test/message/async_error_microtask_main.out

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
Error: test
2+
at one (*fixtures*async-error.js:4:9)
3+
at two (*fixtures*async-error.js:17:9)
4+
at async three (*fixtures*async-error.js:20:3)
5+
at async four (*fixtures*async-error.js:24:3)
6+
at async main (*message*async_error_microtask_main.js:7:5)

‎test/message/async_error_nexttick_main.js

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
'use strict';
2+
require('../common');
3+
const four = require('../fixtures/async-error');
4+
5+
async function main() {
6+
try {
7+
await four();
8+
} catch (e) {
9+
console.error(e);
10+
}
11+
}
12+
13+
process.nextTick(main);

‎test/message/async_error_nexttick_main.out

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
Error: test
2+
at one (*fixtures*async-error.js:4:9)
3+
at two (*fixtures*async-error.js:17:9)
4+
at processTicksAndRejections (internal/process/task_queues.js:*:*)
5+
at async three (*fixtures*async-error.js:20:3)
6+
at async four (*fixtures*async-error.js:24:3)
7+
at async main (*message*async_error_nexttick_main.js:7:5)

‎test/message/async_error_sync_esm.mjs

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,14 @@
1+
// Flags: --experimental-modules
2+
/* eslint-disable node-core/required-modules */
3+
import '../common/index.mjs';
4+
import four from '../fixtures/async-error.js';
5+
6+
async function main() {
7+
try {
8+
await four();
9+
} catch (e) {
10+
console.error(e);
11+
}
12+
}
13+
14+
main();

‎test/message/async_error_sync_esm.out

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
(node:*) ExperimentalWarning: The ESM module loader is experimental.
2+
Error: test
3+
at one (*fixtures*async-error.js:4:9)
4+
at two (*fixtures*async-error.js:17:9)
5+
at async three (*fixtures*async-error.js:20:3)
6+
at async four (*fixtures*async-error.js:24:3)
7+
at async main (*message*async_error_sync_esm.mjs:8:5)

‎test/message/async_error_sync_main.js

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
'use strict';
2+
require('../common');
3+
const four = require('../fixtures/async-error');
4+
5+
async function main() {
6+
try {
7+
await four();
8+
} catch (e) {
9+
console.error(e);
10+
}
11+
}
12+
13+
main();

‎test/message/async_error_sync_main.out

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
Error: test
2+
at one (*fixtures*async-error.js:4:9)
3+
at two (*fixtures*async-error.js:17:9)
4+
at async three (*fixtures*async-error.js:20:3)
5+
at async four (*fixtures*async-error.js:24:3)
6+
at async main (*message*async_error_sync_main.js:7:5)

‎test/message/events_unhandled_error_nexttick.out

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,3 @@ Error
1313
Emitted 'error' event at:
1414
at *events_unhandled_error_nexttick.js:*:*
1515
at processTicksAndRejections (internal/process/task_queues.js:*:*)
16-
at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:*:*)
17-
at Function.Module.runMain (internal/modules/cjs/loader.js:*:*)
18-
at internal/main/run_main_module.js:*:*

‎test/message/nexttick_throw.out

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,3 @@
55
ReferenceError: undefined_reference_error_maker is not defined
66
at *test*message*nexttick_throw.js:*:*
77
at processTicksAndRejections (internal/process/task_queues.js:*:*)
8-
at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:*:*)
9-
at Function.Module.runMain (internal/modules/cjs/loader.js:*:*)
10-
at internal/main/run_main_module.js:*:*

‎test/message/unhandled_promise_trace_warnings.out

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -9,9 +9,6 @@
99
at *
1010
at *
1111
at *
12-
at *
13-
at *
14-
at *
1512
(node:*) Error: This was rejected
1613
at * (*test*message*unhandled_promise_trace_warnings.js:*)
1714
at *
@@ -25,9 +22,6 @@
2522
at *
2623
at *
2724
at *
28-
at *
29-
at *
30-
at *
3125
(node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1)
3226
at handledRejection (internal/process/promises.js:*)
3327
at promiseRejectHandler (internal/process/promises.js:*)

0 commit comments

Comments
 (0)