concurrent tests are slow

[iambumblehead]

Version

v19.8.1

Platform

Darwin Bumbles-MBP.home 21.6.0 Darwin Kernel Version 21.6.0: Mon Dec 19 20:44:01 PST 2022; root:xnu-8020.240.18~2/RELEASE_X86_64 x86_64

What steps will reproduce the bug?

Use this repo https://github.com/iambumblehead/demo-slow-node-test

from the package,

• npm run test-ava takes about 10 seconds
  
• npm run test-node-describe takes about 30 seconds
  
• npm run test-node-test takes about 30 seconds
  

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

It is reproduced any time the test repo is used on this machine

What is the expected behavior? Why is that the expected behavior?

node:test should use multiple cores and should not be slow

What do you see instead?

Hello, I recently replaced node:test with ava in a project using ~250 tests. The node:test runner would complete in ~18 minutes and the ava runner completes in ~9 minutes. The node:test version of the project used describe/it tests with the following pattern,

describe('app', { concurrency: true }, async () => {
  beforeEach(() => {
    nock.disableNetConnect();
  });

  it('test a', async () => {
    assert.ok(true);
  });
  
  it('test b', async () => {
    assert.ok(true);
  });
  
  // ...
});

Additional information

Test concurrency might have some problems. Initially, I tried using { concurrency: true } with a single file that contained about a dozen tests and tests completed in a time that was observably faster. When { concurrency: true } was used with multiple files, the improvement seemed to go away and each group of tests would run slowly,

Test concurrency requires extra boilerplate. Eg, to run tests concurrently, one needs to use nested describe/it tests, nested tests wrapped in a promise or use a configuration file. related links here, and here. It would be nice if concurrent tests were easier to achieve with a special import import test from 'node:test/concurrent' or with a cli option --test-concurrency=true, link to a related comment here: do not expose a test-concurrency flag.

Thank you

[cjihrig]

The fact that you're seeing almost exactly a 2x slowdown seems to me like something is being done in serial. It's impossible to say without knowing more about the test suite itself. I will say that I personally wouldn't recommend using concurrency blindly. The default behavior of running the test files in parallel and running the tests in each file serially seems to work well for most cases.

Initially, I tried using { concurrency: true } with a single file that contained about a dozen tests and tests completed in a time that was observably faster. When { concurrency: true } was used with multiple files, the improvement seemed to go away and each group of tests would run slowly,

This sounds to me like trying to run too many things in parallel lead to a slowdown, which is understandable and will also depend on your system and the nature of the tests.

I did a small comparison with ava. Given the following files and Node 19.8.1:

// core.mjs
import test from 'node:test';

for (let i = 0; i < 250; i++) {
  test(`test ${i}`, t => {});
}

and

// ava.mjs
import test from 'ava';

for (let i = 0; i < 250; i++) {
  test(`test ${i}`, t => {
    t.pass();
  });
}

On my M1, time node --test core.mjs ran in about 0.11-0.13 seconds, while time node node_modules/.bin/ava ava.mjs ran in about 0.32-0.34 seconds. Obviously, this example isn't using concurrency but I doubt that alone would double the execution time without the nature of the tests playing a part too.

[iambumblehead]

@cjihrig screenshots of system monitor while running tests with ava (left) then node:test (right)

node:test uses one cpu it appears. No blip at "memory pressure" when running either test runner,

[iambumblehead]

It would be really nice if node:test supported a cli option --test-concurrency=true to run all tests with maximum concurrency and no boilerplate or nesting ceremony.

[ForbiddenEra]

It would be really nice if node:test supported a cli option --test-concurrency=true to run all tests with maximum concurrency and no boilerplate or nesting ceremony.

+1 or otherwise --test-concurrency=<number of threads> (edit: eg. same behavior as docs say for run())

[iambumblehead]

I wrote this little test forumula to multiple files to try and reproduce the single-processor issue, but node handles these tests correctly using three cores and they finish relatively quickly. There must be something in my application tests that is causing tests to run sequentially, but I don't know what that could be...

import { describe, it, beforeEach } from 'node:test';
import assert from 'node:assert/strict';
import util from 'util';
import crypto from 'crypto';

const lorem = 'Lorem ipsum dolor sit amet, consectetur adipiscing elit,'
  + 'sed do eiusmod tempor incididunt ut labore et dolore magna aliqua.';

const scrypt = async (plaintext, salt) => (
  util.promisify(crypto.scrypt)(plaintext, salt, 64));

const testNumber = 1000;

beforeEach(() => 1 + 1 === 2);

const test = (tests => Object.assign((name, fn) => tests.push([name, fn]), {
  go: descr => describe(
    descr, { concurrency: true }, async () => tests
      .map(([name, fn]) => it(name, fn)))
}))([]);

for (let x = testNumber; x--;) {
  test(`test-${x}`, async () => {
    await scrypt(x + lorem + x, 'salt' + x);
    assert.ok(true);
  });
}

test.go();

[iambumblehead]

Update: possible reproduction here when using node --loader=esmock --test ./path/to/file.test.js

describe('legacy_routeAppV2', { concurrency: true }, async () => {
  beforeEach(() => {
    nock.disableNetConnect();
  });

  for (let x = 50; x--;) {
    it(`test-${x}`, async () => {
      const mockdb = await mockdbPopulate(mockdbData);
      // the below call causes tests to slow and cpu usage to stay at one core
      // increasing loop number from 50 to 1000 causes test runner to hang
      const {
        routeAppGetAuthorized
      } = await esmock('../../src/routes/legacy_routeAppV2.js', {}, {
        db: mockdb
      });

      assert.ok(String(routeAppGetAuthorized));
    });
  }
});

at each test (above), esmock creates a deeply mocked import tree using query params that include a unique id for the tree. Adding esmock to the crypto-ciphering describe/it test loop submitted here an hour or so ago did not reproduce the issue, so the issue is not trivially reproduced by using "--loader"

cc @cjihrig possibly this can be reproduced with tests that generate deeply mocked import trees. In the loop above, increasing the loop number from 50 to 1000 causes the test runner to completely hang.

attached: updated describe/it test, using esmock. (using --loader and esmock here does not reproduce the issue. Tests complete quickly and use maximum number of cores, 3)

test.target.js

import util from 'util';
import crypto from 'crypto';

const lorem = 'Lorem ipsum dolor sit amet, consectetur adipiscing elit,'
  + 'sed do eiusmod tempor incididunt ut labore et dolore magna aliqua.';

const scrypt = async (plaintext, salt) => (
  util.promisify(crypto.scrypt)(plaintext, salt, 64));

export {
  scrypt,
  lorem
};

node.describe.many.test.js

import { describe, it, beforeEach } from 'node:test';
import esmock from 'esmock';
import assert from 'node:assert/strict';

const testNumber = 1000;

const test = (tests => Object.assign((name, fn) => tests.push([name, fn]), {
  go: descr => {
    beforeEach(() => 1 + 1 === 2);
    describe(
      descr, { concurrency: true }, async () => tests
        .map(([name, fn]) => it(name, fn)));
  }
}))([]);

for (let x = testNumber; x--;) {
  test(`test-${x}`, async () => {
    // this creates a "shallow" mock rather than an entirely new "deep" mock
    // import tree. The crypto-ciphering test above uses "deep" mocking
    const { scrypt, lorem } = await esmock('./test.target.js', {
      crypto: {
        salt: () => 'salty'
      }
    });
    
    await scrypt(x + lorem + x, 'salt' + x);
    assert.ok(true);
  });
}

test.go('with esmock');

cc @koshic @Swivelgames

[iambumblehead]

The esmock usage here triggers a situation that ava is better able to manage than node:test

[koshic]

@iambumblehead I still can't catch the root cause - there are no equal scripts for node:test / ava to compare them.

[iambumblehead]

I apologize for expressing opinions without having a clear reproduction to share here.

@koshic thanks, I'll try to create a reproduction before next week.

[iambumblehead]

sorry to not create a reproduction yet, I plan to make a reproduction soon

[tniessen]

Could we clarify both the expectations and the actual implementation regarding concurrency? The node:test docs are a bit vague in this regard.

It seems that different files are executed in different processes:

node/doc/api/test.md

Lines 376 to 377 in 9a7b971

	Each matching test file is executed in a separate child process. If the child
	process finishes with an exit code of 0, the test is considered passing.

It seems that the concurrency option of run() is the number of files that are executed in parallel:

node/doc/api/test.md

Lines 733 to 734 in 9a7b971

	* `concurrency` {number|boolean} If a number is provided,
	then that many files would run in parallel.

But I am not sure what the concurrency option of test() does. All I can find in the docs is:

node/doc/api/test.md

Lines 797 to 803 in 9a7b971

	* `concurrency` {number|boolean} If a number is provided,
	then that many tests would run in parallel.
	If `true`, it would run `os.availableParallelism() - 1` tests in parallel.
	For subtests, it will be `Infinity` tests in parallel.
	If `false`, it would only run one test at a time.
	If unspecified, subtests inherit this value from their parent.
	**Default:** `false`.

But what mechanism is used for concurrency? Is the test() itself again split into multiple processes? That could mean quite a lot of overhead. Is the test() split into multiple threads? That would be much more efficient, but it does not seem likely based on the documentation. Or is it just parallel asynchronous operations in a single process? That would be easy to implement, but then using a value of os.availableParallelism() seems illogical.

---

Aside from these questions, the kind of workload makes a big difference. For example, synchronous tasks are going to exhaust the application thread, whereas asynchronous thread pool tasks (such as crypto.scrypt() in the example above) are going to exhaust the thread pool across all application threads within a single process. Spawning many processes comes with a ton of overhead, and each process spawns its own thread pool, etc.

[MoLow]

Could we clarify both the expectations and the actual implementation regarding concurrency? The node:test docs are a bit vague in this regard.

I agree, we should probably document this better.

It seems that the concurrency option of run() is the number of files that are executed in parallel:

both run() and node --test (which uses run internally) spawn a process per test file, using os.availableParallelism() - 1 as the number of concurrent tests.

But I am not sure what the concurrency option of test() does. All I can find in the docs is:
But what mechanism is used for concurrency? Is the test() itself again split into multiple processes? That could mean quite a lot of overhead. Is the test() split into multiple threads? That would be much more efficient, but it does not seem likely based on the documentation. Or is it just parallel asynchronous operations in a single process?

it is indeed a queue running parallel asynchronous operations, with no isolation between tests in the same file.
the default concurrency for tests inside a file is 1, meaning they run sequentially be default

That would be easy to implement, but then using a value of os.availableParallelism() seems illogical.
Aside from these questions, the kind of workload makes a big difference

using os.availableParallelism() - 1 for files and 1 for test()'s is a heuristic that tries to aim at the common use cases (or what we believe they are).
there might be a better value but as you said, that would really depend on the specific tests and use-case, thus this is configurable

Additionally, these choices take into account not just speed but also the isolation of tests,
where in case they are isolated in separate processes, it is safer to run them in parallel (not impossible to face race conditions but usually that would be in race conditions in accession I/O)
but in tests in the same file facing such issues is more likely when running in parallel

[iambumblehead]

I'm reproducing the issue with the package at this repo https://github.com/iambumblehead/demo-slow-node-test

from the package,

• npm run test-ava takes about 10 seconds
• npm run test-node-describe takes about 30 seconds
• npm run test-node-test takes about 30 seconds

increasing the number defined in the package.json can make the node test runner hang, but ava reasonably handles any number. cc @cjihrig

[ForbiddenEra]

using os.availableParallelism() - 1 for files and 1 for test()'s is a heuristic that tries to aim at the common use cases (or what we believe they are). there might be a better value but as you said, that would really depend on the specific tests and use-case, thus this is configurable

Just want to mention that it may be a common case where some/all tests are intended to run sequentially.

One might not want test2.js to run if test1.js fails or modify what tests test2.js runs.. or one might want test1.js to run basically sequentially and if it passes then test2.js could run in parallel.

The current implementation isn't really ideal for this and I can't really use run() or --test in my situations, I have a run-tests.js file that launches the tests instead, generally importing a default exported async function from each test file and calling that to initiate it's tests.

I can provide some more in-depth examples that relate to projects I'm using node:test for already if anyone is curious or wants more info.

[tniessen]

Thanks for the detailed response @MoLow, that's very helpful. So every test file has its own process, and within a test file, there is no real concurrency in the classical sense: all tests run within the same application thread. That seems be confirmed by @iambumblehead's statement above: "node:test uses one cpu it appears."

What surprises me is that the docs say that test({ concurrency: true }) is equivalent to test({ concurrency: os.availableParallelism() - 1 }). However, as far as I know, os.availableParallelism() is pretty much meaningless for scaling within a single thread.

[targos]

@tniessen what would be a good default value in your opinion? Infinity?

[tniessen]

npm run test-ava

@iambumblehead Running this on a 16-core CPU, it takes less than 5 seconds wall clock time, but about 30 seconds of user CPU time. In other words, it utilizes about 50 % of all available CPU cores.

npm run test-node-test

Running this on the same CPU, it takes about 20 seconds wall clock time, and about the same amount of user CPU time. In other words, it utilizes just a single CPU core out of 16.

[MoLow]

npm run test-node-test
Running this on the same CPU, it takes about 20 seconds wall clock time, and about the same amount of user CPU time. In other words, it utilizes just a single CPU core out of 16.

I have not yet had the time to look into the repro, but if node --test files does not use all available cores that sounds like an issue

[iambumblehead]

btop cpu while running while true; do npm run test-ava; done

btop cpu while running while true; do npm run test-node-describe; done

[MoLow]

@iambumblehead test files were actually running serially, thanks for the good repro!
after the fix, it seems like AVA and node --test perform pretty much the same

[iambumblehead]

@MoLow awesome it will be great to try it out soon!

[tniessen]

what would be a good default value in your opinion? Infinity?

@targos It seems like the documentation is incorrect and the implementation does use Infinity in that case. Similar to the issue that was discovered in #47675, this also does not seem to be covered by any tests.

PR for more doc fixes and test: #47734