performance regression #26229

Trott · 2019-02-21T04:22:37Z

Unfortunately, it appears that one of the commits in #21573 (d345b0d) has resulted in a significant performance regression. test/pummel/test-crypto-timing-safe-equal-benchmarks.js now takes about twice as long to run and is timing out in the nightly CI. This may be an edge-case thing that we don't care about, but I don't actually know.

$ time ./node-d345b0d test/pummel/test-crypto-timing-safe-equal-benchmarks.js 

real	0m55.449s
user	0m53.389s
sys	0m8.196s
$ time ./node-8375c706 test/pummel/test-crypto-timing-safe-equal-benchmarks.js 

real	0m28.996s
user	0m36.509s
sys	0m6.947s
$

Refs: #26216

/ping @ryzokuken

The text was updated successfully, but these errors were encountered:

jasnell · 2019-02-21T04:42:32Z

If necessary, we can do a quick revert.

Trott · 2019-02-21T05:06:37Z

Running the module benchmarks with n=500:

$ node benchmark/compare.js --old ./node-8375c706 --new ./node-d345b0d --set n=500 module > compare.csv
[00:04:16|% 100| 1/1 files | 60/60 runs | 4/4 configs]: Done
$ cat compare.csv | Rscript benchmark/compare.R 
                                                                 confidence improvement accuracy (*)    (**)   (***)
 module/module-loader.js useCache='false' fullPath='false' n=500                 2.30 %       ±7.01%  ±9.36% ±12.22%
 module/module-loader.js useCache='false' fullPath='true' n=500          **     11.13 %       ±6.60%  ±8.79% ±11.47%
 module/module-loader.js useCache='true' fullPath='false' n=500                 10.26 %      ±17.67% ±23.51% ±30.60%
 module/module-loader.js useCache='true' fullPath='true' n=500          ***    -38.15 %      ±10.97% ±14.60% ±19.01%

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 (***)
$

jdalton · 2019-02-21T05:21:46Z

I'm seeing a regression (to a lesser extent) in my own non-Node core use related to vm.compileFunction() in my master branch too. @hashseed Do you have any insight into possible implementation red flags or improvements for vm.compileFunction()?

hashseed · 2019-02-21T10:41:11Z

TL;DR: v8::ScriptCompiler::CompileFunctionInContext does not use the compilation cache.

V8 uses a compilation cache to speed up parsing/compiling the same source string. This cache is only keyed on the source string, and transparent to the embedder. We cannot use this cache for v8::ScriptCompiler::CompileFunctionInContext because the parameters passed to it affect how we parse/compile.

Note that this compilation cache is not to be confused with the code cache that is stored on disk and needs to be managed by the embedder. v8::ScriptCompiler::CompileFunctionInContext does support the code cache, but the embedder must make sure that the parameters are the same to ensure consistent results.

This particular test benefits a lot from the compilation cache because it compiles the same script over and over again. With a pre-regression build I get this (reducing numTrials from 1e5 to 1e4):

$ time out/Release/node test/pummel/test-crypto-timing-safe-equal-benchmarks.js

real	0m1.702s
user	0m1.985s
sys	0m0.401s

$ time out/Release/node --no-compilation-cache test/pummel/test-crypto-timing-safe-equal-benchmarks.js

real	0m4.488s
user	0m4.742s
sys	0m0.564s

I don't think what this test represents real-world conditions, so how about we just fix this test to no longer time out?

Trott · 2019-02-21T10:59:53Z

I don't think what this test represents real-world conditions, so how about we just fix this test to no longer time out?

If we decide that's the approach to take, we'll probably also want to adjust the benchmark too? (See #26229 (comment).)

Trott · 2019-02-21T11:07:36Z

Making the test not time out but still be reliable may be rather challenging. See #8744.

If we decide this is the way to go, perhaps we can split the test file into two tests: One that runs the timing-safe test and one that runs the not-timing-safe Buffer stuff as the smoke test.

@bnoordhuis @not-an-aardvark

Trott · 2019-02-21T11:32:49Z

Fix (hopefully) for the test #26237?

devsnek · 2019-02-21T21:05:49Z

just to sum this up, it's only a regression for people who depended on the behaviour of V8 to cache the compilation of source text when they repeatedly cleared the require cache?

if that's correct, this regression seems absolutely fine to me. obviously if there's some way to fix it we should, but I don't think this is a serious problem.

hashseed · 2019-02-21T21:07:57Z

Yup. That's why I don't think we need to fix anything in the implementation.

Trott · 2019-02-21T22:09:59Z

If this is a so-called nothingburger, perhaps we should fix the benchmark to not report this as a problem? I'm not sure if that means removing the one variant in the benchmark or if it would mean adjusting the benchmark. See #26229 (comment).

Trott · 2019-02-21T22:11:08Z

I'm going to close this but feel free to re-open or comment if anyone thinks that's premature. Thanks, everyone.

Resetting require.cache() to `Object.create(null)` each time rather than deleting the specific key results in a 10x improvement in running time. Fixes: nodejs#25984 Refs: nodejs#26229

Using `eval()` rather than `require()`'ing a fixture and deleting it from the cache results in a roughtly 10x improvement in running time. Fixes: nodejs#25984 Refs: nodejs#26229 PR-URL: nodejs#26237 Reviewed-By: Joyee Cheung <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Yang Guo <[email protected]> Reviewed-By: Ruben Bridgewater <[email protected]> Reviewed-By: Teddy Katz <[email protected]> Reviewed-By: Richard Lau <[email protected]>

Using `eval()` rather than `require()`'ing a fixture and deleting it from the cache results in a roughtly 10x improvement in running time. Fixes: #25984 Refs: #26229 PR-URL: #26237 Reviewed-By: Joyee Cheung <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Yang Guo <[email protected]> Reviewed-By: Ruben Bridgewater <[email protected]> Reviewed-By: Teddy Katz <[email protected]> Reviewed-By: Richard Lau <[email protected]>

SimenB · 2020-08-15T11:32:04Z

v8::ScriptCompiler::CompileFunctionInContext does support the code cache, but the embedder must make sure that the parameters are the same to ensure consistent results.

@hashseed I realize this is an old comment, but is this something that we can control from JS? "Embedder" sounds like a lower level than vm's API.

Using Script instead of compileFunction seems to improve performance in Jest by 25-40% (see jestjs/jest#9457 (comment)), but if we can cache compilation that might bring them in line (if I understand your comments correctly).

Does it relate to #24069?

I can of course open up a new issue if that's better 👍

Trott added the regression Issues related to regressions. label Feb 21, 2019

This was referenced Feb 21, 2019

module: use compileFunction over Module.wrap #21573

Closed

test: add (temporary) logging for unreliable test #26216

Closed

Trott mentioned this issue Feb 21, 2019

Investigate flaky test-crypto-timing-safe-equal-benchmarks #25984

Closed

hashseed self-assigned this Feb 21, 2019

Trott mentioned this issue Feb 21, 2019

test: improve performance of test-crypto-timing-safe-equal-benchmarks #26237

Closed

2 tasks

Trott closed this as completed Feb 21, 2019

richardlau mentioned this issue Jun 26, 2020

pummel/test-crypto-timing-safe-equal-benchmarks failing #34073

Closed

SimenB mentioned this issue Aug 13, 2020

jest 25 performance jestjs/jest#9457

Open

SimenB mentioned this issue Sep 27, 2020

vm.compileFunction(source) is much slower than new vm.Script(source) #35375

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

performance regression #26229

performance regression #26229

Trott commented Feb 21, 2019 •

edited

Loading

jasnell commented Feb 21, 2019

Trott commented Feb 21, 2019 •

edited

Loading

jdalton commented Feb 21, 2019

hashseed commented Feb 21, 2019 •

edited

Loading

Trott commented Feb 21, 2019

Trott commented Feb 21, 2019

Trott commented Feb 21, 2019

devsnek commented Feb 21, 2019 •

edited

Loading

hashseed commented Feb 21, 2019

Trott commented Feb 21, 2019

Trott commented Feb 21, 2019

SimenB commented Aug 15, 2020 •

edited

Loading

performance regression #26229

performance regression #26229

Comments

Trott commented Feb 21, 2019 • edited Loading

jasnell commented Feb 21, 2019

Trott commented Feb 21, 2019 • edited Loading

jdalton commented Feb 21, 2019

hashseed commented Feb 21, 2019 • edited Loading

Trott commented Feb 21, 2019

Trott commented Feb 21, 2019

Trott commented Feb 21, 2019

devsnek commented Feb 21, 2019 • edited Loading

hashseed commented Feb 21, 2019

Trott commented Feb 21, 2019

Trott commented Feb 21, 2019

SimenB commented Aug 15, 2020 • edited Loading

Trott commented Feb 21, 2019 •

edited

Loading

Trott commented Feb 21, 2019 •

edited

Loading

hashseed commented Feb 21, 2019 •

edited

Loading

devsnek commented Feb 21, 2019 •

edited

Loading

SimenB commented Aug 15, 2020 •

edited

Loading