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.

[cspotcode]

Regarding the issue explained here #36616 (comment) where the node process does not terminate until WASM optimization has fully completed:

Is the issue that the WASM compilation task should be aborted instead of completed? I don't know v8 or node internals so I don't know if that theory makes sense or not. Is there a way that tasks are classified as either necessary or unnecessary to complete, so that unnecessary ones are aborted on process.exit()?

Or is the problem that process.on('exit' handlers cannot be invoked as long as the event loop is blocked by BlockingDrain?

[gahaas]

I think the problem is still what I wrote in the comment above. V8 has foreground tasks and background tasks. Typically background tasks could be ignored completely, they just exist to make V8 faster. For example, the optimizing compiler can be executed on a background task, but if this task is not executed, then V8 can still execute the baseline code. Similarly the garbage collector can be executed on a background task, but if the background task is not executed, then V8 will just stop the main thread and do garbage collection on the main thread. This means also, that when all foreground tasks have finished and only background tasks are left, you can just terminate the node without any issue.

The only case where background tasks are important, and where node should wait for background tasks, is asynchronous compilation of WebAssembly modules. In that case the WebAssembly module gets compiled completely on background tasks, and the last background task will then spawn a foreground task to continue execution on the main thread. This means that if node terminates when no foreground task is available anymore, it would not wait for WebAssembly compilation to finish, and not would potentially not execute an important part of a script.

V8 introduced the API function Isolate::HasPendingBackgroundTasks() to tell the embedder if there is background work that will spawn a foreground task or not. If Isolate::HasPendingBackgroundTasks() returns false, then node can just terminate. But if Isolate::HasPendingBackgroundTasks() returns true, node should also wait for background tasks to finish.

[cspotcode]

Thank you for the detailed explanation. I was looking at the code to hopefully make a PR based on your recommendation.

Is the following scenario a potential risk? Again, I'm coming in blind so I don't know if this makes sense.

• 2x background tasks exist, one that will take 5 seconds and one that will take 0.1 seconds.
• Isolate::HasPendingBackgroundTasks returns true because the 0.1 second task must be completed. (the 5 second task is not important)
• Main thread picks up the 5 second task instead of the 0.1 second task.

The main thread is stuck for 5 seconds executing work that is not strictly necessary. Is this possible? Is there a correct way to avoid it?

[cspotcode]

Trying to learn node's internals based on this ticket. I see this looks like where the event loop happens:

node/src/api/embed_helpers.cc

Lines 33 to 49 in bdaf51b

	do {
	if (env->is_stopping()) break;
	uv_run(env->event_loop(), UV_RUN_DEFAULT);
	if (env->is_stopping()) break;
	platform->DrainTasks(env->isolate());
	more = uv_loop_alive(env->event_loop());
	if (more && !env->is_stopping()) continue;
	if (EmitProcessBeforeExit(env).IsNothing())
	break;
	// Emit `beforeExit` if the loop became alive either after emitting
	// event, or after running some callbacks.
	more = uv_loop_alive(env->event_loop());
	} while (more == true && !env->is_stopping());

If I understand correctly, it should be rewritten to the following pseudocode:

      // while event loop has no work and background task is available to be executed,
      // execute a single background task.
      // Stop as soon as event loop gets something to do or we run out of background tasks
      while(true) {
        more = uv_loop_alive(env->event_loop()));
        if(more) break;
        didATask = platform->DrainSingleTask(env->isolate()); // DrainSingleTask is a new method to be implemented
        if(!didATask) break;
      }

      if (more && !env->is_stopping()) continue;

I'm still not sure if this will suffer from the issue I described here, where the event loop can be blocked by a single long task that's not important: #36616 (comment)

[gahaas]

I don't think node blocking on a 5 second background task is an issue anymore. We had that in the past, but by now preempt background tasks regularly so that this cannot happen. Also, the important background tasks are spawned with higher priority, so they should typically get started before the unimportant ones.

[cspotcode]

Are there docs from V8 for the various work queues? I'm looking at https://v8.dev/docs, should I be looking elsewhere to learn more?

[gahaas]

The best I can think of are the comments in v8-platform.h, which defines the API an embedder has to implement to provide a valid platform for V8.
You can also take a look at how the default platform is implemented in V8.

Did you try what I proposed above? Does it now work?

[cspotcode]

Coming back to this. I think some assumptions made in this thread may be incorrect.

BlockingDrain does not execute the tasks, rather it blocks the current thread indefinitely until there are no more tasks, waiting for other threads to execute them.

[gahaas]

Indeed, my assumption was that BlockingDrain does execute tasks, and can be changed to execute just a single task. If BlockingDrain does not execute tasks, maybe it's implementation should then not wait until there are no more tasks, but just until Isolate::HasPendingBackgroundTasks() turns false or until a foreground task got posted.

An alternative would be to change BlockingDrain to execute a single task.

[cspotcode]

My current focus is figuring out how to wait for a foreground task to get posted. Does anyone know of any existing functionality for that?

My free time for this is limited, and so far node's extremely long build times have chewed through most of it. It's very difficult to justify the effort, which is I suspect why this bug remains unfixed a year later.

I also noticed that a workaround to this issue has stopped working in stable node releases:
You used to be able to process.exit() to eagerly end the process if you knew it would otherwise stay alive waiting for turbofan. That workaround works on node 14 but not on node 17.

[gahaas]

Could you try if setting the V8 flag --wasm-dynamic-tiering fixes the problem for you? This is a new feature we are currently working on in V8 where we don't optimize wasm code so eagerly. This feature will be shipped soon, hopefully. Soon means in the next quarter. So if this feature fixes the problem, then maybe we could just wait.

The current implementation of the node platform is still wrong, in my opinion, but maybe it's not such a big issue with dynamic tiering.

[ekpyron]

FYI, I can confirm that the process.exit() workaround stopped working for us (i.e. we still get delayed exit on node 17), but I can also confirm that --wasm-dynamic-tiering seems to solve this issue in our case.

[cspotcode]

Does V8 make any distinction between tasks that may create event loop work, and tasks that will not?

Looking at #15428

V8 platform tasks may schedule other tasks (both background and foreground), and may perform asynchronous operations like resolving Promises.

This is why node's SpinEventLoop implementation waits for all tasks to finish before concluding that the event loop has no more work:

node/src/api/embed_helpers.cc

Lines 35 to 45 in 3f0bcfb

	if (env->is_stopping()) break;
	uv_run(env->event_loop(), UV_RUN_DEFAULT);
	if (env->is_stopping()) break;
	platform->DrainTasks(isolate);
	more = uv_loop_alive(env->event_loop());
	if (more && !env->is_stopping()) continue;
	if (EmitProcessBeforeExit(env).IsNothing())
	break;

I believe this is the problem that needs to be solved: if tasks exist, but they will not schedule anything on the event loop, then node should proceed with calling beforeExit

[gahaas]

If there are background tasks that may schedule foreground tasks, then Isolate::HasPendingBackgroundTasks() returns true. Otherwise Isolate::HasPendingBackgroundTasks() returns false and node should proceed with calling beforeExit.

[cspotcode]

I'm making progress.

I've tweaked NodePlatform::DrainTasks to use this loop, and now beforeExit and exit are calling immediately.

while(true) {
    while(per_isolate->FlushForegroundTasksInternal()) {}
    if(!per_isolate->HasPendingBackgroundTasks()) break;
    uv_sleep(10); // TODO replace with appropriate `Wait` for foreground task to be posted
}

However, the node process is still taking a while to exit because Isolate::Dispose() is taking a long time.

node/src/node_main_instance.h

Line 93 in 8de858b

v8::Isolate* isolate_;

node/src/node_main_instance.cc

Line 124 in 8de858b

isolate_->Dispose();

My informal testing is loading @swc/wasm and synchronously invoking it 1000 times. Either @swc/wasm generates some resources or garbage that take a long time to cleanup, v8's WASM stuff generates resources that take a long time to dispose, or Isolate::Dispose() is still trying to flush all those background tasks. I'm not sure yet.

[cspotcode]

I've tracked the slowness down to OptimizingCompileDispatcher::Stop():

node/deps/v8/src/compiler-dispatcher/optimizing-compile-dispatcher.cc

Lines 194 to 200 in 8de858b

	void OptimizingCompileDispatcher::Stop() {
	HandleScope handle_scope(isolate_);
	FlushQueues(BlockingBehavior::kBlock, false);
	// At this point the optimizing compiler thread's event loop has stopped.
	// There is no need for a mutex when reading input_queue_length_.
	DCHECK_EQ(input_queue_length_, 0);
	}

I'm going to wait for an expert to reply because I suspect they can offer guidance which will be far more productive than me spinning my wheels in the interim.

[gahaas]

I wonder if the issue in the OptimizingCompileDispatcher would be worth a separate issue, maybe even on the V8 bug tracker. For the problem with WebAssembly compilation we have a solution now, don't we?

[cspotcode]

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

@mejedi how was this file created? I think I'll need to recreate it if we're going to write automated tests for this bugfix.

[cameel]

In case @mejedi in not reachable, you could also try Solidity binaries which have the same problem, as mentioned above by @ekpyron.

You can build it by checking out https://github.com/ethereum/solidity/ and launching ./scripts/build_emscripten.sh, which will pull a docker image with all dependencies and compile it.

[cspotcode]

I wonder if the issue in the OptimizingCompileDispatcher would be worth a separate issue, maybe even on the V8 bug tracker. For the problem with WebAssembly compilation we have a solution now, don't we?

To be honest, I'm not really sure. I haven't had a chance to figure out what OptimizingCompileDispatcher is doing.

I've modified node's logic elsewhere so that it does not wait for turbofan tasks to finish. But is OptimizingCompileDispatcher waiting for them anyway? I'm not sure.

[cspotcode]

I've posted my work in progress here: cspotcode#1

[gahaas]

The OptimizingCompileDispatcher manages the optimization of JavaScript code. I guess in your benchmark you are executing some JavaScript code often enough so that it gets hot, and V8 decides to optimize it. But then optimization is still happening when the benchmark wants to exit. The background work of the OptimizingCompileDispatcher would not set Isolate::HasPendingBackgroundTasks() to true, so the node platform would not have to wait for it.

As you also wrote above, it's not node.js that is waiting for the OptimizingCompileDispatcher, it is V8 itself. So if this is really something that needs to be fixed, it should be fixed in V8 and not in node.js. That's why I suggested to file a V8 bug.

[evanw]

It looks like this may have actually been fixed? The first node release that doesn't have this problem is version 18.3.0:

Node version	Time to run esbuild --version with WebAssembly in node
v14.21.1	3.27s
v16.18.1	2.51s
v18.0.0	1.89s
v18.2.0	1.90s
v18.3.0	0.32s ← The problem was fixed here
v18.5.0	0.31s
v18.12.1	0.31s

I didn't see any relevant changes in node itself for that release other than V8 version bumps. So I searched back in V8's history from version 10.2.154 (the version of V8 that node v18.3.0 uses) and found this commit that seems relevant: dynamic tiering for WebAssembly was enabled by default. I'm guessing that was what fixed it.

It's still not as fast as it could be (with the _exit(0) hack mentioned above esbuild --version takes 0.15s instead of 0.31s). But least node no longer takes multiple seconds to exit, which I'd consider good enough for me.

[bnoordhuis]

Re: #36616 (comment) - yes, I do believe this is fixed in v18.x and newer. v16.x is almost EOL and won't get any big updates anymore so I'll go ahead and close this.