Node.js - a tale of two bugs

One day, back in March 2017, I decided to implement WhatWG URL parsing in swagger2openapi. This depended on Node.js 7, so I installed it locally, and everything worked fine.

I then added Node.js 7 to the list of Node.js versions tested by my favoured CI tool, Travis.

That's when I noticed something wrong. Node.js 6.x would complete the test-suite in around 4 minutes, but Node.js 7 was taking over 14 minutes!

I temporarily disabled the WhatWG URL parsing, assuming this had to be the slow path, as it was the only different code enabled on Node.js 7.

That turned out to have no appreciable effect on the Travis wall-clock timings.

At this point, I raised an issue on the Node.js GitHub repository giving as much information as I had, including that the performance issue existed in all versions of Node.js 7.x and also in a pre-release version of Node.js 8.

I also included profiling information using the following options:

$ node8.exe --profile swagger2openapi petstore.json
$ node8.exe --prof-process isolate-007FD5D8-v8.log

The first command produces a profiling log, and the second command analyses it. It is important to run both commands with exactly the same version of Node.js.

Unfortunately, when I tried to profile converting a single file (which showed around a 100% increase in execution time), both Node.js 7.x and v8.0.0-test20170511830c4bf319 showed almost all the time as unaccounted:

...
 [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
...
 [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
...

Having exhausted my Node.js debugging skills, I asked what I could do to try and produce a minimal test-case, and if there were any major anti-patterns which could result in much worse performance in Node.js 7 and 8.

I was at this stage convinced that the problem lay either in ajv (the library used to validate JSON schemas in swagger2openapi) or should.js (the BDD test/assertion library I was using).

Ben Noordhuis added to the issue that the following command would provide more in-depth profiling information, specifically on which functions were being de-optimised, and why:

$ node8 --trace_opt --trace_deopt swagger2openapi petstore.json

This pointed to two lines within should.js:

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

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

That helped narrow it down, and I soon came up with a minimal test-case which showed the regressed behaviour.

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

for (var i=0;i<10000;i++) {
    i.should.not.be.type('string');
}

Node.js contributor Anna Henningsen reported that this was reproduceable.

Things went a little quiet then, so I looked at all the other Node.js issues labelled performance to see if anything was related.

I found another issue which seemed similar, in that it was related to thrown exceptions.

This issue demonstrated a standalone benchmark, which didn't reference any libraries:

for (let i = 0; i < 100000; i++) {
  Error.captureStackTrace({});
}

This ran 10 times slower on Node.js 7 and 8 than it did on Node.js 6.

On this issue Ben Noordhuis noted that it was a known issue in v8, and it was later noted that a fix had been implemented there.

A few weeks went by, and I decided to chase up my original issue to see what version of v8 contained the fix and when was it likely to show up in Node.js - this would allow me to update my daily-driver version of Node.js to version 8.

Node.js contributor Michaël Zasso showed me a neat trick I wasn't aware of, on GitHub when looking at a commit, under the commit message, it shows you all the branches which include that commit (the list can be expanded if it is large):

He also offered to try and back-port the fix into v8 6.0 so it could be included in the current release stream of Node.js. This effort appears to have stalled however, but the good news is that the fix is already in the nightly builds of Node.js 9.0, which include v8 6.1.

The plan was to release Node.js 8.7 with v8 6.1, which should have fixed all my problems, however, a problem has been found with the v8 escape analysis which has had to be disabled in Node.js 8.7 - potentially making this release not as fast as I'd hoped. Whether the fix from v8 6.2 will make it into Node.js 8.x before it goes LTS (Long Term Support) is still a matter of conjecture, but I leave you with the comparative timings from my use-case for Node.js 6.11.4, 8.6.0, 8.7.0 and 9.0.0-nightly.

If you're using an exception-based assertion tool in your development environment, or any performance-critical code which depends on thrown error stack-traces, or just wondered where your performance went since Node.js 6.x, you should definitely consider upgrading to Node.js 8.7.