Skip to content
This repository has been archived by the owner on Oct 15, 2020. It is now read-only.

Much slower react-scripts-ts build in node-chakracore v10.0.0 #527

Open
kfarnung opened this issue Apr 30, 2018 · 13 comments
Open

Much slower react-scripts-ts build in node-chakracore v10.0.0 #527

kfarnung opened this issue Apr 30, 2018 · 13 comments

Comments

@kfarnung
Copy link
Contributor

kfarnung commented Apr 30, 2018

  • Version: 10.0.0
  • Platform: Ubuntu Linux 16.04
  • Subsystem:

Comparing the build times for react-scripts-ts build between node-chakracore v8.11.1 and v10.0.0 there's a huge difference in runtime.

node-chakracore v8.11.1

$ time npm run build

> puzzle-web@0.2.0 build /home/kfarnung/Git/GitHub/puzzle-web
> react-scripts-ts build

Creating an optimized production build...
Starting type checking and linting service...
Using 1 worker with 2048MB memory limit
Warning: Ignored engine flag: --max-old-space-size=2048
ts-loader: Using typescript@2.8.3 and /home/kfarnung/Git/GitHub/puzzle-web/tsconfig.json
Compiled successfully.

File sizes after gzip:

  98.5 KB   build/static/js/main.96142344.js
  22.05 KB  build/static/css/main.b0b2f18b.css
  8.19 KB   build/static/js/0.aaca5de8.chunk.js
  7.71 KB   build/static/js/2.5520f4a1.chunk.js
  7.25 KB   build/static/js/6.fb95d7c4.chunk.js
  6.95 KB   build/static/js/5.75ea5328.chunk.js
  6.95 KB   build/static/js/4.82aaf33a.chunk.js
  6.86 KB   build/static/js/1.7b5fda59.chunk.js
  6.82 KB   build/static/js/3.a72f793e.chunk.js
  1.11 KB   build/static/js/7.b5c7f374.chunk.js
  961 B     build/static/js/8.5cd26f46.chunk.js

The project was built assuming it is hosted at /puzzle/.
You can control this with the homepage field in your package.json.

The build folder is ready to be deployed.

Find out more about deployment here:

  http://bit.ly/2vY88Kr


real	1m45.986s
user	2m18.834s
sys	0m12.984s

node-chakracore v10.0.0

$ time npm run build

> puzzle-web@0.2.0 build /home/kfarnung/Git/GitHub/puzzle-web
> react-scripts-ts build

Creating an optimized production build...
Starting type checking and linting service...
Using 1 worker with 2048MB memory limit
Warning: Ignored engine flag: --max-old-space-size=2048
ts-loader: Using typescript@2.8.3 and /home/kfarnung/Git/GitHub/puzzle-web/tsconfig.json
Compiled successfully.

File sizes after gzip:

  98.5 KB   build/static/js/main.96142344.js
  22.05 KB  build/static/css/main.b0b2f18b.css
  8.19 KB   build/static/js/0.aaca5de8.chunk.js
  7.71 KB   build/static/js/2.5520f4a1.chunk.js
  7.25 KB   build/static/js/6.fb95d7c4.chunk.js
  6.95 KB   build/static/js/5.75ea5328.chunk.js
  6.95 KB   build/static/js/4.82aaf33a.chunk.js
  6.86 KB   build/static/js/1.7b5fda59.chunk.js
  6.82 KB   build/static/js/3.a72f793e.chunk.js
  1.11 KB   build/static/js/7.b5c7f374.chunk.js
  961 B     build/static/js/8.5cd26f46.chunk.js

The project was built assuming it is hosted at /puzzle/.
You can control this with the homepage field in your package.json.

The build folder is ready to be deployed.

Find out more about deployment here:

  http://bit.ly/2vY88Kr


real	6m1.563s
user	7m3.294s
sys	0m12.743s
@kfarnung kfarnung changed the title Much slowers react-scripts-ts build in node-chakracore v10.0.0 Much slower react-scripts-ts build in node-chakracore v10.0.0 May 1, 2018
@rhuanjl
Copy link
Contributor

rhuanjl commented May 4, 2018

I had a look at this on macOS (obtained puzzle-web from your GitHub repository to test) and didn't notice nearly as big a speed drop only about a 10% regression. Could there be something windows specific here?

Though whilst the regression was not as significant in both cases v8 node took less than half the time.

That said I'd thought I'd try and determine the source of the 10% regression.

Profiling showed that (on macOS at least) most of the time is spent within ChakraCore inside JavascriptArray::EveryHelper - the implementation of Array.prototype.every.

The 10% regression seemed to relate to this change: chakra-core/ChakraCore#4511

Reverting it gave a 5-10% improvement.

I tried implementing Array.prototype.every in javascript inside chakra_shim.js and this gave around a 10-20% improvement.

I then tried updating to latest master of chakracore - latest master combined with the JS implementation of Array.prototype.every resulted in a comparable speed to v8 node, still slower but 10-20% slower instead of double the length.

Note latest master without the JS implementation of array.prototype.every was not nearly as significant an improvement - I assume the large speedup I observed was due to the combination of the JS implementation of Array.prototype.every and this recent CC change: chakra-core/ChakraCore#5081

@kfarnung
Copy link
Contributor Author

kfarnung commented May 4, 2018

That's some interesting data, I hadn't actually measured the time on macOS, the numbers I've collected have been from Linux and Windows.

I actually see the biggest speed drop on Linux, the numbers in the original post were from a VM running Ubuntu 16.04 and the original source of this issue was actually some Travis-CI runs where the speed is consistently much slower:

https://travis-ci.org/kfarnung/puzztool/builds/374762013

Digging down into the individual legs it took npm run build 496.17 seconds to complete for node-chakracore 10.0.0, but only 144.48 seconds. These are obviously machines not controlled by me, but it's pretty consistent across builds. The Travis builds are only Ubuntu 14.04.

On Windows the drop isn't quite as pronounced (but the tests were all run on different hardware too, so that's likely a factor):

> Measure-Command { npm run build }
Warning: Ignored engine flag: --max-old-space-size=2048


Days              : 0
Hours             : 0
Minutes           : 1
Seconds           : 5
Milliseconds      : 646
Ticks             : 656466906
TotalDays         : 0.000759799659722222
TotalHours        : 0.0182351918333333
TotalMinutes      : 1.09411151
TotalSeconds      : 65.6466906
TotalMilliseconds : 65646.6906
> Measure-Command { npm run build }
Warning: Ignored engine flag: --max-old-space-size=2048


Days              : 0
Hours             : 0
Minutes           : 1
Seconds           : 38
Milliseconds      : 506
Ticks             : 985061608
TotalDays         : 0.00114011760185185
TotalHours        : 0.0273628224444444
TotalMinutes      : 1.64176934666667
TotalSeconds      : 98.5061608
TotalMilliseconds : 98506.1608

@rhuanjl
Copy link
Contributor

rhuanjl commented May 4, 2018

I don't have a linux machine to test on - considering that chakra's macOS and linux builds are very similar I'm very surprised about the difference though - only a 10% regression on my MacBook vs that 300% regression.

Not sure if I can do much more as it sounds like this needs profiling on linux specifically.

@kfarnung
Copy link
Contributor Author

kfarnung commented May 5, 2018

Well, that is interesting indeed. I added macOS to the CI script and the results are much more inline with what you're seeing:

https://travis-ci.org/kfarnung/puzztool/builds/375131975

92.89 vs 132.03 seconds

EDIT: Looks like the v8.11.1 leg failed with a native module incompatibility:

dyld: lazy symbol binding failed: Symbol not found: __ZN2v820EscapableHandleScopeC1EPNS_7IsolateE

  Referenced from: /Users/travis/build/kfarnung/puzztool/node_modules/fsevents/lib/binding/Release/node-v57-darwin-x64/fse.node

  Expected in: flat namespace


dyld: Symbol not found: __ZN2v820EscapableHandleScopeC1EPNS_7IsolateE

  Referenced from: /Users/travis/build/kfarnung/puzztool/node_modules/fsevents/lib/binding/Release/node-v57-darwin-x64/fse.node

  Expected in: flat namespace


Type checking and linting aborted - probably out of memory. Check `memoryLimit` option in ForkTsCheckerWebpackPlugin configuration.

EDIT2: But it looks like the build did pass, so it's probably a valid test.

@kfarnung
Copy link
Contributor Author

kfarnung commented May 5, 2018

Taking a perf trace on Linux _Unwind_Find_FDE pops out in both traces, but it's must more pronounced in v10.0.0.

node-chakracore v8.11.1

-   30.43%    29.96%  node     libgcc_s.so.1        [.] _Unwind_Find_FDE
   - 22.04% 0x7f7ccc2b0445
        _ZN2Js26JavascriptExternalFunction28StdCallExternalFunctionThunkEPNS_16RecyclableObjectENS_8CallInfoEz
        _ZN2Js28JavascriptExceptionOperators22RethrowExceptionObjectEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEb
        _ZN2Js28JavascriptExceptionOperators28ThrowExceptionObjectInternalEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEbbPvb
        _ZN2Js28JavascriptExceptionOperators7DoThrowEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextE
        __cxa_throw
      + _Unwind_RaiseException
   - 7.35% 0x7f7ccb62e449
        _ZN2Js26JavascriptExternalFunction28StdCallExternalFunctionThunkEPNS_16RecyclableObjectENS_8CallInfoEz
        _ZN2Js28JavascriptExceptionOperators22RethrowExceptionObjectEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEb
        _ZN2Js28JavascriptExceptionOperators28ThrowExceptionObjectInternalEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEbbPvb
        _ZN2Js28JavascriptExceptionOperators7DoThrowEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextE
        __cxa_throw
      + _Unwind_RaiseException

node-chakracore v10.0.0

-   55.24%    54.31%  node     libgcc_s.so.1        [.] _Unwind_Find_FDE
   - 34.24% 0x7f6c3ae1cf1c
        _ZN2Js19JavascriptOperators13PatchGetValueILb1ENS_11InlineCacheEEEPvPNS_12FunctionBodyEPT0_jS3_i
        _ZN2Js19JavascriptOperators20GetProperty_InternalILb0EEEiPvPNS_16RecyclableObjectEbiPS2_PNS_13ScriptContextEPNS_17PropertyValueInfoE
        _ZN2Js18JavascriptFunction16GetPropertyQueryEPviPS1_PNS_17PropertyValueInfoEPNS_13ScriptContextE
        _ZN2Js18JavascriptFunction19GetPropertyBuiltInsEPviPS1_PNS_13ScriptContextEPi
        _ZN2Js18JavascriptFunction17GetCallerPropertyEPvPS1_PNS_13ScriptContextE
        _ZN2Js15JavascriptError14ThrowTypeErrorEPNS_13ScriptContextEiPKDs
        _ZN2Js28JavascriptExceptionOperators5ThrowEPvPNS_13ScriptContextE
        _ZN2Js28JavascriptExceptionOperators20ThrowExceptionObjectEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEbPvb
        _ZN2Js28JavascriptExceptionOperators28ThrowExceptionObjectInternalEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEbbPvb
        _ZN2Js28JavascriptExceptionOperators7DoThrowEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextE
        __cxa_throw
      + _Unwind_RaiseException
   - 18.76% 0x7f6c4ce085a3
        _ZN13BailOutRecord7BailOutEPKS_
        _ZN13BailOutRecord13BailOutCommonEPN2Js25JavascriptCallStackLayoutEPKS_jPvN2IR11BailOutKindENS0_17ImplicitCallFlagsES5_PNS_18BailOutReturnValueES5_
      + _ZN13BailOutRecord13BailOutHelperEPN2Js25JavascriptCallStackLayoutEPPNS0_14ScriptFunctionERNS0_9ArgumentsEbPKS_jPvN2IR11BailOutKindEPSA_PNS_18BailOutReturnValueESD_SA_SA_
   - 0.93% _Unwind_Find_FDE
        0.63% __GI___dl_iterate_phdr
   - 0.65% 0x7f6c2ac63712
        _ZN2Js19JavascriptOperators13PatchGetValueILb1ENS_11InlineCacheEEEPvPNS_12FunctionBodyEPT0_jS3_i
        _ZN2Js19JavascriptOperators20GetProperty_InternalILb0EEEiPvPNS_16RecyclableObjectEbiPS2_PNS_13ScriptContextEPNS_17PropertyValueInfoE
        _ZN2Js18JavascriptFunction16GetPropertyQueryEPviPS1_PNS_17PropertyValueInfoEPNS_13ScriptContextE
        _ZN2Js18JavascriptFunction19GetPropertyBuiltInsEPviPS1_PNS_13ScriptContextEPi
        _ZN2Js18JavascriptFunction17GetCallerPropertyEPvPS1_PNS_13ScriptContextE
        _ZN2Js15JavascriptError14ThrowTypeErrorEPNS_13ScriptContextEiPKDs
        _ZN2Js28JavascriptExceptionOperators5ThrowEPvPNS_13ScriptContextE
        _ZN2Js28JavascriptExceptionOperators20ThrowExceptionObjectEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEbPvb
        _ZN2Js28JavascriptExceptionOperators28ThrowExceptionObjectInternalEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextEbbPvb
        _ZN2Js28JavascriptExceptionOperators7DoThrowEPNS_25JavascriptExceptionObjectEPNS_13ScriptContextE
        __cxa_throw
        _Unwind_RaiseException                                                                                                                                                                    

@MSLaguana
Copy link
Contributor

Perhaps node v10 is throwing more exceptions? You could try counting that using perf, although it's a huge pain to add a probe point to a c++/mangled function.

@rhuanjl
Copy link
Contributor

rhuanjl commented May 5, 2018

I tried profiling again with current node-chakracore, with CC master and with array.prototype.every overwritten with a JS implementation.

(Note total execution time at this point was significantly shorter than node-chakracore v8.11.1's time as in 60% as long or something like it - I assume a JS implementation of array.prototype.every is incoming for ChakraCore in light of the inlining work that's been done and the current PR for array.prototype.indexOf - so this benefit should be seen in a future release)

That aside with these steps, the profile trace was now dominated by Javascript Try operators, and a couple of ThrowException operators as well as a few bail out related calls.

@rhuanjl
Copy link
Contributor

rhuanjl commented May 10, 2018

After looking at the point identified above about array.prototype.every which is used so heavily in react-scripts-ts build I reviewed the benchmarks included in the chakracore repository and cannot find one that exercises array.prototype.every - should there be/is there an action around assessing the completeness of those benchmarks?

Unless already being worked on I could make a PR to add a JS implementation of array.prototype.every to CC but it won't effect cc's own benchmarks at all - it will affect this massively though.

@kfarnung
Copy link
Contributor Author

Sorry for the delay, I don't believe anyone is currently working on Array.prototype.every.

Ping @sigatrev to confirm.

@kfarnung
Copy link
Contributor Author

@rhuanjl I confirmed that there's nobody working on Array.prototype.every so you're welcome to make a PR for it.

@rhuanjl
Copy link
Contributor

rhuanjl commented May 30, 2018

Thanks - I'll have a look at it shortly, not sure I want to open any more CC PRs until a couple of my existing ones are done though.

@rhuanjl
Copy link
Contributor

rhuanjl commented Jun 3, 2018

Something else seems to have changed since I did the profiling above. I made a JS implementation of array.prototype.every for CC but using it with latest CC master it's not showing the performance improvement I had before at all. Additionally simply putting in a JS implementation into chakra_shim.js as I did before isn't showing the same speedup anymore either; I'll hold off on submitting anything and do some more profiling + see if I can work out what's changed.

@rhuanjl
Copy link
Contributor

rhuanjl commented Aug 8, 2018

Been looking at this more - using my implementation of Array.prototype.every (in this branch: https://github.com/rhuanjl/ChakraCore/tree/every ) performance now seems similar or slightly worse than with current CC master/CC 1.10.1.

When using that much of the time in the trace is in JavascriptFunction::GetCallerProperty - I'll look into why that could be slow.

It seems to be taking forever a) throwing type errors AND b) finding the caller of the function that threw them

Having a JS implemented every method seems to make this finding of the caller slower.

(I assume these type errors are all inside try/catch blocks as the build completes successfully) Could anything have made the handling of finding the caller when an error is thrown slower?

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants