Start time performance regression when upgrading from 16.x to 18.x

[styfle]

Version

v18.12.1

Platform

Linux ddf105937af6 5.10.47-linuxkit #1 SMP PREEMPT Sat Jul 3 21:50:16 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

No response

What steps will reproduce the bug?

Run the following script replacing node -p '7+8' with the node binary and any command you want to benchmark.

I chose 7+8 as a simple addition example but it reproduces with anything.

Run once with node 16.x and then run again with node 18.x binary.

#!/bin/bash

export TIMEFORMAT=%R;

SUM=0
TRIES=3

for i in $(seq $TRIES)
do
  STR=$( { time node -p '7+8' > /dev/null; } 2>&1 )
  TRIM=$(echo $STR | sed 's/^0\.0*//')
  echo "   $i - start time was $TRIM ms"
  MS=$((TRIM))
  SUM=`expr $SUM + $MS`
done

AVG=`expr $SUM / $TRIES`
echo "Done - average start time for node $(node --version) was $AVG ms"

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

Every time

What is the expected behavior?

Expected Node.js 18 to perform the same as Node.js 16

What do you see instead?

Node.js 16 was faster and Node.js 18 was slower

16.x

   1 - start time was 428 ms
   2 - start time was 387 ms
   3 - start time was 379 ms
Done - average start time for node v16.18.1 was 398 ms

18.x

   1 - start time was 440 ms
   2 - start time was 452 ms
   3 - start time was 425 ms
Done - average start time for node v18.12.1 was 439 ms

That's a decrease of 10%

Additional information

This regression affects macOS, Linux, etc

[anonrig]

According to my local benchmarks, Node 18 is 12.24% slower in start time than Node 16.

➜  node git:(v16.x) ✗ node benchmark/compare.js --old ./node-16 --new ./node-18 --filter startup misc > misc.csv
[00:04:18|% 100| 1/1 files | 60/60 runs | 4/4 configs]: Done
 %
➜  node git:(v16.x) ✗ node-benchmark-compare misc.csv
                                                                                  confidence improvement accuracy (*)   (**)  (***)
misc/startup.js mode='process' script='benchmark/fixtures/require-builtins' dur=1        ***     -2.96 %       ±0.37% ±0.49% ±0.64%
misc/startup.js mode='process' script='test/fixtures/semicolon' dur=1                    ***    -12.24 %       ±0.40% ±0.53% ±0.69%
misc/startup.js mode='worker' script='benchmark/fixtures/require-builtins' dur=1         ***     -2.35 %       ±0.37% ±0.49% ±0.63%
misc/startup.js mode='worker' script='test/fixtures/semicolon' dur=1                     ***     -5.74 %       ±0.32% ±0.42% ±0.55%

Be aware that when doing many comparisons the risk of a false-positive result increases.
In this case, there are 4 comparisons, you can thus expect the following amount of false-positive results:
  0.20 false positives, when considering a   5% risk acceptance (*, **, ***),
  0.04 false positives, when considering a   1% risk acceptance (**, ***),
  0.00 false positives, when considering a 0.1% risk acceptance (***)

[styfle]

Any idea why its slower?

Perhaps @joyeecheung might have more insight here.

[trivikr]

cc @nodejs/performance

[prettydiff]

@styfle Its most likely because V8 is measurably slower across the board: #44186

[anonrig]

Here's the most recent benchmarks I ran after the recent startup performance pull request got merged today:

                                                                                     confidence improvement accuracy (*)   (**)  (***)
misc/startup.js count=30 mode='process' script='benchmark/fixtures/require-builtins'        ***     -3.73 %       ±1.08% ±1.43% ±1.87%
misc/startup.js count=30 mode='process' script='test/fixtures/semicolon'                      *     -0.79 %       ±0.75% ±0.99% ±1.30%
misc/startup.js count=30 mode='worker' script='benchmark/fixtures/require-builtins'         ***     -4.06 %       ±1.06% ±1.41% ±1.84%
misc/startup.js count=30 mode='worker' script='test/fixtures/semicolon'                             -0.82 %       ±1.45% ±1.94% ±2.54%

Be aware that when doing many comparisons the risk of a false-positive result increases.
In this case, there are 4 comparisons, you can thus expect the following amount of false-positive results:
  0.20 false positives, when considering a   5% risk acceptance (*, **, ***),
  0.04 false positives, when considering a   1% risk acceptance (**, ***),
  0.00 false positives, when considering a 0.1% risk acceptance (***)

[joyeecheung]

Sorry that I missed the ping. #45716 and #45659 should fix the baseline startup regression (if not faster, I got locally a slight performance boost when I compared it against v14 and v16, which probably came from snapshotting internals), and I have another WIP to make it 2-3% faster. The regression in most-builtins-loaded startup is expected because the builtins simply has bloated more since previous releases (even if the same set of builtins are required, they actually have more sub-namespaces now for new alternatives). But then most users probably don’t have to load every builtin out there in Node.js during startup.

[joyeecheung]

#45716 can be easily backported to any release line (where v8 snapshot compression was causing slowdown). #45659 would be different because the gradual bloating was at different stages in different releases, so the patch basically needs a re-write for different releases.

[styfle]

Thanks @joyeecheung 🙏

Just checking in here now (happy new year 🎉 )

It looks like both #45716 and #45659 have been merged but we still need to backport both.

Would you like me to create the PRs to backport those into v18.x.

[Whobeu]

I found this issue searching for Node.js v18 vs Node.js v16 performance. I performed an upgrade on some Linux based projects yesterday from 16.19.0 to 18.13.0 and I noticed slightly longer runtimes. Small projects but increases on the order of one or more seconds to accomplish the same task in 16.19.0. Mostly CPU bound tasks performing graphing using Chart.js, node-canvas and ffmpeg. Glad to see I am not the only one who noticed something a bit off. I am going to downgrade back to 16.19.0, as I have the Node upgrade process worked out to be trivial with the necessary "npm rebuild" operations, and see what changes.

[muhammadbilal87]

Facing the same slowdown in upgrading from node 12 to node 19

[joyeecheung]

@muhammadbilal87 Which version of Node.js 19? From my testing Node.js 19.x with the recent patches is as fast as or faster than releases up to v14.x (I didn't test further beyond that). If the issue is still present in Node.js 19.x, I wonder if that's an issue from something else, for example npm run can be 10x slower than the Node.js core startup. Also another factor is that if any code path/dependency was previously in CommonJS but somehow changed to ESM in a new Node.js release, I suspect there would be a pretty significant performance hit because the ESM loader is not quite optimized as CommonJS.

[muhammadbilal87]

In our CI/CD and server we are using node:19-alpine and on on our local we are using 19.3.0

…

On Fri, Mar 3, 2023, 7:40 PM Joyee Cheung ***@***.***> wrote: @muhammadbilal87 <https://github.com/muhammadbilal87> Which version of Node.js 19? From my testing Node.js 19.x with the recent patches is as fast as or faster than releases up to v14.x (I didn't test further beyond that). If the issue is still present in Node.js 19.x, I wonder if that's an issue from something else, for example npm run can be 10x slower than the Node.js core startup. — Reply to this email directly, view it on GitHub <#45662 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ALKR2ZFCYMW4QGHOGY3JKRDW2H7FTANCNFSM6AAAAAASNUUWV4> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[joyeecheung]

I think that might be a different issue, possibly related to other components in Node.js being slower (or maybe user code too if they have version-detect code) - do you have a smaller repro? Or is something like node hello-world.js generally slower in v19.3.0 in your set up?

[Silic0nS0ldier]

It appears #45716 has been backported and is available in NodeJS v18.13.0.

Benchmarks from Linux (Docker using WSL2) compiled from source with node -p '7+8';

• v14.21.4-pre@e9e68b942d: ~20ms
• v16.20.2-pre@7447de2794: ~21ms
• v18.15.2-pre@d92b69e1c1: ~20ms

There does appear to be a separate performance regression which in one service has slowdown down response rates by ~30% (under investigation), which might explain why startup performance regressions are still being reported (that is, it's not a startup performance regression but rather affecting effecting performance in general). Benchmarking across versions with node -p '7+8' should provide the answer in that regard.

[mcollina]

Thanks for confirming that the fix worked. I think we can close this now.

Please feel free to open separate issues for other regressions.