search

nodejs / node

Node.js JavaScript runtime ✨🐢🚀✨
https://nodejs.org
Other
108.07k stars 29.83k forks source link

Node v8 4-5x slower than previous versions #13445

Closed milesj closed 7 years ago

milesj commented 7 years ago

Occurs on both OSX and Linux (Travis CI).

I've noticed that one of my projects unit tests are running 4-5x slower on Node v8 than previous versions. I have yet to determine the cause, but an example can be found in the Travis builds: https://travis-ci.org/milesj/emoji-database

This is 100% reproducible and consistent, even on OSX. Here's an output of the tests being run on OSX (notice the times).

$ NODE_ENV=test run-tests 
 PASS  tests/extractGender.test.js
 PASS  tests/cleanName.test.js
 PASS  tests/extractSkinTone.test.js
 PASS  tests/createShortnames.test.js
 PASS  tests/createTags.test.js
 PASS  tests/extractSet.test.js
 PASS  tests/fromUnicodeToHex.test.js
 PASS  tests/fromHexToCodepoint.test.js
 PASS  tests/regex.test.js (57.436s)
 PASS  tests/packageData.test.js (121.958s)

Test Suites: 10 passed, 10 total
Tests:       51415 passed, 51415 total
Snapshots:   0 total
Time:        123.471s, estimated 129s
Ran all test suites.

Compared to Node v7.

$ NODE_ENV=test run-tests 
 PASS  tests/extractSet.test.js
 PASS  tests/extractGender.test.js
 PASS  tests/createTags.test.js
 PASS  tests/extractSkinTone.test.js
 PASS  tests/cleanName.test.js
 PASS  tests/createShortnames.test.js
 PASS  tests/fromUnicodeToHex.test.js
 PASS  tests/fromHexToCodepoint.test.js
 PASS  tests/regex.test.js (8.174s)
 PASS  tests/packageData.test.js (11.178s)

Test Suites: 10 passed, 10 total
Tests:       51415 passed, 51415 total
Snapshots:   0 total
Time:        13.606s
Ran all test suites.

https://github.com/milesj/emoji-database

mscdex commented 7 years ago

I was about to try to look into it myself, but it appears the emoji-database module depends on at least a 148mb dependency (emojione) that npm wants nothing to do with.

Have you tried running with the appropriate V8 flags to see if things are being deoptimized permanently or something similar? You can check for permanent deopts with:

node --trace-opt --trace-file-names myscript.js | grep -i 'aborted\|disabled'

Otherwise you can generally see what V8 is optimizing, deoptimizing, and/or inlining or not with the --trace-opt, --trace-deopt, and --trace-inlining flags respectively.

milesj commented 7 years ago

Here's the output of the first command.

node --trace-opt --trace-file-names ./node_modules/.bin/run-tests ./tests/packageData.test.js | grep -i 'aborted\|disabled'
[aborted optimizing 0x27e1aedbba81 <JS Function </Users/Miles/Sites/emoji-database/node_modules/yargs/lib/argsert.js> (SharedFunctionInfo 0xecb8c886681)> because: Unsupported phi use of const or let variable]
[disabled optimization for 0xecb8c886681 <SharedFunctionInfo>, reason: Unsupported phi use of const or let variable]
[disabled optimization for 0x2b7b9f96ea89 <SharedFunctionInfo createShortnames>, reason: Unsupported let compound assignment]
[disabled optimization for 0x29ef9f818ac1 <SharedFunctionInfo it>, reason: Bad value context for arguments value]
[disabled optimization for 0x29ef9f815809 <SharedFunctionInfo>, reason: Bad value context for arguments value]
[aborted optimizing 0xcbf7ffb02c1 <JS Function toBeOneOf </Users/Miles/Sites/emoji-database/tests/setup.js> (SharedFunctionInfo 0x855beb486b9)> because: Unsupported phi use of const or let variable]
[disabled optimization for 0x855beb486b9 <SharedFunctionInfo toBeOneOf>, reason: Unsupported phi use of const or let variable]

I'll mess around with the others.

mscdex commented 7 years ago

Try fixing those permanent deopts first and see what kind of impact that has. For example, the ones about let or const would involve changing variable declarations in those functions one by one back to var until the deopt message disappears.

The others like 'Bad value context for arguments value' may not be as straightforward. That particular deopt typically has to do with having func.apply(..., arguments) in functions that have properties tacked onto them. It's hard to say whether this is being done in the test runner itself, just in the tests, or in the actual module code.

vsemozhetbyt commented 7 years ago

You can also check if your code heavily uses the patterns that are currently slower in the Node.js 8 in comparison with the previous versions:

https://fhinkel.github.io/six-speed/

cc @nodejs/performance, @nodejs/v8

bmeurer commented 7 years ago

Can you try with --turbo or alternatively using Node LKGR?

ctdio commented 7 years ago

I too have been seeing some slower performance on node 8.0.0 with one of my projects. In my case, I managed to narrow down the culprit and found that String.prototype.split is approximately 5x slower now. I haven't tried benchmarking any of the other string methods to see if there were performance hits there.

@milesj I peeked into your code and saw that one of your tests uses split quite frequently. I have a strong feeling that you are seeing the same performance issues I am.

vsemozhetbyt commented 7 years ago

@charlieduong94 I cannot reproduce the String.prototype.split slowdown with a naive test:

Code and results (click me): ```js console.log(` // Node.js ${process.versions.node} (v8 ${process.versions.v8}) ${process.config.variables.target_arch} `); const str = 'ab'.repeat(1000); let len; console.time("'a'"); for (let i = 0; i < 1e4; i++) len = str.split('a').length; console.timeEnd("'a'"); console.time('/a/'); for (let i = 0; i < 1e4; i++) len = str.split(/a/).length; console.timeEnd('/a/'); console.time(" ''"); for (let i = 0; i < 1e4; i++) len = str.split('').length; console.timeEnd(" ''"); process.title = len; // to not discard the results ``` ```console // Node.js 4.8.3 (v8 4.5.103.47) x64 'a': 365ms /a/: 1307ms '': 112ms // Node.js 6.10.3 (v8 5.1.281.101) x64 'a': 349.567ms /a/: 1339.276ms '': 106.782ms // Node.js 7.10.0 (v8 5.5.372.43) x64 'a': 370.449ms /a/: 1352.863ms '': 105.928ms // Node.js 8.0.0-nightly201703249ff7ed23cd (v8 5.6.326.57) x64 'a': 356.759ms /a/: 1200.888ms '': 99.012ms // Node.js 8.0.0-nightly2017050673d9c0f903 (v8 5.7.492.69) x64 'a': 368.424ms /a/: 1234.220ms '': 107.315ms // Node.js 8.0.0 (v8 5.8.283.41) x64 'a': 384.050ms /a/: 1287.733ms '': 94.300ms // Node.js 8.0.0-test201704119b43f9c487 (v8 5.9.0 (candidate)) x64 'a': 376.580ms /a/: 1251.424ms '': 102.169ms // Node.js 8.0.0-pre (v8 6.0.153) x64 'a': 363.516ms /a/: 1292.573ms '': 104.215ms ```

mscdex commented 7 years ago

@charlieduong94 Can you share the snippet of code you used to benchmark that function? Also, which other node version did you compare with (besides node v8.0.0)?

ctdio commented 7 years ago

Here's the snippet. I used benchmark.js to run the function as many times as possible in quick succession. I compared against node 7.6.0.

const { Suite } = require('benchmark')

const str = 'this/string/has/some/slashes/in/it'

const suite = new Suite()
suite
  .add('split', () => {
    return str.split('/')
  })
  .on('cycle', (event) => {
    console.log(String(event.target))
  })
  .on('complete', function (event) {
    console.log('Fastest is ' + this.filter('fastest').map('name'))
  })
  .run({ async: true })

Here are the results I got: screen shot 2017-06-06 at 12 00 16 am

mscdex commented 7 years ago

I think I've verified this. Here's a simpler reproduction:

const str = 'this/string/has/some/slashes/in/it';
const header = `split ${process.version}`;
const n = 1e7;

console.time(header);
for (var i = 0; i < n; ++i)
  str.split('/');
console.timeEnd(header);

Results:

split v9.0.0-pre: 3546.705ms
split v7.9.0: 713.974ms
milesj commented 7 years ago

Thanks guys for looking into this. I've been out of town the last few days and am just now getting back to this.

I've ran both --trace-deopt and --trace-inlining, but I'm not exactly sure what I should be looking for. Here's the output.

``` node --trace-inlining --trace-file-names ./node_modules/.bin/run-tests ./tests/packageData.test.js Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining api function 0x7349653971 (SharedFunctionInfo 0x73496538b9)> Inlined GetExistingHash called from get. Inlined HashToEntry called from MapFindEntry. Inlined MapFindEntry called from get. Inlined GetExistingHash called from GetHash. Inlined GetHash called from set. Inlined HashToEntry called from MapFindEntry. Inlined MapFindEntry called from set. Inlining api function 0x7349653971 (SharedFunctionInfo 0x73496538b9)> Inlined stat called from tryFile. Did not inline toRealPath called from tryFile (ParseAndAnalyze found incompatibility). Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._resolveFilename. Did not inline Module._resolveLookupPaths called from Module._resolveFilename (target text too big). Did not inline Module._findPath called from Module._resolveFilename (target text too big). Inlined ok called from Module.require. Inlined ok called from Module.require. Did not inline Module._load called from Module.require (target text too big). Inlined Buffer.isEncoding called from assertEncoding. Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined modeNum called from fs.openSync. Inlined getPathFromURL called from fs.openSync. Inlined handleError called from fs.openSync. Inlined nullCheck called from fs.openSync. Did not inline stringToFlags called from fs.openSync (target text too big). Inlining api function 0x7349652521 (SharedFunctionInfo 0x7349652469)> Inlined assertSize called from Buffer.allocUnsafe. Did not inline createUnsafeArrayBuffer called from createPool (ParseAndAnalyze found incompatibility). Inlined createPool called from allocate. Inlined alignPool called from allocate. Did not inline createUnsafeArrayBuffer called from createUnsafeBuffer (ParseAndAnalyze found incompatibility). Inlined createUnsafeBuffer called from allocate. Inlined allocate called from Buffer.allocUnsafe. Did not inline createUnsafeArrayBuffer called from createPool (ParseAndAnalyze found incompatibility). Inlined createPool called from allocate. Inlined alignPool called from allocate. Did not inline createUnsafeArrayBuffer called from createUnsafeBuffer (ParseAndAnalyze found incompatibility). Inlined createUnsafeBuffer called from allocate. Inlining api function 0x7349652729 (SharedFunctionInfo 0x7349652671)> Inlining api function 0x7349652319 (SharedFunctionInfo 0x7349652261)> Did not inline stringSlice called from Buffer.toString (target text too big). Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlined createScript called from runInThisContext. Did not inline fs.readFileSync called from Module._extensions..js (target text too big). Did not inline Module._compile called from Module._extensions..js (target text too big). Inlined exports._extend called from getOptions. Inlined Buffer.isEncoding called from assertEncoding. Inlined assertEncoding called from getOptions. Inlined getOptions called from realpathSync. Inlined nullCheck called from realpathSync. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlined splitRoot called from realpathSync. Inlined nextPart called from realpathSync. Inlining api function 0x7349653d81 (SharedFunctionInfo 0x7349653cc9)> Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlined splitRoot called from realpathSync. Inlined encodeRealpathResult called from realpathSync. Inlined debugs.(anonymous function) called from Module._load. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._resolveFilename. Did not inline Module._resolveLookupPaths called from Module._resolveFilename (target text too big). Did not inline Module._findPath called from Module._resolveFilename (target text too big). Inlined Module._resolveFilename called from Module._load. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._load. Inlined debugs.(anonymous function) called from Module._load. Did not inline NativeModule.require called from Module._load (target text too big). Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined Module called from Module._load. Did not inline tryModuleLoad called from Module._load (ParseAndAnalyze found incompatibility). Inlined exports._extend called from getOptions. Inlined Buffer.isEncoding called from assertEncoding. Inlined assertEncoding called from getOptions. Inlined assertPath called from resolve. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Did not inline normalizeStringPosix called from resolve (target text too big). Inlined assertPath called from isAbsolute. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da064b1 (SharedFunctionInfo 0x13651ae49c01)> Inlined retry called from . Did not inline Array called from ArraySpeciesCreate (Dont inline [new] Array(n) where n isn't constant.). Inlining builtin 0x22021da064b1 (SharedFunctionInfo 0x13651ae49c01)> Inlined guessType called from . Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> RUNS tests/packageData.test.js Inlined GetExistingHash called from get. Inlined HashToEntry called from MapFindEntry. Inlined MapFindEntry called from get. Inlined assertPath called from extname. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlined debugs.(anonymous function) called from Module.load. Inlined ok called from Module.load. Did not inline Module._nodeModulePaths called from Module.load (target text too big). Inlined ComputeIntegerHash called from GetExistingHash. Inlined ComputeIntegerHash called from GetExistingHash. Inlined GetExistingHash called from GetHash. Inlined NativeModule.getCached called from NativeModule.require. Inlined NativeModule.exists called from NativeModule.require. Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined NativeModule called from NativeModule.require. Inlined NativeModule.cache called from NativeModule.require. Did not inline NativeModule.compile called from NativeModule.require (ParseAndAnalyze found incompatibility). Inlined ComputeIntegerHash called from GetExistingHash. Inlined GetExistingHash called from GetHash. Inlined GetHash called from set. Inlined HashToEntry called from MapFindEntry. Inlined MapFindEntry called from set. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._resolveFilename. Did not inline Module._resolveLookupPaths called from Module._resolveFilename (target text too big). Did not inline Module._findPath called from Module._resolveFilename (target text too big). Inlined debugs.(anonymous function) called from Module._load. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._resolveFilename. Did not inline Module._resolveLookupPaths called from Module._resolveFilename (target text too big). Did not inline Module._findPath called from Module._resolveFilename (target text too big). Inlined Module._resolveFilename called from Module._load. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._load. Inlined debugs.(anonymous function) called from Module._load. Did not inline NativeModule.require called from Module._load (target text too big). Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined Module called from Module._load. Did not inline tryModuleLoad called from Module._load (ParseAndAnalyze found incompatibility). Inlined assertPath called from dirname. Inlined assertPath called from basename. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Did not inline stringSlice called from Buffer.toString (target text too big). Inlined NativeModule.wrap called from Module._compile. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined exports._extend called from getOptions. Inlined Buffer.isEncoding called from assertEncoding. Inlined assertEncoding called from getOptions. Inlined getOptions called from realpathSync. Inlined nullCheck called from realpathSync. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlined splitRoot called from realpathSync. Inlined nextPart called from realpathSync. Inlining api function 0x7349653d81 (SharedFunctionInfo 0x7349653cc9)> Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlined splitRoot called from realpathSync. Inlined encodeRealpathResult called from realpathSync. Did not inline fs.readFileSync called from Module._extensions..js (target text too big). Did not inline Module._compile called from Module._extensions..js (target text too big). Inlined ComputeIntegerHash called from GetExistingHash. Inlined GetExistingHash called from GetHash. Inlined GetHash called from add. Inlined HashToEntry called from SetFindEntry. Inlined SetFindEntry called from add. Inlined debugs.(anonymous function) called from Module._load. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._resolveFilename. Did not inline Module._resolveLookupPaths called from Module._resolveFilename (target text too big). Did not inline Module._findPath called from Module._resolveFilename (target text too big). Inlined Module._resolveFilename called from Module._load. Inlined NativeModule.exists called from NativeModule.nonInternalExists. Inlined NativeModule.isInternal called from NativeModule.nonInternalExists. Inlined NativeModule.nonInternalExists called from Module._load. Inlined debugs.(anonymous function) called from Module._load. Did not inline NativeModule.require called from Module._load (target text too big). Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined Module called from Module._load. Did not inline tryModuleLoad called from Module._load (ParseAndAnalyze found incompatibility). Inlined exports._extend called from getOptions. Inlined Buffer.isEncoding called from assertEncoding. Inlined assertEncoding called from getOptions. Inlined CSSStyleSheet called from parse. Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlined setProperty called from parse. Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined CSSStyleDeclaration called from CSSStyleRule. Inlined CSSStyleRule called from parse. Inlined CSSStyleSheet called from parse. Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlined setProperty called from parse. Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined CSSStyleDeclaration called from CSSStyleRule. Inlined CSSStyleRule called from parse. Inlined CSSStyleSheet called from parse. Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlined setProperty called from parse. Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined CSSStyleDeclaration called from CSSStyleRule. Inlined CSSStyleRule called from parse. Inlined CSSStyleSheet called from parse. Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlined setProperty called from parse. Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined CSSStyleDeclaration called from CSSStyleRule. Inlined CSSStyleRule called from parse. Inlined CSSStyleSheet called from parse. Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined CSSStyleDeclaration called from CSSStyleRule. Inlined CSSStyleRule called from parse. Inlined CSSStyleSheet called from parse. Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da17169 (SharedFunctionInfo 0x13651ae36c01)> Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined CSSStyleDeclaration called from CSSStyleRule. Inlined CSSStyleRule called from parse. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined module.exports called from isCoreModule. Inlined assertPath called from normalize. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Did not inline normalizeStringPosix called from normalize (target text too big). Inlined getMockModule called from getMockModule. Did not inline _resolveStubModuleName called from getMockModule (target text too big). Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Did not inline requireModule called from requireInternalModule (target text too big). Inlined requireInternalModule called from options.isInternalModule.moduleName. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Inlined Stats called from statsFromValues. Inlined assertPath called from parse. Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da171b1 (SharedFunctionInfo 0x13651ae36d41)> Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined module.exports called from isCoreModule. Inlined isCoreModule called from _getAbsolutPath. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Inlined getModule called from _isModuleResolved. Inlined getMockModule called from getMockModule. Did not inline _resolveStubModuleName called from getMockModule (target text too big). Inlined getMockModule called from _isModuleResolved. Inlined _isModuleResolved called from _getAbsolutPath. Inlined getModulePath called from _getVirtualMockPath. Did not inline resolveModule called from _getVirtualMockPath (target text too big). Inlined _getVirtualMockPath called from _getAbsolutPath. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined module.exports called from isCoreModule. Inlined isCoreModule called from _getMockPath. Inlined getMockModule called from getMockModule. Did not inline _resolveStubModuleName called from getMockModule (target text too big). Inlined getMockModule called from _getMockPath. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Inlined getModule called from _isModuleResolved. Inlined getMockModule called from getMockModule. Did not inline _resolveStubModuleName called from getMockModule (target text too big). Inlined getMockModule called from _isModuleResolved. Inlined getModulePath called from _getVirtualMockPath. Did not inline resolveModule called from _getVirtualMockPath (target text too big). Inlined assertPath called from join. Did not inline require called from runScript (ParseAndAnalyze found incompatibility). Inlined implForWrapper called from exports.evalVMScript. Inlined exports.evalVMScript called from runScript. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Inlined Stats._checkModeProperty called from Stats.isFile. Inlined getPathFromURL called from fs.statSync. Inlined handleError called from fs.statSync. Inlined nullCheck called from fs.statSync. Inlining api function 0x7349653b79 (SharedFunctionInfo 0x7349653ac1)> Inlined Stats called from statsFromValues. Inlined statsFromValues called from fs.statSync. Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Did not inline nodeModulesPaths called from getModulePaths (target text too big). Did not inline shouldInstrument called from transform (target text too big). Inlined getScriptCacheKey called from transform. Did not inline _transformAndBuildScript called from transform (target text too big). Inlining builtin 0x22021da06619 (SharedFunctionInfo 0x13651ae4a081)> Inlined _supportsNativePlatform called from getModule. Inlined getModule called from getModule. Inlined transformEmojiDatum called from . Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Inlined transformEmojiDatum called from . Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Inlined transformEmojiDatum called from . Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Inlined transformEmojiDatum called from . Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Did not inline Array called from ArraySpeciesCreate (Dont inline [new] Array(n) where n isn't constant.). Inlined removeDiacritics called from emojiOne.keywords.filter.map.kw. Inlined cleanName called from createTags. Inlined cleanName called from createShortnames. Inlined extractSkinTone called from createShortnames. Inlined CACHE.sort called from QuickSort. Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Did not inline specFactory called from Env.it (target text too big). Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Inlined Object..Suite.addChild called from Env.it. Inlined Object..Suite.getFullName called from getSpecName. Inlined getSpecName called from getSpecName. Inlined Object..Spec.getFullName called from Spec. Inlined getNextSpecId called from specFactory. Did not inline beforeAndAfterFns called from specFactory (target has context-allocated variables). Did not inline Spec called from specFactory (target has context-allocated variables). Inlined Env.specFilter called from specFactory. Inlined Object..Spec.getFullName called from Spec. Inlined getNextSpecId called from specFactory. Did not inline beforeAndAfterFns called from specFactory (target has context-allocated variables). Did not inline Spec called from specFactory (target has context-allocated variables). Inlined Env.specFilter called from specFactory. Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline it called from forEach.emoji (target not inlineable). Did not inline executeNode called from node.children.map.child (target has context-allocated variables). Inlined isEnabled called from executeNode. Inlined isEnabled called from executeNode. Inlined Object..Suite.getFullName called from getSpecName. Did not inline _asyncToGenerator called from makeResolveMatcher (target has context-allocated variables). Did not inline _asyncToGenerator called from makeRejectMatcher (target has context-allocated variables). Did not inline pTimeout called from mapper (target has context-allocated variables). Inlined ComputeIntegerHash called from GetExistingHash. Inlined GetExistingHash called from GetHash. Did not inline insert called from exports.active (target text too big). Inlined TimersList called from createTimersList. Inlining api function 0x22021da74391 (SharedFunctionInfo 0x22021da742d9)> Inlined remove called from append. Inlined initTriggerId called from Timeout. Inlined Timeout called from createSingleTimeout. Did not inline insert called from exports.active (target text too big). Inlined exports.active called from createSingleTimeout. Inlined debugs.(anonymous function) called from reuse. Inlining api function 0x22021da744d9 (SharedFunctionInfo 0x22021da74421)> Inlined reuse called from exports.unenroll. Inlined debugs.(anonymous function) called from exports.unenroll. Inlining api function 0x22021da73e71 (SharedFunctionInfo 0x22021da73db9)> Inlined exports.unenroll called from Timeout.close. Inlined Timeout.close called from exports.clearTimeout. Did not inline _extractSpecResults called from specDone (target text too big). Inlining builtin 0x22021da06469 (SharedFunctionInfo 0x13651ae49ac9)> Inlined ComputeIntegerHash called from GetExistingHash. Inlined GetExistingHash called from get. Inlined HashToEntry called from MapFindEntry. Inlined MapFindEntry called from get. Did not inline queueRunner called from queueRunnerFactory (target text too big). Did not inline Object..module.exports called from queueRunner (target text too big). Inlined TimersList called from createTimersList. Inlining api function 0x22021da74391 (SharedFunctionInfo 0x22021da742d9)> Did not inline Object..Spec.execute called from fn (target text too big). Inlined Object..Spec.getFullName called from Spec.attr.onStart.context. Inlined Object..expect.setState.state called from Spec.attr.onStart.context. Inlined defaultResourcesForRunnable called from specStarted. Did not inline called from specStarted (target not inlineable). Inlined Object..Suite.sharedUserContext called from Object..Suite.clonedSharedUserContext. Inlined Object..Suite.clonedSharedUserContext called from userContext. Inlined isPromise called from asyncFn. Inlined isPromise called from asyncFn. Inlined Object..Spec.status called from complete. Inlined Object..expect.getState called from addSuppressedErrors. Inlined Object..expect.setState.state called from addSuppressedErrors. Inlined addSuppressedErrors called from Spec.attr.resultCallback. Did not inline addAssertionErrors called from Spec.attr.resultCallback (target text too big). Inlined currentRunnable called from currentSpies. Inlined currentRunnable called from currentSpies. Inlined currentSpies called from SpyRegistry.clearSpies. Inlined SpyRegistry.clearSpies called from clearResourcesForRunnable. Inlined clearResourcesForRunnable called from specResultCallback. Did not inline called from specResultCallback (target not inlineable). Inlining builtin 0xd687e2cb641 (SharedFunctionInfo 0x13651ae49ac9)> Inlining api function 0x22021da747b1 (SharedFunctionInfo 0x22021da746f9)> Inlined debugs.(anonymous function) called from insert. Inlined TimersList called from createTimersList. Inlining api function 0x22021da74391 (SharedFunctionInfo 0x22021da742d9)> Inlined createTimersList called from insert. Inlined ok called from insert. Inlined ComputeIntegerHash called from GetExistingHash. Inlined GetExistingHash called from GetHash. Inlined GetHash called from set. Inlined HashToEntry called from MapFindEntry. Inlined MapFindEntry called from set. Did not inline makeThrowingMatcher called from Object.keys.forEach.name (target text too big). Did not inline makeThrowingMatcher called from Object.keys.forEach.name (target text too big). Did not inline makeResolveMatcher called from Object.keys.forEach.name (target text too big). Did not inline makeResolveMatcher called from Object.keys.forEach.name (target text too big). Did not inline makeRejectMatcher called from Object.keys.forEach.name (target text too big). Did not inline makeRejectMatcher called from Object.keys.forEach.name (target text too big). Inlined Object..Spec.isExecutable called from Object..Spec.execute. Did not inline queueRunner called from queueRunnerFactory (target text too big). Inlined queueRunnerFactory called from Object..Spec.execute. Inlined ensureActualIsNumber called from ensureNumbers. Inlined ensureExpectedIsNumber called from ensureNumbers. Did not inline expect called from emoji.tags.forEach.tag (target text too big). Inlined ensureActualIsNumber called from ensureNumbers. Inlined ensureExpectedIsNumber called from ensureNumbers. Inlined ensureNumbers called from toBeGreaterThanOrEqual. Trying to inline the polymorphic call to apply from dispatch Trying to inline the polymorphic call to apply from dispatch Inlining builtin 0xd687e2cb7f1 (SharedFunctionInfo 0x13651ae4a081)> Did not inline Array called from wrapper (Dont inline [new] Array(n) where n isn't constant.). Did not inline expect called from emoji.shortnames.forEach.name (target text too big). Inlined initTriggerId called from Timeout. Inlined Timeout called from createSingleTimeout. Did not inline insert called from exports.active (target text too big). Inlined exports.active called from createSingleTimeout. Inlined createSingleTimeout called from setTimeout. Did not inline startTimer called from Window.setTimeout (target has context-allocated variables). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Inlined ensureActualIsNumber called from ensureNumbers. Inlined ensureExpectedIsNumber called from ensureNumbers. Inlined ensureNumbers called from toBeLessThanOrEqual. Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from it (target text too big). Inlined ensureNoExpected called from toBeDefined. Inlined initTriggerId called from Timeout. Inlined Timeout called from createSingleTimeout. Did not inline insert called from exports.active (target text too big). Inlined exports.active called from createSingleTimeout. Inlined createSingleTimeout called from setTimeout. Inlined setTimeout called from startTimer. Did not inline expect called from emoji.shortnames.forEach.name (target text too big). Inlined Object..expect.getState called from addAssertionErrors. Inlined Object..expect.setState.state called from addAssertionErrors. Did not inline expect called from emoji.tags.forEach.tag (target text too big). Did not inline expect called from emoji.shortnames.forEach.name (target text too big). Did not inline expect called from it (target text too big). Did not inline expect called from emoji.shortnames.forEach.name (target text too big). Inlined currentRunnable called from currentSpies. Inlined currentRunnable called from currentSpies. Inlined currentSpies called from SpyRegistry.clearSpies. Inlined SpyRegistry.clearSpies called from clearResourcesForRunnable. ```

The deopt output is far too large, but it was basically repeating this a lot.

``` [removing optimized code for: getSpecName] [deoptimizing (DEOPT eager): begin 0xc3babd836c1 (SharedFunctionInfo 0x3b4af74b0521)> (opt #179) @4, FP to SP delta: 72, caller sp: 0x7fff5fbf5c48] ;;; deoptimize at , wrong map reading input frame getSpecName => node=7, args=2, height=2; inputs: 0: 0xc3babd836c1 ; [fp - 16] 0xc3babd836c1 (SharedFunctionInfo 0x3b4af74b0521)> 1: 0x7d512b62ff9 ; [fp + 24] 0x7d512b62ff9 2: 0x7d512b62ff9 ; rcx 0x7d512b62ff9 3: 0x39beb1b32691 ; rax 0x39beb1b32691 4: 0x321bf9b26a39 ; rbx 0x321bf9b26a39 (SharedFunctionInfo 0x3a9f526c8791)> reading input frame getSpecName => node=3, args=3, height=3; inputs: 0: 0x321bf9b26a39 ; (literal 5) 0x321bf9b26a39 (SharedFunctionInfo 0x3a9f526c8791)> 1: 0xdf76b202311 ; (literal 6) 0xdf76b202311 2: 0x7d512b62ff9 ; rcx 0x7d512b62ff9 3: 0x1201695db3c9 ; rdx 0x1201695db3c9 4: 0x3b4af74de669 ; (literal 7) 0x3b4af74de669 5: 0xdf76b202311 ; (literal 6) 0xdf76b202311 6: 0xdf76b202311 ; (literal 6) 0xdf76b202311 translating frame getSpecName => node=7, height=8 0x7fff5fbf5c40: [top + 48] <- 0x7d512b62ff9 ; 0x7d512b62ff9 (input #1) 0x7fff5fbf5c38: [top + 40] <- 0x7d512b62ff9 ; 0x7d512b62ff9 (input #2) ------------------------- 0x7fff5fbf5c30: [top + 32] <- 0x17f5ebd5260e ; caller's pc 0x7fff5fbf5c28: [top + 24] <- 0x7fff5fbf5c78 ; caller's fp 0x7fff5fbf5c20: [top + 16] <- 0x39beb1b32691 ; context 0x39beb1b32691 (input #3) 0x7fff5fbf5c18: [top + 8] <- 0xc3babd836c1 ; function 0xc3babd836c1 (SharedFunctionInfo 0x3b4af74b0521)> (input #0) ------------------------- 0x7fff5fbf5c10: [top + 0] <- 0x321bf9b26a39 ; 0x321bf9b26a39 (SharedFunctionInfo 0x3a9f526c8791)> (input #4) translating frame getSpecName => node=3, height=16 0x7fff5fbf5c08: [top + 64] <- 0xdf76b202311 ; 0xdf76b202311 (input #1) 0x7fff5fbf5c00: [top + 56] <- 0x7d512b62ff9 ; 0x7d512b62ff9 (input #2) 0x7fff5fbf5bf8: [top + 48] <- 0x1201695db3c9 ; 0x1201695db3c9 (input #3) ------------------------- 0x7fff5fbf5bf0: [top + 40] <- 0x17f5ebd0d8d3 ; caller's pc 0x7fff5fbf5be8: [top + 32] <- 0x7fff5fbf5c28 ; caller's fp 0x7fff5fbf5be0: [top + 24] <- 0x3b4af74de669 ; context 0x3b4af74de669 (input #4) 0x7fff5fbf5bd8: [top + 16] <- 0x321bf9b26a39 ; function 0x321bf9b26a39 (SharedFunctionInfo 0x3a9f526c8791)> (input #0) ------------------------- 0x7fff5fbf5bd0: [top + 8] <- 0xdf76b202311 ; 0xdf76b202311 (input #5) 0x7fff5fbf5bc8: [top + 0] <- 0xdf76b202311 ; 0xdf76b202311 (input #6) [deoptimizing (eager): end 0xc3babd836c1 (SharedFunctionInfo 0x3b4af74b0521)> @4 => node=3, pc=0x17f5ebd0d998, caller sp=0x7fff5fbf5c48, state=NO_REGISTERS, took 1.169 ms] ```
bmeurer commented 7 years ago

@schuay can probably shed some light on this.

schuay commented 7 years ago

Thanks for reporting, this looks like a bug in V8. I created http://crbug.com/v8/6463 to track this on our side.

What's happening is that String.p.split has a fast path that caches results for certain inputs. A recent change had the unintended consequence of disabling this path.

vsemozhetbyt commented 7 years ago

@schuay Can you explain why the results in these two tests differ?

@vsemozhetbyt (no regression): https://github.com/nodejs/node/issues/13445#issuecomment-306358293

@mscdex (regression): https://github.com/nodejs/node/issues/13445#issuecomment-306382960

schuay commented 7 years ago

Your test does not cache results because the subject string isn't internalized, so it isn't affected by the bug above.

(Internalized strings are deduplicated and stored in a hash table inside v8, so equality can be determined just by comparing pointers. E.g. string literals are turned into internalized strings.)

vsemozhetbyt commented 7 years ago

@schuay Is there a way to forcibly internalize a non-literal string (e.g. mentioned 'ab'.repeat(1000)), say, for a test purpose?

schuay commented 7 years ago

@vsemozhetbyt You can run node with --allow-natives-syntax and then use

%InternalizeString(str)  // Internal function, subject to change at any time.
vsemozhetbyt commented 7 years ago

@schuay I have just stumbled upon this line in a benchmark (+another one). Is it somehow connected with string internalizing?

schuay commented 7 years ago

@vsemozhetbyt no, flattening is another concept - it's intended to ensure that the string contents are in a plain sequential memory area (like C strings).

schuay commented 7 years ago

The fix (http://crbug.com/v8/6463) has now been backmerged to V8 6.0, and should be picked up automatically for Node lts.

bmeurer commented 7 years ago

Since the fix is trivial, it might be worth considering to cherry-pick this into Node master (which is now at 5.9). cc @targos @MylesBorins

mcollina commented 7 years ago

I'm +1 on cherry-picking this.

targos commented 7 years ago

I can do that

MylesBorins commented 7 years ago

@targos can we get this included in the V8 8.x backport?

targos commented 7 years ago

Or course. I will open a PR for master and include it in the backport next Monday.

milesj commented 7 years ago

Awesome, thanks everyone!