tiered WebAssembly compilation broken

[mejedi]

• Version: v16.0.0-pre (903998aced7dbb964ec7567c4b5765888d16b18d)
• Platform: Darwin DEU0917.local 19.6.0 Darwin Kernel Version 19.6.0: Thu Oct 29 22:56:45 PDT 2020; root:xnu-6153.141.2.2~1/RELEASE_X86_64 x86_64
• Subsystem: embed_helpers.cc/SpinEventLoop

Trivia: V8 has two tiers of WASM compilation — liftoff and turbofan. Liftoff produces unoptimised code and completes fast. Once it's done, the promise returned from WebAssembly.compile(...) is resolved and the module is ready to run. In meantime, Turbofan continues in the background. It will transparently replace the compiled module code with an optimised version.

Use --trace-wasm-compiler flag to gain some visibility into the process.

What steps will reproduce the bug?

Get a big WASM file (20MiB+). The following snippet assumes that the file is called BIG.wasm:

const fs = require("fs")
const data = fs.readFileSync("BIG.wasm")
WebAssembly.compile(data).then(()=>console.log("module ready"))

How often does it reproduce? Is there a required condition?

Reproduces always if there's nothing registered with the event loop.

What is the expected behavior?

WebAssembly module becomes available shortly while optimised compiler continues in the background.

Works as expected in interactive mode (node --trace-wasm-compiler):

Welcome to Node.js v16.0.0-pre.
Type ".help" for more information.
> const fs = require("fs")
undefined
> const data = fs.readFileSync("BIG.wasm")
undefined
> WebAssembly.compile(data).then(()=>console.log("module ready"))
(1) Decoding module...
Promise { <pending> }
(2) Prepare and start compile...
ExecuteCompilationUnits (task id 0)
Compiling wasm function 21088 with liftoff
ExecuteCompilationUnits (task id 1)
Compiling wasm function 29541 with liftoff
ExecuteCompilationUnits (task id 2)
Compiling wasm function 39979 with liftoff
ExecuteCompilationUnits (task id 3)
Compiling wasm function 791 with liftoff
Compiling wasm function 654 with liftoff
Compiling wasm function 27451 with liftoff
Compiling wasm function 24648 with liftoff
...
(3b) Compilation finished
(4) Finish module...
Compiling wasm function 791 with turbofan
module ready
Compiling wasm function 654 with turbofan
Compiling wasm function 27451 with turbofan
Compiling wasm function 24648 with turbofan
Compiling wasm function 27700 with turbofan
...

What do you see instead?

WebAssembly module doesn't become available until optimising compiler completes. The startup is rather slow.

(1) Decoding module...
(2) Prepare and start compile...
ExecuteCompilationUnits (task id 0)
Compiling wasm function 21088 with liftoff
ExecuteCompilationUnits (task id 1)
Compiling wasm function 29541 with liftoff
ExecuteCompilationUnits (task id 2)
Compiling wasm function 39979 with liftoff
ExecuteCompilationUnits (task id 3)
Compiling wasm function 791 with liftoff
Compiling wasm function 654 with liftoff
Compiling wasm function 27451 with liftoff
Compiling wasm function 24648 with liftoff
...
Compiling wasm function 21088 with turbofan
Compiling wasm function 791 with turbofan
Compiling wasm function 29541 with turbofan
Compiling wasm function 39979 with turbofan
...
(3b) Compilation finished
(4) Finish module...
module ready

Additional information

Main thread is blocked in node::WorkerThreadsTaskRunner::BlockingDrain, waiting for compiler task. BlockingDrain doesn't run the event loop. Apparently there's an assumption that tasks don't communicate with the main thread.

That's wrong. WASM compiler notifies the main thread once baseline compilation is complete (see AsyncCompileJob::CompilationStateCallback, CompilationEvent::kFinishedBaselineCompilation case).

The message goes through WorkerThreadsTaskRunner::DelayedTaskScheduler::PostDelayedTask (node_platform.cc), calling uv_async_send. The later goes unnoticed since BlockingDrain doesn't run the event loop.

  * frame #0: 0x00007fff696fd882 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff697be425 libsystem_pthread.dylib`_pthread_cond_wait + 698
    frame #2: 0x0000000101394c9d node`uv_cond_wait(cond=0x0000000107517f98, mutex=0x0000000107517f28) at thread.c:780:7
    frame #3: 0x000000010014867d node`node::LibuvMutexTraits::cond_wait(cond=0x0000000107517f98, mutex=0x0000000107517f28) at node_mutex.h:156:5
    frame #4: 0x0000000100148620 node`node::ConditionVariableBase<node::LibuvMutexTraits>::Wait(this=0x0000000107517f98, scoped_lock=0x00007ffeefbff430) at node_mutex.h:194:3
    frame #5: 0x00000001002dfae7 node`node::TaskQueue<v8::Task>::BlockingDrain(this=0x0000000107517f28) at node_platform.cc:603:20
    frame #6: 0x00000001002dfa95 node`node::WorkerThreadsTaskRunner::BlockingDrain(this=0x0000000107517f28) at node_platform.cc:207:25
    frame #7: 0x00000001002e2274 node`node::NodePlatform::DrainTasks(this=0x0000000108808d80, isolate=0x00000001073ec000) at node_platform.cc:441:33
    frame #8: 0x00000001000087fe node`node::SpinEventLoop(env=0x000000010780f800) at embed_helpers.cc:38:17
    frame #9: 0x000000010024cfb2 node`node::NodeMainInstance::Run(this=0x00007ffeefbff6a0, env_info=0x000000010491d6b8) at node_main_instance.cc:144:19
    frame #10: 0x000000010012f28a node`node::Start(argc=3, argv=0x00007ffeefbff850) at node.cc:1078:38
    frame #11: 0x0000000101d1215e node`main(argc=3, argv=0x00007ffeefbff850) at node_main.cc:127:10
    frame #12: 0x00007fff695b9cc9 libdyld.dylib`start + 1

[mejedi]

Attaching a large WASM file.
clang-11.wasm.zip

[targos]

Is this a bug in V8 or in Node.js?

[mejedi]

@targos
This is a Node.js bug. If there's anything registered with the event loop, it works as expected. It works in the interactive mode. Also works in non-interactive mode when there is a pending timer (setTimeout).

See Additional information in the bug report for some additional info.

[targos]

I don't know which team to ping for this kind of issues, so let's go with @addaleax who is probably the most familiar with node_platform.cc.

[mejedi]

There are further oddities related to WebAssembly.compile. Piggybacking on the existing issue since these shortcomings are closely related.

const fs = require('fs');

// Workaround #36616
const timerId = setInterval(() => {}, 60000);

process.on('exit', () => {
  console.log(new Date(), 'process exit');
});

process.on('beforeExit', () => {
  console.log(new Date(), 'process beforeExit');
});

WebAssembly.compile(fs.readFileSync('BIG.wasm')).then(() => {
  console.log(new Date(), 'compiled (liftoff)');
  clearInterval(timerId);
  if (process.env.EXPLICIT_EXIT) process.exit();
});

console.log(new Date(), 'WebAssembly.compile()');

Without EXPLICIT_EXIT

Pending WebAssembly.compile should keep event loop running. Once the promise is resolved, event loop should stop (assuming that there's no other ongoing activity).

% time ./out/Release/node bug.js
2021-01-11T12:39:00.828Z WebAssembly.compile()
2021-01-11T12:39:01.369Z compiled (liftoff)
2021-01-11T12:39:12.717Z process beforeExit
2021-01-11T12:39:12.718Z process exit
./out/Release/node bug.js  45.90s user 1.17s system 389% cpu 12.092 total

Event loop keeps going for another ~11 seconds until the module is fully optimised.

With EXPLICIT_EXIT

Node should terminate promptly when process.exit() is called.

% time EXPLICIT_EXIT=1 ./out/Release/node bug.js
2021-01-11T12:43:53.213Z WebAssembly.compile()
2021-01-11T12:43:53.761Z compiled (liftoff)
2021-01-11T12:43:53.762Z process exit
EXPLICIT_EXIT=1 ./out/Release/node bug.js  45.71s user 1.14s system 395% cpu 11.840 total

It took ~11 seconds for process.exit() to be honoured.

[evanw]

I'm working on esbuild and have also encountered this issue, and I believe swc has as well. I think I have a hacky workaround. I'm describing the workaround here in case it's useful to anyone:

1. Compile the following C code into a shared library for each platform you want to support:

   #include <unistd.h>
   void* napi_register_module_v1(void* a, void* b) {
     _exit(0);
   }

2. Include all compiled shared libraries in your module, then invoke the shared library for the current platform as a native module:

   process.on('exit', () => require('./exit0-darwin.node'))

Manually compiling the module like this avoids the complexity of node-gyp and should make the shared libraries really small, so it should be reasonable to just include precompiled versions for each supported platform in your package. FWIW.

[devsnek]

cc @addaleax @backes as y'all touched this most recently. i looked through this a bit but i'm not entirely sure what should be done. maybe adding a uv_run to the loop in DrainTasks?

[backes]

Sorry, I don't know much about the different queues, especially in node. It looks wrong though to have the main task blocked if there is foreground work to be executed. That work can indeed be triggered by background compilation, in which case the main thread should pick it up as soon as possible.

@gahaas anything to add here?

[gahaas]

It seems to me that BlockingDrain should only execute a single task, not all tasks. As far as I understand, the purpose of DrainTask is to make the main thread help the worker threads while it does not have any work, not to do all the background work. The loop condition should be (per_isolate->FlushForegroundTasksInternal() || Isolate::HasPendingBackgroundTasks()), so that still all background work is done that could potentially spawn foreground work.