Worker threads can be much slower than child processes

[zackschuster]

While updating emailjs to ava@4, i noticed that a certain section of our tests were running far slower using worker threads compared to child processes. the code in question involves transmitting large data streams over an smtp connection & parsing them into objects.

with worker threads:

  ✔ message › very large text message (5.9s)
  ✔ message › very large text data message (9.7s)
  ✔ message › html data message (9.8s)
  ✔ message › html file message (9.9s)
  ✔ message › html with image embed message (9.9s)
  ✔ message › html data and attachment message (10s)
  ✔ message › attachment message (10.1s)
  ✔ message › attachment sent with unicode filename message (10.2s)
  ✔ message › attachments message (13.3s)
  ✔ message › streams message (16.4s)

with child processes:

  ✔ message › very large text message (1.9s)
  ✔ message › very large text data message (3.1s)
  ✔ message › html data message (3.1s)
  ✔ message › html file message (3.2s)
  ✔ message › html with image embed message (3.2s)
  ✔ message › html data and attachment message (3.2s)
  ✔ message › attachment message (3.2s)
  ✔ message › attachment sent with unicode filename message (3.3s)
  ✔ message › attachments message (4.2s)
  ✔ message › streams message (5s)

the latter results are consistent with ava@3 performance. the conversion work is not pushed to the github repo yet.

here is the ava.config,js:

export default {
	extensions: {
		ts: 'module',
	},
	environmentVariables: {
		NODE_TLS_REJECT_UNAUTHORIZED: '0',
	},
	files: ['test/*.ts'],
	nodeArguments: ['--loader=ts-node/esm'],
	workerThreads: false,
};

[novemberborn]

Individual tests aside, how long does it take for the total suite to complete? If you run with --concurrency 1 do the execution times align?

It strikes me that file access is synchronous. Perhaps it's blocking across threads? I'm not sure how this works internally actually.

[zackschuster]

i think there is some form of blocking; when i change our synchronous file reads to async it changes around the ordering, but e.g. last item will always be ~5s. that could just be request timing; one of our testing libraries is slow on profiles, and since tests share a server per module, could (also) be blocking. not sure how that would affect worker threads perf relative to child processes, though.

[zackschuster]

on an M1 Pro chip: ava completes after ~9s; ava --concurrency 1 completes after ~14s. execution times for the tests in question are indistinguishable across scenarios.

[zackschuster]

update: as of this commit, on the same chip with workerThreads: false our tests now complete after ~4.7s (concurrency 1 completes after ~9s). with workerThreads: true they produce this lovely v8 crash:

FATAL ERROR: v8::FromJust Maybe value is Nothing.
 1: 0x100aed35c node::Abort() [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 2: 0x100aed4dc node::OnFatalError(char const*, char const*) [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 3: 0x100c17340 v8::V8::FromJustIsNothing() [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 4: 0x100b954e0 node::ReportWritesToJSStreamListener::OnStreamAfterReqFinished(node::StreamReq*, int) [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 5: 0x100b95530 node::ShutdownWrap::OnDone(int) [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 6: 0x100b99b9c node::LibuvStreamWrap::AfterUvShutdown(uv_shutdown_s*, int) [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 7: 0x101356190 uv__stream_io [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 8: 0x10135e0a8 uv__io_poll [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
 9: 0x10134c0a0 uv_run [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
10: 0x100b7e408 node::worker::Worker::Run() [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
11: 0x100b81580 node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::__invoke(void*) [/Users/zackschuster/.nvm/versions/node/v14.19.2/bin/node]
12: 0x18b62226c _pthread_start [/usr/lib/system/libsystem_pthread.dylib]
13: 0x18b61d08c thread_start [/usr/lib/system/libsystem_pthread.dylib]

[zackschuster]

worker threads stopped crashing, for seemingly no reason. their speed is on par or maybe slightly faster than child processes.

at this point i'm thinking the reported slowness is due to the original behavior in the tests, where more than a dozen (already very slow!) units each unintentionally blocked each other by using the same test object, and the object in question was doing lots of inter-process communication. something in that mess probably pushed V8 over a perf cliff.