Open privatenumber opened 2 weeks ago
You should be using performance.now()
if you want a more accurate result. You could also replace module.register(import.meta.url, import.meta.url)
with simply module.register(import.meta.url)
.
To get more context, I ran the following commands:
$ # From a data: URL module (does NOT reproduce):
$ node --import 'data:text/javascript,import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}'
start time: 0.0015829999999965594
end time: 2.3966250000000002
node:internal/modules/run_main:115
triggerUncaughtException(
^
AssertionError [ERR_ASSERTION]: false == true
at data:text/javascript,import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}:1:128
at ModuleJob.run (node:internal/modules/esm/module_job:262:25)
at async ModuleLoader.import (node:internal/modules/esm/loader:475:24)
at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:104:9) {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}
Node.js v23.0.0-pre
$ # From a custom source in load hook (DOES reproduce):
$ node --import 'data:text/javascript,import module from "module";
module.register(`data:text/javascript,export ${encodeURIComponent(function load(url, context, next) {
if (url.endsWith("/file.mjs")) {
return {
shortCircuit: true,
format: "module",
source: `import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}`
}
}
return next(url, context);
})}`);' file.mjs
start time: 0.0019159999999942556
end time: 9.943540999999996
node:internal/modules/run_main:115
triggerUncaughtException(
^
AssertionError [ERR_ASSERTION]: false == true
at file://…/file.mjs:1:128
at ModuleJob.run (node:internal/modules/esm/module_job:262:25)
at async ModuleLoader.import (node:internal/modules/esm/loader:475:24)
at async asyncRunEntryPointWithESMLoader (node:internal/modules/run_main:109:5) {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}
Node.js v23.0.0-pre
$ # Resolving to a data: URL from a resolve hook (does NOT reproduce):
$ node --input-type=module <<'EOF'
import module from 'module';
module.register(`data:text/javascript,export ${encodeURIComponent(function resolve(specifier, context, next) {
if (specifier.endsWith('/file.mjs')) {
return {
shortCircuit: true,
format: 'module',
url: 'data:text/javascript,import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}'
}
}
return next(specifier, context);
})}`);
await import('./file.mjs')
EOF
start time: 0.0014169999999893435
end time: 1.318249999999992
node:internal/modules/run_main:115
triggerUncaughtException(
^
AssertionError [ERR_ASSERTION]: false == true
at data:text/javascript,import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}:1:128
at ModuleJob.run (node:internal/modules/esm/module_job:262:25)
at async ModuleLoader.import (node:internal/modules/esm/loader:475:24)
at async file:///Users/duhamean/Documents/node/[eval1]:14:1 {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}
Node.js v23.0.0-pre
$ # From a data: URL module with a no-op load hook (does NOT reproduce):
$ node --input-type=module <<'EOF'
import module from 'module';
module.register(`data:text/javascript,export ${encodeURIComponent(function load(url, context, next) {
return next(url, context)
})}`);
await import('data:text/javascript,import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}')
EOF
start time: 0.0016250000000042064
end time: 1.3178329999999931
node:internal/modules/run_main:115
triggerUncaughtException(
^
AssertionError [ERR_ASSERTION]: false == true
at data:text/javascript,import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}:1:128
at ModuleJob.run (node:internal/modules/esm/module_job:262:25)
at async ModuleLoader.import (node:internal/modules/esm/loader:475:24)
at async file:///Users/duhamean/Documents/node/[eval1]:7:1 {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}
Node.js v23.0.0-pre
$ # From a custom source in load hook with Error.stackTraceLimit=0 (DOES reproduce):
$ node --import 'data:text/javascript,import module from "module";
Error.stackTraceLimit=0;
module.register(`data:text/javascript,export ${encodeURIComponent(function load(url, context, next) {
if (url.endsWith("/file.mjs")) {
return {
shortCircuit: true,
format: "module", source: Buffer.from(`import assert from"assert";const startTime=performance.now();console.log("start time:",performance.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",performance.now()-startTime)}`)
}
}
return next(url, context)
})}`);' file.mjs
start time: 0.0017500000000012506
end time: 8.960207999999994
node:internal/modules/run_main:115
triggerUncaughtException(
^
[AssertionError [ERR_ASSERTION]: false == true] {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}
Node.js v23.0.0-pre
It seems to be limited to modules that are loaded with a custom source. As we can see, disabling the stack trace does not help.
/cc @nodejs/loaders
When you write "becomes slow", relative to what? Not registering any hooks?
Is it particular to assert.ok
or is it that any code becomes slow? Any code where an exception is thrown? Something else?
@aduh95 Appreciate the tips and quick debugging + confirmation!
@GeoffreyBooth
The assert.ok()
function call is slow relative to running without hooks.
Without the hook, the entire function runs in under 10ms. With the hook (note, it's not just the hook—even removing a space in from the input file makes it behave expectedly again), it takes ~600ms on my computer, and ~1.5s on GitHub Actions.
In the repro, the hook doesn't actually do anything except return a hard-coded minified version of the input, but it somehow slows down the assert.ok()
function call.
So far, I've only noticed it in assert.ok()
, but the repro is so fragile so it's hard to explore. I tried assert()
, new Error().stack
, etc but it didn't reproduce.
@privatenumber is the regression gone if you pass the message parameter to assert.ok?
Yep, when a message is passed in, it runs expectedly. On GitHub Actions, it runs in 1.6ms: https://github.com/privatenumber/node-bug-slow/actions/runs/9062364248/job/24896059626
Hard to draw conclusions from this though. To be fair, even removing a space removes the regression: https://github.com/privatenumber/node-bug-slow/actions/runs/9062420886/job/24896268910
Version
v20.13.1
Platform
No response
Subsystem
Mac/Linux
What steps will reproduce the bug?
hook.mjs:
file.mjs: https://github.com/privatenumber/node-bug-slow/blob/develop/file.mjs (The minimal reproduction requires a file with a massive comment so I decided not to paste here)
I uploaded the minimal reproduction here as well: https://github.com/privatenumber/node-bug-slow
And it takes 1.3s to run on GitHub Actions: https://github.com/privatenumber/node-bug-slow/actions/runs/9057737597/job/24882195019
How often does it reproduce? Is there a required condition?
Consistently.
But the reproduction is fragile. Deleting a space here and there would make it run expectedly under 10ms.
What is the expected behavior? Why is that the expected behavior?
It should take under 10ms.
What do you see instead?
The
assert.ok(false)
call takes around 600ms for me, and 1.5s on GitHub Actions.Additional information
Originally reported in https://github.com/privatenumber/tsx/issues/548