assert.ok() becomes slow when using the Hooks API

[privatenumber]

Version

v20.13.1

Platform

No response

Subsystem

Mac/Linux

What steps will reproduce the bug?

node --import ./hook.mjs file.mjs

hook.mjs:

import { isMainThread } from 'worker_threads';
import module from 'module';

if (isMainThread) {
	module.register(import.meta.url, import.meta.url);
}

export const load = async (
	url,
	context,
	nextLoad,
) => {
	if (url.endsWith('/file.mjs')) {
		return {
			shortCircuit: true,
			format: 'module',
			// Originally, this is from esbuild compiling the input. But inlining the compiled code here demonstrates that's not the issue.
			source: 'import assert from"assert";const startTime=Date.now();console.log("start time:",Date.now()-startTime);try{assert.ok(false)}finally{console.log("end time:",Date.now()-startTime)}',
		};
	}
	return await nextLoad(url, context);
};

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 privatenumber/tsx#548

[aduh95]

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.

[aduh95]

/cc @nodejs/loaders

[GeoffreyBooth]

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?

[privatenumber]

@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.

[benjamingr]

@privatenumber is the regression gone if you pass the message parameter to assert.ok?

[privatenumber]

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