Major performance regression from 6.10.2 to 7.x and 8.0.0-test

[MikeRalphson]

• Version: 7.0.0 (first version with regressed performance)
• Platform: Windows 10.0.14393 32-bit
• Subsystem: unknown

I'm seeing a major performance regression from Node 6.x (e.g. 6.10.2) to all versions of Node 7.x and v8.0.0-test20170511830c4bf319.

The application is the test-suite of swagger2openapi which converts a JS object from one schema to another, then validates using ajv and the should assertion library.

I know travis isn't a benchmarking environment, but the results are consistent.

When I try to profile converting a single file (which shows around a 100% increase in execution time), both Node 7.0.0 and v8.0.0-test20170511830c4bf319 show almost all the time as unaccounted.

Node8 profiling results

Statistical profiling result from isolate-007FD5D8-v8.log, (1008 ticks, 811 unaccounted, 0 excluded).
 [Shared libraries]:
   ticks  total  nonlib   name
     63    6.3%          D:\nodejs\node8.exe

 [JavaScript]:
   ticks  total  nonlib   name
     42    4.2%    4.4%  LazyCompile: <anonymous>
     26    2.6%    2.8%  LazyCompile: *<anonymous> D:\nodejs\swagger2openapi\node_modules\should-type\cjs\should-type.js:171:16
      4    0.4%    0.4%  LazyCompile: *typeAdaptorForEachFormat D:\nodejs\swagger2openapi\node_modules\should-format\cjs\should-format.js:166:34
      3    0.3%    0.3%  LazyCompile: *AssertionError D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:67:24
      2    0.2%    0.2%  LazyCompile: *LightAssertionError D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:151:29
      2    0.2%    0.2%  Function: ~getLocale D:\nodejs\swagger2openapi\node_modules\os-locale\index.js:29:19
      2    0.2%    0.2%  Function: ~<anonymous> D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:2350:34
      1    0.1%    0.1%  RegExp: data1([^0-9])
      1    0.1%    0.1%  RegExp: ^\\/\\/[^@/]+@[^@/]+
      1    0.1%    0.1%  RegExp: ^[-+]?(?:\\d+(?:\\.\\d*)?|\\.\\d+)(e[-+]?\\d+)?$
      1    0.1%    0.1%  RegExp: ^(?:(?:[a-z][a-z0-9+-.]*:)?\\/\\/)?[^\\s]*$
      1    0.1%    0.1%  RegExp: ^"|"$
      1    0.1%    0.1%  RegExp: \\bgfs4\\b
      1    0.1%    0.1%  RegExp: [{]protocols_re[}]
      1    0.1%    0.1%  RegExp: [\\/@\\s\\+%:]
      1    0.1%    0.1%  LazyCompile: ~jptr D:\nodejs\swagger2openapi\node_modules\jgexml\jpath.js:15:14
      1    0.1%    0.1%  LazyCompile: ~LightAssertionError D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:151:29
      1    0.1%    0.1%  LazyCompile: *formatPlainObjectKey D:\nodejs\swagger2openapi\node_modules\should-format\cjs\should-format.js:229:30
      1    0.1%    0.1%  LazyCompile: *constructorName D:\nodejs\swagger2openapi\node_modules\should-format\cjs\should-format.js:146:25
      1    0.1%    0.1%  Function: ~setupInit internal/process/next_tick.js:221:21
      1    0.1%    0.1%  Function: ~convertPropertyName D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:24:29
      1    0.1%    0.1%  Function: ~checkParam D:\nodejs\swagger2openapi\validate.js:146:20
      1    0.1%    0.1%  Function: ~LightAssertionError D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:151:29
      1    0.1%    0.1%  Function: ~<anonymous>

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
     98    9.7%   10.4%  JavaScript
      0    0.0%    0.0%  C++
      4    0.4%    0.4%  GC
     63    6.3%          Shared libraries
    811   80.5%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
    811   80.5%  UNKNOWN
    684   84.3%    D:\nodejs\node8.exe

     63    6.3%  D:\nodejs\node8.exe

     42    4.2%  LazyCompile: <anonymous>
      4    9.5%    LazyCompile: *<anonymous> D:\nodejs\swagger2openapi\node_modules\should-type\cjs\should-type.js:171:16
      4    9.5%    D:\nodejs\node8.exe
      2    4.8%    LazyCompile: <anonymous>
      2  100.0%      D:\nodejs\node8.exe
      1    2.4%    Function: ~D:\nodejs\swagger2openapi\node_modules\ajv\lib\dotjs\_limitProperties.js

     26    2.6%  LazyCompile: *<anonymous> D:\nodejs\swagger2openapi\node_modules\should-type\cjs\should-type.js:171:16
      7   26.9%    D:\nodejs\node8.exe
      1    3.8%    LazyCompile: <anonymous>

What can I do to narrow-down the problem so I can produce a minimal test-case? My antivirus suite excludes the whole directory containing the versions of node.exe and the running code.

Are there any major anti-patterns which are likely to trigger much worse performance in 7.x and above?

[bnoordhuis]

Did you node8.exe --prof-process isolate-007FD5D8-v8.log? If you use a different node binary to process it, you can get bad output like 80% unaccounted ticks.

[MikeRalphson]

@bnoordhuis Indeed I did:

Mike@Mike_Ralphson MINGW32 /d/nodejs/swagger2openapi (master)
$ node8.exe --prof-process isolate-007FD5D8-v8.log
Statistical profiling result from isolate-007FD5D8-v8.log, (1008 ticks, 811 unaccounted, 0 excluded).

I've added the log as a gist here.

[bnoordhuis]

You mentioned you saw similar numbers on a different system? What does the profile look like on that system?

Apropos the gist:

code-creation,LazyCompile,1,067F2040,3460,"writeNode D:\nodejs\swagger2openapi\node_modules\js-yaml\lib\js-yaml\dumper.js:668:19",05CB2ABC,*
code-disable-optimization,"writeNode","Deoptimized too many times"

If you don't see that with node 6, that would be a good place to start looking.

[bnoordhuis]

I forgot to mention, node --trace_opt --trace_deopt script.js prints out what functions get deoptimized and why.

[MikeRalphson]

You mentioned you saw similar numbers on a different system? What does the profile look like on that system?

I will try and get profiles from Travis uploaded as build artifacts (the ones above come from my local Windows 10 system).

If you don't see that with node 6, that would be a good place to start looking.

I don't see that in the logs for Node 6 or 7, but disabling that part of the code doesn't seem to bring the wall-clock times appreciably closer.

Will look at node --trace_opt --trace_deopt, thanks.

[MikeRalphson]

What looks different in the Node 8 --trace_deopt log are several instances each of:

;;; deoptimize at <D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:152:14>,
no cache

and

;;; deoptimize at <D:\nodejs\swagger2openapi\node_modules\should\cjs\should.js:68:14>, no cache

Both lines are shouldUtil.merge(this, options);

should_utils merge is defined as:

function merge(a, b) {
  if (a && b) {
    for (var key in b) {
      a[key] = b[key];
    }
  }
  return a;
}

Commenting out the calls to merge get Node 7 and 8 to completing in around 5s instead of the 9.5 or so, which is comparable with Node 6. Is the reference to this and no cache helpful at all?

I can try and minimise a test case if needed.

[MikeRalphson]

It would be interesting to see if this testcase is reproducable:

var should = require('should'); //11.2.0

for (var i=0;i<10000;i++) {
    true.should.not.throw();
}

Windows 10 w/ Node 6 around 3.6s, w/ Node 8 around 12.5s.

[addaleax]

$ nvm use 6
Now using node v6.10.1
$ time node test.js

real	0m2.400s
user	0m1.388s
sys	0m0.128s
$ nvm use 7
Now using node v7.10.0
$ time node test.js

real	0m5.736s
user	0m5.784s
sys	0m0.064s

That seems reproducible to me.

[MikeRalphson]

The loop contents may be an abuse of shoulds syntax, but the following real-world example also shows the performance problem and the large number of unaccounted ticks:

i.should.not.be.type('string');

I wonder if we're hitting this V8 bug ?

[MikeRalphson]

Possibly related to #11343 which indicates a fix has landed in v8.

[MikeRalphson]

Could someone help me determine which release of v8 includes commit 989d7b96f8352b502e2ede62e0b105e143d03837 and when this version is likely to be incorporated into a Node.js release?

[targos]

GitHub shows you all the branches that contain this commit if you follow this link: v8/v8@989d7b9. It's right under the commit message.
In this case, the oldest version is 6.1.522. V8 6.1 will soon be incorporated into Node's master branch. Meanwhile, I will try to backport this commit to V8 6.0.

[targos]

#15383

[BridgeAR]

The fix is already in master and this will be fixed in probably the next release. I am closing this therefore.