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
Closed
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
4 changes: 0 additions & 4 deletions lib/internal/modules/cjs/loader.js
Expand Up @@ -819,13 +819,9 @@ Module.runMain = function() {
true /* fromPromise */
);
});
// Handle any nextTicks added in the first tick of the program
process._tickCallback();
return;
}
Module._load(process.argv[1], null, true);
// Handle any nextTicks added in the first tick of the program
process._tickCallback();
};

Module.createRequireFromPath = (filename) => {
Expand Down
4 changes: 0 additions & 4 deletions lib/internal/process/execution.js
Expand Up @@ -50,8 +50,6 @@ function evalModule(source, print) {
error(e);
process.exit(1);
});
// Handle any nextTicks added in the first tick of the program.
process._tickCallback();
}

function evalScript(name, body, breakFirstLine, print) {
Expand Down Expand Up @@ -83,8 +81,6 @@ function evalScript(name, body, breakFirstLine, print) {
const { log } = require('internal/console/global');
log(result);
}
// Handle any nextTicks added in the first tick of the program.
process._tickCallback();
}

const exceptionHandlerState = { captureFn: null };
Expand Down
1 change: 1 addition & 0 deletions lib/internal/process/task_queues.js
Expand Up @@ -49,6 +49,7 @@ function setHasTickScheduled(value) {

const queue = new FixedQueue();

// Should be in sync with RunNextTicksNative in node_task_queue.cc
function runNextTicks() {
if (!hasTickScheduled() && !hasRejectionToWarn())
runMicrotasks();
Expand Down
10 changes: 7 additions & 3 deletions src/node.cc
Expand Up @@ -379,9 +379,13 @@ MaybeLocal<Value> StartExecution(Environment* env, const char* main_script_id) {
->GetFunction(env->context())
.ToLocalChecked()};

MaybeLocal<Value> result =
ExecuteBootstrapper(env, main_script_id, &parameters, &arguments);
return scope.EscapeMaybe(result);
Local<Value> result;
if (!ExecuteBootstrapper(env, main_script_id, &parameters, &arguments)
.ToLocal(&result) ||
!task_queue::RunNextTicksNative(env)) {
return MaybeLocal<Value>();
}
return scope.Escape(result);
}

MaybeLocal<Value> StartMainThreadExecution(Environment* env) {
Expand Down
10 changes: 10 additions & 0 deletions src/node_process.h
Expand Up @@ -36,6 +36,16 @@ v8::MaybeLocal<v8::Object> CreateProcessObject(
const std::vector<std::string>& args,
const std::vector<std::string>& exec_args);
void PatchProcessObject(const v8::FunctionCallbackInfo<v8::Value>& args);

namespace task_queue {
// Handle any nextTicks added in the first tick of the program.
// We use the native version here for once so that any microtasks
// created by the main module is then handled from C++, and
// the call stack of the main script does not show up in the async error
// stack trace.
bool RunNextTicksNative(Environment* env);
} // namespace task_queue

} // namespace node
#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
#endif // SRC_NODE_PROCESS_H_
15 changes: 15 additions & 0 deletions src/node_task_queue.cc
Expand Up @@ -2,6 +2,7 @@
#include "node.h"
#include "node_errors.h"
#include "node_internals.h"
#include "node_process.h"
#include "v8.h"

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

// Should be in sync with runNextTicks in internal/process/task_queues.js
bool RunNextTicksNative(Environment* env) {
TickInfo* tick_info = env->tick_info();
if (!tick_info->has_tick_scheduled() && !tick_info->has_rejection_to_warn())
env->isolate()->RunMicrotasks();
if (!tick_info->has_tick_scheduled() && !tick_info->has_rejection_to_warn())
return true;

Local<Function> callback = env->tick_callback_function();
CHECK(!callback.IsEmpty());
return !callback->Call(env->context(), env->process_object(), 0, nullptr)
.IsEmpty();
}

static void RunMicrotasks(const FunctionCallbackInfo<Value>& args) {
args.GetIsolate()->RunMicrotasks();
}
Expand Down
27 changes: 27 additions & 0 deletions test/fixtures/async-error.js
@@ -0,0 +1,27 @@
'use strict';

async function one() {
throw new Error('test');
}

async function breaker() {
return true;
}

async function stack() {
await breaker();
}

async function two() {
await stack();
await one();
}
async function three() {
await two();
}

async function four() {
await three();
}

module.exports = four;
36 changes: 36 additions & 0 deletions test/message/async_error_eval_cjs.js
@@ -0,0 +1,36 @@
'use strict';

require('../common');
const fixtures = require('../common/fixtures');
const errorModule = fixtures.path('async-error.js');
const { spawnSync } = require('child_process');

const main = `'use strict';

const four = require('${errorModule}');

async function main() {
try {
await four();
} catch (e) {
console.log(e);
}
}

main();
`;

// --eval CJS
{
const child = spawnSync(process.execPath, [
'-e',
main
], {
env: { ...process.env }
joyeecheung marked this conversation as resolved.
Show resolved Hide resolved
});

if (child.status !== 0) {
console.error(child.stderr.toString());
}
console.error(child.stdout.toString());
}
6 changes: 6 additions & 0 deletions test/message/async_error_eval_cjs.out
@@ -0,0 +1,6 @@
Error: test
at one (*fixtures*async-error.js:4:9)
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)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

42 changes: 42 additions & 0 deletions test/message/async_error_eval_esm.js
@@ -0,0 +1,42 @@
'use strict';

require('../common');
const { spawnSync } = require('child_process');

const four = require('../common/fixtures')
.readSync('async-error.js')
.toString()
.split('\n')
.slice(2, -2)
.join('\n');

const main = `${four}

async function main() {
try {
await four();
} catch (e) {
console.log(e);
}
}

main();
`;

// --eval ESM
{
const child = spawnSync(process.execPath, [
'--experimental-modules',
'--input-type',
'module',
'-e',
main
], {
env: { ...process.env }
});

if (child.status !== 0) {
console.error(child.stderr.toString());
}
console.error(child.stdout.toString());
}
7 changes: 7 additions & 0 deletions test/message/async_error_eval_esm.out
@@ -0,0 +1,7 @@
Error: test
at one (eval:1:2:9)
at two (eval:1:15:9)
at processTicksAndRejections (internal/process/task_queues.js:*:*)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 async three (eval:1:18:3)
at async four (eval:1:22:3)
at async main (eval:1:28:5)
13 changes: 13 additions & 0 deletions test/message/async_error_microtask_main.js
@@ -0,0 +1,13 @@
'use strict';
require('../common');
const four = require('../fixtures/async-error');

async function main() {
try {
await four();
} catch (e) {
console.error(e);
}
}

queueMicrotask(main);
6 changes: 6 additions & 0 deletions test/message/async_error_microtask_main.out
@@ -0,0 +1,6 @@
Error: test
at one (*fixtures*async-error.js:4:9)
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)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

13 changes: 13 additions & 0 deletions test/message/async_error_nexttick_main.js
@@ -0,0 +1,13 @@
'use strict';
require('../common');
const four = require('../fixtures/async-error');

async function main() {
try {
await four();
} catch (e) {
console.error(e);
}
}

process.nextTick(main);
7 changes: 7 additions & 0 deletions test/message/async_error_nexttick_main.out
@@ -0,0 +1,7 @@
Error: test
at one (*fixtures*async-error.js:4:9)
at two (*fixtures*async-error.js:17:9)
at processTicksAndRejections (internal/process/task_queues.js:*:*)
at async three (*fixtures*async-error.js:20:3)
at async four (*fixtures*async-error.js:24:3)
at async main (*message*async_error_nexttick_main.js:7:5)
14 changes: 14 additions & 0 deletions test/message/async_error_sync_esm.mjs
@@ -0,0 +1,14 @@
// Flags: --experimental-modules
/* eslint-disable node-core/required-modules */
// import '../common/index.mjs';
import four from '../fixtures/async-error.js';

async function main() {
try {
await four();
} catch (e) {
console.error(e);
}
}

main();
7 changes: 7 additions & 0 deletions test/message/async_error_sync_esm.out
@@ -0,0 +1,7 @@
(node:*) ExperimentalWarning: The ESM module loader is experimental.
Error: test
at one (*fixtures*async-error.js:4:9)
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_sync_esm.mjs:8:5)
13 changes: 13 additions & 0 deletions test/message/async_error_sync_main.js
@@ -0,0 +1,13 @@
'use strict';
require('../common');
const four = require('../fixtures/async-error');

async function main() {
try {
await four();
} catch (e) {
console.error(e);
}
}

main();
6 changes: 6 additions & 0 deletions test/message/async_error_sync_main.out
@@ -0,0 +1,6 @@
Error: test
at one (*fixtures*async-error.js:4:9)
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_sync_main.js:7:5)
3 changes: 0 additions & 3 deletions test/message/events_unhandled_error_nexttick.out
Expand Up @@ -13,6 +13,3 @@ Error
Emitted 'error' event at:
at *events_unhandled_error_nexttick.js:*:*
at processTicksAndRejections (internal/process/task_queues.js:*:*)
at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:*:*)
at Function.Module.runMain (internal/modules/cjs/loader.js:*:*)
at internal/main/run_main_module.js:*:*
3 changes: 0 additions & 3 deletions test/message/nexttick_throw.out
Expand Up @@ -5,6 +5,3 @@
ReferenceError: undefined_reference_error_maker is not defined
at *test*message*nexttick_throw.js:*:*
at processTicksAndRejections (internal/process/task_queues.js:*:*)
at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:*:*)
at Function.Module.runMain (internal/modules/cjs/loader.js:*:*)
at internal/main/run_main_module.js:*:*
6 changes: 0 additions & 6 deletions test/message/unhandled_promise_trace_warnings.out
Expand Up @@ -9,9 +9,6 @@
at *
at *
at *
at *
at *
at *
(node:*) Error: This was rejected
at * (*test*message*unhandled_promise_trace_warnings.js:*)
at *
Expand All @@ -25,9 +22,6 @@
at *
at *
at *
at *
at *
at *
(node:*) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1)
at handledRejection (internal/process/promises.js:*)
at promiseRejectHandler (internal/process/promises.js:*)
Expand Down