esbuild-wasm on Windows with Node.js v14 and an ESM loader enabled takes a while to load

[merceyz]

Describe the bug

Running esbuild-wasm@0.17.5 on Windows with Node.js v14.21.2 and an ESM loader enabled takes a long time to return on the first transform call.

Ref yarnpkg/berry#5180 (yarnpkg/berry@79ce8bd)

To Reproduce

Run the following script

require('fs').writeFileSync(
	`foo.mjs`,
	`
export function getFormat() {
  return {
    format: 'commonjs'
  }
}
`
);

// Comment out the next line and the problem disappears
process.env.NODE_OPTIONS = '--loader ./foo.mjs';

console.time('transformSync');
require('esbuild-wasm').transformSync('let foo = 0;');
console.timeEnd('transformSync');

console.time('transformSync');
require('esbuild-wasm').transformSync('let bar = 0;');
console.timeEnd('transformSync');

Expected behaviour

When the --loader flag isn't specified:

$ node ./test.js
transformSync: 461.729ms
transformSync: 4.944ms

Actual behaviour

When the --loader flag is specified:

$ node ./test.js
(node:5580) ExperimentalWarning: --experimental-loader is an experimental feature. This feature could change at any time
(Use `node --trace-warnings ...` to show where the warning was created)
transformSync: 49.776s
transformSync: 1.945ms

Additional information

Adding --prof to the node flags at node_modules/esbuild-wasm/lib/main.js:1927 and processing the isolate log with node --prof-process gives the following output:

Statistical profiling result from isolate-000001D420338B10-1004-v8.log, (3845 ticks, 1 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
   3825   99.5%          C:\WINDOWS\SYSTEM32\ntdll.dll
     19    0.5%          C:\nodejs\node.exe

 [JavaScript]:
   ticks  total  nonlib   name

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
      0    0.0%    0.0%  C++
      0    0.0%    0.0%  GC
   3844  100.0%          Shared libraries
      1    0.0%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
   3825   99.5%  C:\WINDOWS\SYSTEM32\ntdll.dll

[evanw]

It sounds like you're saying that node has a performance issue with WebAssembly + Windows + ESM loaders. I believe you, but I don't know what I can do about it. Should this be a bug report for node instead?

In the meantime, you could consider using esbuild's native API instead of the WebAssembly API, especially if you are interested in higher performance. The native API should be significantly faster.

And for maximum speed you could also consider not using the yarn command to run the build script. Running the build script using yarn node instead of node seems to make it run ~10x slower:

node tempdir/build-node-native.js: 910.375ms
node tempdir/build-node-native.js: 884.248ms
node tempdir/build-node-native.js: 879.188ms

yarn node build-yarn-native.js: 7.818s
yarn node build-yarn-native.js: 7.606s
yarn node build-yarn-native.js: 7.790s

node tempdir/build-node-wasm.js: 11.485s
node tempdir/build-node-wasm.js: 12.237s
node tempdir/build-node-wasm.js: 11.918s

yarn node build-yarn-wasm.js: 19.967s
yarn node build-yarn-wasm.js: 19.885s
yarn node build-yarn-wasm.js: 19.725s

I'm guessing you're trying to use esbuild to implement a TypeScript ESM loader. But you could also consider bundling everything together with esbuild and then running it as an alternative if the loader stuff is getting in the way.

Here's the code I used to generate the above output (run it using node demo.js in the Yarn repo):

const child_process = require('child_process')
const fs = require('fs')

const options = outfile => JSON.stringify({
  banner: {
    js: `#!/usr/bin/env node\n/* eslint-disable */\n//prettier-ignore`,
  },
  entryPoints: ['./packages/yarnpkg-cli/sources/cli.ts'],
  bundle: true,
  define: {
    YARN_VERSION: JSON.stringify(require('./packages/yarnpkg-cli/package.json').version),
    'process.env.NODE_ENV': JSON.stringify(`production`),
    'process.env.DEV': JSON.stringify(`false`),
    'process.env.__TESTING_MKDIRP_PLATFORM__': `false`,
    'process.env.__TESTING_MKDIRP_NODE_VERSION__': `false`,
    'process.env.__FAKE_PLATFORM__': `false`,
  },
  outfile,
  resolveExtensions: [`.tsx`, `.ts`, `.jsx`, `.mjs`, `.js`, `.css`, `.json`],
  logLevel: `silent`,
  format: `iife`,
  platform: `node`,
  minify: true,
  target: `node14`,
}, null, 2)

const run = (command, { count = 1, cwd = __dirname } = {}) => {
  for (let i = 0; i < count; i++) {
    console.time(command)
    child_process.execSync(command, { cwd, stdio: 'inherit' })
    console.timeEnd(command)
  }
}

// Install "esbuild" and "esbuild-wasm" inside Yarn
if (!require('./package.json').devDependencies.esbuild) {
  run('yarn add --dev esbuild@0.15.15 esbuild-wasm@0.15.15')
}

// Install "esbuild" and "esbuild-wasm" outside Yarn
if (!fs.existsSync('tempdir')) {
  fs.mkdirSync('tempdir', { recursive: true })
  fs.writeFileSync('tempdir/package.json', `{
    "dependencies": {
      "esbuild": "0.15.15",
      "esbuild-wasm": "0.15.15"
    }
  }`)
  run('npm i', { cwd: 'tempdir' })
}

// node + esbuild's native package
fs.writeFileSync('tempdir/build-node-native.js', `require('esbuild').build(${options('out/node-native.js')})`)
run('node tempdir/build-node-native.js', { count: 3 })

// Yarn + esbuild's native package
fs.writeFileSync('build-yarn-native.js', `require('esbuild').build(${options('out/yarn-native.js')})`)
run('yarn node build-yarn-native.js', { count: 3 })

// node + esbuild's WebAssembly package
fs.writeFileSync('tempdir/build-node-wasm.js', `require('esbuild-wasm').build(${options('out/node-wasm.js')})`)
run('node tempdir/build-node-wasm.js', { count: 3 })

// Yarn + esbuild's WebAssembly package
fs.writeFileSync('build-yarn-wasm.js', `require('esbuild-wasm').build(${options('out/yarn-wasm.js')})`)
run('yarn node build-yarn-wasm.js', { count: 3 })

[merceyz]

It sounds like you're saying that node has a performance issue with WebAssembly + Windows + ESM loaders. I believe you, but I don't know what I can do about it. Should this be a bug report for node instead?

Yeah, it might be that, I opened an issue here first in case it was an issue with how the "glue code" interacts with Node.js v14 on Windows.

And for maximum speed you could also consider not using the yarn command to run the build script

Yeah, but that's unrelated in this case, the reproduction doesn't involve Yarn.

I'm guessing you're trying to use esbuild to implement a TypeScript ESM loader

Not really, I'm replacing our use of @babel/register (commonjs only) with esbuild-wasm which works great on Node.js v16 and v18 but when an ESM loader is present on v14 it takes a really long time to load.

But you could also consider bundling everything together with esbuild and then running it as an alternative if the loader stuff is getting in the way.

While that might speed up running Yarn from sources it would prevent us from dogfooding the PnP hook.

[merceyz]

After looking into it a bit more it seems to boil down to nodejs/node#36616 as I can reproduce the issue with the following script:

const data = require('fs').readFileSync('node_modules/esbuild-wasm/esbuild.wasm');
console.time('instantiate');
new WebAssembly.Module(data);
console.timeEnd('instantiate');

Node.js v14.21.2:

$ time node test.js
instantiate: 139.521ms

________________________________________________________
Executed in   50.40 secs      fish           external
   usr time    0.00 millis    0.00 millis    0.00 micros
   sys time   16.00 millis   16.00 millis    0.00 micros

Node.js v16.19.0:

$ time node test.js
instantiate: 142.864ms

________________________________________________________
Executed in    4.77 secs      fish           external
   usr time   15.00 millis    0.00 micros   15.00 millis
   sys time   15.00 millis    0.00 micros   15.00 millis

Node.js v18.14.0:

$ time node test.js
instantiate: 125.414ms

________________________________________________________
Executed in  234.44 millis    fish           external
   usr time    0.00 millis    0.00 micros    0.00 millis
   sys time   15.00 millis    0.00 micros   15.00 millis

If I add process.kill(process.pid, 'SIGTERM'); to the end of that reproduction it closes "instantly".

It's interesting that in the original reproduction a --loader triggers it but since this isn't an issue with esbuild I'll close this.