Performance regression in Node.js v14

[mcollina]

See #46 (comment)

[mcollina]

@puzpuzpuz I think it's a regression in core.

v12:

benchCore*1000: 5758.926ms

v14:

benchCore*1000: 6.924s

[mcollina]

@ronag do you know what could have slown down https://github.com/mcollina/sonic-boom/blob/63bc3a4024c17302c7b0d4d3d0ca2ee0f2e772a9/bench.js#L55-L60 so much in v14?

[puzpuzpuz]

Yes, it looks a lot like a core-side regression. I'm going to profile the benchmark tomorrow and try to find the bottleneck in v14.

[ronag]

How does it look if you try with node 15?

[mcollina]

same

[ronag]

Yea, we would need to do a bisect.

[puzpuzpuz]

@mcollina @ronag
A quick bisect over versions showed that the regression was introduced in v14.5.0. So, the regression must be somewhere here: nodejs/node#34093

[mcollina]

There are so many suspects there, it'll take a while :/.

[puzpuzpuz]

I've tried profiling the benchmark on 14.4.0 and 14.5.0 and noticed one strange thing. In 14.5.0 flatstr takes 32.1% (1656 of 5157 samples), while in 14.4.0 it's only 4.9% (179 of 3665 samples). So, maybe it's a regression on V8 side?

[ronag]

I can't really see anything suspicious in the change log for 14.5. At least not related to streams or fs.

[mcollina]

I've tried profiling the benchmark on 14.4.0 and 14.5.0 and noticed one strange thing. In 14.5.0 flatstr takes 32.1% (1656 of 5157 samples), while in 14.4.0 it's only 4.9% (179 of 3665 samples). So, maybe it's a regression on V8 side?

removing flatstr does not change the bench

[puzpuzpuz]

removing flatstr does not change the bench

Hmm, then it's something else.

[mcollina]

I'm currently bisect, let's see where I land.

[mcollina]

It's the V8 update

$ git bisect good
There are only 'skip'ped commits left to test.
The first bad commit could be any of:
55f7ae6386eafa10012e1a7ccf3149becb3b5288
6b5ea2efa23d5e6206ea8db2bba54995c20c6597
9dfaf49b84ff13f83dbe9755ac2eb934719792df
c3866a1b3e9de7b19753d822b313509f43266c42
32be677f49b6415ce08842fe78288637f300041d
a48928836a930ecdc894e9c684a675bde1508109
db0ed118d8f39e93063425076dd7d95351d799eb
e9a6ba0a4c144585f58a78e36692a4f6d0fb82ea
308900faef8b2e5edab5f9737495d2d1b3b54ffe
54ae041309b0f8934b45b4fd73efcfc1bcb1842b
0d50ba5d482a7d5e3f94df3bbc182813d3fb28e4
37abad4340d4602ced23125b5a409a2aa4a7f57d
1d6adf7432defeb39b751a19c68335e8afb0d8ee
56bdec44a8ab447edafbd7a31116650cd0cf138b
7baaab014b5427a326689aebc7ce9846882c5af5
We cannot bisect more!

[puzpuzpuz]

So, it's something in V8 after all.

[mcollina]

I'm not set up to bisect V8 :/

[puzpuzpuz]

In the profiler output I also noticed the following.

14.4.0:

 [Summary]:
   ticks  total  nonlib   name
    312    7.9%   43.0%  JavaScript
    413   10.5%   57.0%  C++
    498   12.7%   68.7%  GC
   3204   81.5%          Shared libraries

14.5.0:

 [Summary]:
   ticks  total  nonlib   name
    328    6.1%   47.1%  JavaScript
    368    6.8%   52.9%  C++
   1965   36.3%  282.3%  GC
   4724   87.2%          Shared libraries

Notice the 1965 ticks (36.3%) spent in GC in 14.5.0. So, I wonder if the regression may be related with this change in V8: https://v8.dev/blog/v8-release-83#faster-arraybuffer-tracking-in-the-garbage-collector

[mcollina]

That can definitely be it. However I'm a bit unclear where the ArrayBuffers are being allocated as this manipulates just strings.

[puzpuzpuz]

That can definitely be it. However I'm a bit unclear where the ArrayBuffers are being allocated as this manipulates just strings.

I was thinking of WriteString native function which is used to do the actual write, but it seems that it deals with plain Realloc calls. So, ArrayBuffer changes are probably unrelated, but the difference in time spent in GC still looks suspicious to me.

[mcollina]

It is very suspicious and the source of the slowdown.

[mcollina]

I did a little bit of investigation on this. Apparently, the gc runs 4197 vs 5010 for the same number of iterations. In the v8 8.1 case, it does a few Mark&Sweep, while in the v8.3 it does not.