Repository navigation
Test Runner is slow #47663
Description
Activity
Just my educated guess as someone who's been watching test_runner development from the outside:
The overhead likely comes from Node.js spawning many child processes, one per test file 1. Meanwhile, Mocha is running all tests in the same process.
I generated a performance profile 2 like this (in Bash on Linux):
$ node --prof --test --test-reporter spec test/ & $ echo $! 11456 # PID of main process $ node --prof-process isolate-*-11456-v8.log > processed_main.txt $ node --prof-process isolate-*-11616-v8.log > processed_test_file.txt
There were 20
isolate-*.logfiles generated in total, and your project has 19 test files. The main profile has the following summary:[Summary]: ticks total nonlib name 6 0.3% 0.4% JavaScript 1541 82.4% 97.5% C++ 479 25.6% 30.3% GC 290 15.5% Shared libraries 34 1.8% Unaccountedand the one sample test file:
[Summary]: ticks total nonlib name 0 0.0% 0.0% JavaScript 844 77.0% 100.0% C++ 6 0.5% 0.7% GC 252 23.0% Shared librariesIn both cases it's almost entirely C++. In the C++ section of the profiles,
__writeis always dominating (total 43% in main and total 62% in child process), followed by__lll_lock_wait. Unfortunately I have no idea how to interpret the results any further since I'm not familiar with the C++ code.Footnotes
There is indeed some overhead here from using child processes. You can see mocha slow down on this particular test suite if you run it with
--parallel, which is more similar to what Node's test runner does.The more interesting thing is that there was a huge slowdown on this suite between Node 18.12.1 and 18.13.0. In 18.12.1, the performance is on par with
mocha --parallel. v18.13.0 is visibly slower. 18.13.0 had a few test runner changes, but I would be willing to bet that the change that introduced the TAP parser is the cause of the slowdown.I think we should confirm if that is indeed the culprit. If it is, we can try to optimize the existing code. It would also be worth looking at removing the TAP parser and lexer completely and using a different serialization format such as JSON or even V8's serializer. I think we could serialize the reporter events directly to the parent process (minus the
Errorobject in thetest:failevent) more quickly than TAP. Unfortunately, changing that format would be a breaking change because 334bb17 publicly tied us to using TAP in this scenario.Reacted by Moshe Atlowthis might very well be a duplicate of #47365
Was the cause of that issue introduced in 18.13.0? If not, then there is at least one other performance issue at play.
perhaps by using IPC
I would be hesitant to spawn the child processes with an IPC channel. That changes how some APIs work, and could lead to different behavior when a file is run with
--testvs. without it.Was the cause of that issue introduced in 18.13.0? If not, then there is at least one other performance issue at play.
Yep, usage of
SafePromiseAllSettledReturnVoidwas added here #45214, and it was released at 18.13.0I would be hesitant to spawn the child processes with an IPC channel. That changes how some APIs work, and could lead to different behavior when a file is run with --test vs. without it.
I am curios, what does it change? the idea was to use IPC to avoid breaking TAP
Yep, usage of SafePromiseAllSettledReturnVoid was added here #45214, and it was released at 18.13.0
That's great to hear.
I am curios, what does it change?
process.channel,process.connected,process.disconnect(),process.send(), and possibly other things that I'm forgetting.the idea was to use IPC to avoid breaking TAP
I'm not 100% sure what you mean here, but I don't think we would break TAP. This would just be the communication protocol between the CLI runner and the child processes. It should never be visible to users unless they were spawning child processes with
NODE_TEST_CONTEXT=child.It's only really a breaking change because we have documented that
NODE_TEST_CONTEXT=childoutputs TAP. We could make it a non-breaking change by changing the CLI to useNODE_TEST_CONTEXT=some-value-other-than-child(actual value to be determined). In that case we could document that the new communication protocol is an internal implementation detail that does not follow semver. We should probably do that for v21 no matter what so that we aren't bound to a specific format forever.Reacted by Moshe AtlowI've noticed a few things when running your test suite locally with node 20.1.0:
- The time elapsed as reported by the test runners seems to be pretty different. I ran the test suites with the
timecommand, and the elapsed time reported by Node's test runner seems to be much closer to what is reported bytime. - I added a three second timeout in the tests. Node properly accounted for this, while mocha completely ignored it when reporting elapsed time.
- When mocha runs all of the tests in a single process, it is indeed faster. According to
time, mocha clocks in around 131ms on my machine, versus 175ms for Node's test runner. However, I don't think running the tests in the same process is a good fundamental design. For example, when I add aprocess.exit()into one of the test files, mocha exits and does not report anything. - When running mocha with
--parallel, which is more similar to how Node's test runner works,timereports mocha being around 261ms, while Node is still at 175ms.
There is definitely still room for improvement in Node's test runner, but I don't think the numbers are quite as drastic as reported in the previous comment.
Reacted by Moshe Atlow and Jamie HaywoodReacted by Moshe Atlow, Toni Villena and Jamie Haywood- The time elapsed as reported by the test runners seems to be pretty different. I ran the test suites with the
Hey guys i'm also experiencing slowness (by slow i mean 10s vs 1s for my faster example while also hammering all cores to the max). i enjoyed how mocha ran everything in the same process cos it was so fast and didnt use all my cpu.
did anyone find out how to speed things up?
one hack i found is to avoid --test and usetime npx c8 node --require ts-node/register/transpile-only --require ./test/setup.ts --test-timeout=300 -e 'require(fs).globSync(test/**/*.test.ts).forEach(file => require(./+ file))'which is wayyyy faster than --test. dunno why.
I made a test repo. with js only my hack from above is faster but the node --test overhead is small enough
With typescript though node --test it's way slower than my hack. it'll take minutes of hammering my CPU instead of 0.8s for my hack
https://github.com/dylan-chong/node-test-slow
I'm guessing typescript is transpiling the entire src for every single test file it runs, so node needs to fix that.
Oh i just realised you dont need the
--require ts-node/register/transpile-onlyat all, its faster but not fast enoughill have to go with my own hack for now :(
Version
18.16.0 same with 20.0.0
Platform
Ubuntu 22.04.2 and Windows 11
Subsystem
test_runner
What steps will reproduce the bug?
Run some simple tests with Nodejs Test Runner. For example:
How often does it reproduce? Is there a required condition?
always
What is the expected behavior? Why is that the expected behavior?
I expect native test runner to run at least as Mocha speed or even faster.
What do you see instead?
duration_ms 1977 when on same tests Mocha runs in 38ms (50x faster, yeah)
Additional information
I also tested it on nodejs 20.0.0 and got same results. Same on Windows 11 and Ubuntu 22.04.2
I was happy to drop Mocha as a dependency, but was not expect to such a slow down.
You can see the switch from Mocha to native Test Runner in this commit egoroof/browser-id3-writer@6d29a06