deno: [node] slow npm resolution with npm binary command

Talked to Bartek out of band. We’ll change setImmediate to use op_void_async_deferred directly, bypassing setTimeout machinery entirely. setTimeout and setInterval themselves will continue to clamp like browsers do to prevent runaway timers causing event loop lockups.

FYI removing the “timerNextingLevel” check makes Deno run the reproduction in the same time as Node (6ms)

EDIT: Opened https://github.com/denoland/deno/pull/19213 that builds on top of #19212 but changes Node compat APIs so that they are not limited to the nesting levels clamping.

@bartlomieju here is a simplified reproduction case: https://github.com/marvinhagemeister/deno-bug-timer

1. Clone this repo https://github.com/marvinhagemeister/deno-bug-timer.git
2. Run deno run -A npm:mocha

To compare this with node:

1. Run npm i
2. Run npx mocha

@bartlomieju I can reproduce the issue reliably with both release and debug builds. The OS doesn’t seem to make a difference either. Can reproduce it on macOS, Windows 11 and WSL (Ubuntu).

@bartlomieju agree with splitting them up. Did a little more testing on various platforms and release vs debug builds and I can reproduce both things with all combinations. Commenting out the op_print() call in JS speeds up the test execution by roughly 80ms.

Regarding setImmediate it looks like setting the fallback to setTimeout(fn, 0) is actually fine. When I overwrite the setImmediate global in node there isn’t any measurable performance difference. This leads me to believe that something is up with our implementation of setTimeout.

The implementation of timeout is slow - Tokio limits us to 1ms resolution (which means that 0ms timeout actually takes more than 1ms), but I think I came up with a “fast path” for 0 timeout - essentially it just needs to run and the end of the current tick of the event loop, so it might not need to involve setting up a timer in Rust at all.

Good investigation @marvinhagemeister! Let’s address both setImmediate problem and slow print in separate issues. I believe for setImmediate I will need to add a special op (I can look into that), but it’s currently unclear why print take so long - effectively it ends us in op_print here: https://github.com/denoland/deno/blob/3e03865d89e3abf0755e6d3b8305632a5319fdfe/core/ops_builtin.rs#L160-L171

This is because it’s doing the npm resolution on each run—not that npm resolution is slow. Last time I measured, Deno’s resolution is faster than npm.

The way to cache the resolution and make it fast is to use a Deno lockfile, which gets automatically created if there’s a deno.json in the repo. That said, for some reason the resolution is not being written even when doing this. I opened https://github.com/denoland/deno/issues/19038

Side note: On Windows, running npm run test fails because of the use of rm, but deno task build && deno task test works 😄