[BUG] Big performance issues and possible memory leak

[archfz]

Current Behavior:

Running npm 7 in docker image has some serious performance issues. Running same npm 7 locally doesn't have this on the other hand. I was thinking about posting this in the docker repository, but I am still unsure of the culprit and how it is related to the problem. I have found that reify:createSparse is the task that slows down dramatically, which as I saw is creating directories. So I suspect this issue might be related to docker volumes. On the other hand using npm@6 there is no such issue in docker.

Now when running same stuff on node:12-buster we also get the following out of heap error: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory. This doesn't happen on node 14 and 16. (* actually just happend so I might be wrong here)

Originally I have found this issue using an ubuntu 16 docker image, but these other images also fail in the same manner.

Expected Behavior:

No performance issues in docker (vs local). No out of heap errors.

Steps To Reproduce:

Test package.json

{
  "name": "test",
  "version": "1.0.0",
  "main": "index.tsx",
  "scripts": {
  },
  "license": "ISC",
  "devDependencies": {
    "@cypress/code-coverage": "^3.9.5",
    "@cypress/webpack-preprocessor": "^4.1.5",
    "@storybook/addon-actions": "^6.1.11",
    "@storybook/addon-essentials": "^6.1.11",
    "@storybook/addon-knobs": "^6.1.11",
    "@storybook/addon-links": "^6.1.11",
    "@storybook/react": "^6.1.11",
    "apollo": "^2.32.5",
    "axios-mock-adapter": "^1.19.0",
    "babel-preset-react-app": "^10.0.0",
    "chai-in-viewport": "^1.0.3",
    "copy-webpack-plugin": "6.2.1",
    "cypress": "^7.2.0",
    "cypress-terminal-report": "^3.1.0",
    "fork-ts-checker-webpack-plugin": "4.0.3",
    "http-serve": "^1.0.1",
    "spa-http-server": "^0.9.0",
    "storybook-addon-designs": "^5.4.3",
    "storybook-addon-intl": "^2.4.1",
    "storybook-react-router": "^1.0.8"
  },
  "dependencies": {
    "@apollo/client": "^3.3.15",
    "@babel/core": "7.10.4",
    "@babel/plugin-syntax-dynamic-import": "7.8.3",
    "@babel/preset-env": "7.10.4",
    "@babel/preset-react": "7.10.4",
    "@babel/register": "^7.10.4",
    "@brokerloop/ttlcache": "^3.2.1",
    "@hot-loader/react-dom": "^16.12.0",
    "@material-ui/core": "5.0.0-alpha.10",
    "@material-ui/icons": "^4.9.1",
    "@material-ui/lab": "4.0.0-alpha.45",
    "@reduxjs/toolkit": "^1.5.0",
    "@types/axios": "^0.14.0",
    "@types/chai": "^4.2.8",
    "@types/chai-as-promised": "^7.1.2",
    "@types/mocha": "^7.0.1",
    "@types/node": "12.0.2",
    "@types/react": "^16.8.23",
    "@types/react-dom": "^16.0.11",
    "@types/react-redux": "^7.1.1",
    "@types/react-router": "^5.1.4",
    "@types/react-router-dom": "^5.1.3",
    "@types/react-slick": "^0.23.4",
    "@types/react-stickynode": "^2.1.0",
    "@types/redux-mock-store": "^1.0.2",
    "@types/sinon": "^7.5.1",
    "@types/storybook-react-router": "^1.0.1",
    "@types/throttle-debounce": "^2.1.0",
    "@types/url-join": "^4.0.0",
    "@types/uuid": "^8.3.0",
    "@types/yup": "^0.26.33",
    "@xstate/react": "^0.8.1",
    "autoprefixer": "^9.7.5",
    "axios": "0.18.1",
    "babel-loader": "8.0.6",
    "chai": "^4.2.0",
    "chai-as-promised": "^7.1.1",
    "clean-webpack-plugin": "^3.0.0",
    "clone-deep": "^4.0.1",
    "clsx": "^1.1.1",
    "css-hot-loader": "^1.4.4",
    "css-loader": "3.4.2",
    "currency-symbol-map": "^4.0.4",
    "deep-equal": "^2.0.2",
    "deepmerge": "^4.2.2",
    "dotenv": "8.2.0",
    "dotenv-webpack": "1.7.0",
    "envsub": "^4.0.7",
    "fast-deep-equal": "^3.1.3",
    "file-loader": "^5.0.2",
    "formik": "^2.1.4",
    "graphql": "^15.5.0",
    "html-webpack-harddisk-plugin": "^1.0.2",
    "html-webpack-plugin": "^4.3.0",
    "istanbul-instrumenter-loader": "^3.0.1",
    "istanbul-lib-coverage": "^3.0.0",
    "js-cookie": "^2.2.1",
    "jsdom": "16.1.0",
    "jsdom-global": "3.0.2",
    "jsonschema": "^1.2.5",
    "jss-increase-specificity": "^0.3.5",
    "material-ui-image": "^3.2.3",
    "md5-file": "^4.0.0",
    "mini-css-extract-plugin": "^0.9.0",
    "mocha": "^7.0.1",
    "nyc": "^15.0.0",
    "postcss-loader": "3.0.0",
    "prettier": "^1.18.2",
    "query-string": "^6.11.0",
    "react": "16.12.0",
    "react-dom": "16.12.0",
    "react-hot-loader": "^4.12.19",
    "react-intl": "^3.12.0",
    "react-router": "^5.1.2",
    "react-router-dom": "^5.1.2",
    "react-scrollbars-custom": "^4.0.25",
    "react-slick": "^0.27.11",
    "react-stickynode": "^2.1.1",
    "react-universal-component": "^4.0.1",
    "redux-mock-store": "^1.5.4",
    "remove": "^0.1.5",
    "sass-loader": "8.0.2",
    "sinon": "^8.1.1",
    "slick-carousel": "^1.8.1",
    "thread-loader": "^3.0.3",
    "throttle-debounce": "^3.0.1",
    "tinycolor2": "^1.4.1",
    "tinyurl": "^1.1.7",
    "ts-loader": "6.2.1",
    "ts-node": "^8.6.2",
    "tslint": "^5.12.1",
    "tslint-config-prettier": "^1.17.0",
    "tslint-config-standard": "^9.0.0",
    "tslint-no-focused-test": "^0.5.0",
    "tslint-react": "^4.0.0",
    "typescript": "3.7.5",
    "url-join": "^4.0.1",
    "uuid": "^8.3.1",
    "webpack": "4.46.0",
    "webpack-cli": "3.3.10",
    "webpack-dev-server": "3.10.3",
    "webpack-license-plugin": "^4.1.1",
    "webpack-livereload-plugin": "^2.2.0",
    "webpack-merge": "4.2.2",
    "xstate": "^4.7.8",
    "yup": "^0.28.3"
  },
  "engines": {
    "node": ">=12"
  }
}

Example 1.

1. Do a local npm i to create the package lock in the directory where you created the above package.json.
2. Run rm node_modules/ -rf
3. Run docker run --rm -it -v $PWD:/app -w /app node:16-buster npm i --legacy-peer-deps --verbose in the directory where you created the above package.json
4. Notice how long the reify:createSparse
5. Same behaviour is with node:14-buster

Example 2:

1. Do a local npm i to create the package lock in the directory where you created the above package.json.
2. Run rm node_modules/ -rf
3. Run docker run --rm -it -v $PWD:/app -w /app node:12-buster bash -c "npm i -g npm@7 && npm i --legacy-peer-deps --verbose"
4. Notice the out of heap error.

Environment:

• Host OS: Ubuntu 20.04 Kernel: 5.11.10-051110-generic
• Docker: 20.10.6
• Node: 16.x, 14.x, 12.x
• npm: 7.x
• System RAM: 32GB, CPU i7-10850H

[undoo]

It is not replicated on:

Mint 20.1 5.4.0-66-generic
Docker: 19.03.8
npm: 6.14.4
node: 10.19.0

[archfz]

A more detailed error log:

npm timing npm:load:configScope Completed in 0ms
npm timing npm:load:projectScope Completed in 0ms
npm timing npm:load Completed in 11ms
npm timing config:load:flatten Completed in 2ms
npm timing arborist:ctor Completed in 0ms
npm timing idealTree:init Completed in 1022ms
npm timing idealTree:userRequests Completed in 0ms
npm timing idealTree:#root Completed in 0ms
npm timing idealTree:buildDeps Completed in 1ms
npm timing idealTree:fixDepFlags Completed in 1ms
npm timing idealTree Completed in 1052ms
npm timing reify:loadTrees Completed in 1053ms
npm timing reify:diffTrees Completed in 41ms
npm timing reify:retireShallow Completed in 0ms
[         .........] / idealTree: timing reify:retireShallow Completed in 0ms
<--- Last few GCs --->

[1:0x4def0f0]    92372 ms: Mark-sweep 3973.7 (4136.6) -> 3964.6 (4139.4) MB, 5029.8 / 10.5 ms  (average mu = 0.162, current mu = 0.007) allocation failure scavenge might not succeed
[1:0x4def0f0]    97260 ms: Mark-sweep 3981.3 (4139.6) -> 3972.0 (4144.1) MB, 4844.3 / 11.4 ms  (average mu = 0.089, current mu = 0.009) allocation failure scavenge might not succeed


<--- JS stacktrace --->

FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
 1: 0xb12b40 node::Abort() [npm i]
 2: 0xa2fe25 node::FatalError(char const*, char const*) [npm i]
 3: 0xcf946e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [npm i]
 4: 0xcf97e7 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [npm i]
 5: 0xee3875  [npm i]
 6: 0xef25f1 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [npm i]
 7: 0xef584c v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [npm i]
 8: 0xec1dfb v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationType, v8::internal::AllocationOrigin) [npm i]
 9: 0x122adbb v8::internal::Runtime_AllocateInYoungGeneration(int, unsigned long*, v8::internal::Isolate*) [npm i]
10: 0x160c599  [npm i]

[archfz]

Still reproduces on following specs (docker downgraded):

• Host OS: Ubuntu 20.04 Kernel: 5.11.10-051110-generic
• Docker: 19.03.15, build 99e3ed8919

[archfz]

Still reproduces on following specs (docker and kernel downgraded):

• Host OS: Ubuntu 20.04 Kernel: 5.4.117-0504117-generic
• Docker: 19.03.15, build 99e3ed8919

Close match to @undoo host specs.

[benelori]

Can confirm this issue on
Ubuntu 20.04
Linux 5.4.0-72-generic x86_64
Docker 20.10.1

I do not get the heap limit allocation error, but it does hang on
[ .........] / idealTree: timing reify:retireShallow Completed in 0ms
for at least a couple of minutes.
And it happens on all 3 Docker image versions described by OP

[archfz]

Apparently the out of heap doesn't reproduce anymore.
But the process still hangs for a very long time on reify:createSparse on any image. For this specific case on my system it's a whopping 180000ms. Also the process uses even up to 5gb ram. Locally still work fast.

Docker version 20.10.7, build f0df350
Npm: 7.18.1

[archfz]

Happened again on previously mentioned newer version, but the Ubuntu 16 docker image.

<--- Last few GCs --->

[1:0x4129fa0]   123169 ms: Mark-sweep 2009.5 (2083.5) -> 2005.9 (2088.7) MB, 1366.4 / 8.3 ms  (average mu = 0.068, current mu = 0.019) allocation failure scavenge might not succeed
[1:0x4129fa0]   124546 ms: Mark-sweep 2010.2 (2088.7) -> 2008.1 (2095.2) MB, 1366.8 / 7.8 ms  (average mu = 0.038, current mu = 0.008) allocation failure GC in old space requested


<--- JS stacktrace --->

==== JS stack trace =========================================

    0: ExitFrame [pc: 0x140de99]
Security context: 0x17e2685408d1 <JSObject>
    1: /* anonymous */(aka /* anonymous */) [0x1c377207c309] [/usr/lib/node_modules/npm/node_modules/chownr/chownr.js:~123] [pc=0xd6d95ce922a](this=0x00d8c5d804b1 <undefined>,0x1c3772070739 <Dirent map = 0x5770c416059>)
    2: forEach [0x17e268556769](this=0x1c37720674e9 <JSArray[1514]>,0x1c377207c309 <JSFunction (sfi = 0x257cbac52951)>)
    3: /* anonymous */ [0...

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0xa1a640 node::Abort() [npm i]
 2: 0xa1aa4c node::OnFatalError(char const*, char const*) [npm i]
 3: 0xb9a68e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [npm i]
 4: 0xb9aa09 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [npm i]
 5: 0xd57c85  [npm i]
 6: 0xd58316 v8::internal::Heap::RecomputeLimits(v8::internal::GarbageCollector) [npm i]
 7: 0xd64bd5 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [npm i]
 8: 0xd65a85 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [npm i]
 9: 0xd6853c v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [npm i]
10: 0xd2ef5b v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationType, v8::internal::AllocationOrigin) [npm i]
11: 0x10716ec v8::internal::Runtime_AllocateInOldGeneration(int, unsigned long*, v8::internal::Isolate*) [npm i]
12: 0x140de99  [npm i]

[darcyclarke]

Action: try to replicate

[sonallux]

@darcyclarke I am also experiencing a very slow npm install in a Docker container with NPM 7. I have reproduced the performance issue on multiple machines (Ubuntu 20.04 server and Windows using Docker Desktop with WSL2) and also on GitHub actions. Check out my https://github.com/sonallux/npm7-performance-issue repository and specifically, this workflow run https://github.com/sonallux/npm7-performance-issue/actions/runs/966881282 with different run configurations.

These are the different timings from the above workflow run:
| | Docker node:14 | Docker node:16 | Local Node 14 | Local Node 16 |
| -------------------------------- | -----------------| -----------------| -----------------| -----------------|
| npm@7 install | 187s | 193s | 68s | 56s |
| npm@6 install | 70s | 64s | 54s | 51s |

Edit: I have recorded new timings with the npm@7.24.0 version, see #3208 (comment)

From the times it is clearly visible that an npm@7 install on Docker takes significantly (more than 2x) longer than locally. An npm@6 install on Docker does not have this performance issue.

Using the alpine docker image does lead to the same results and using the --legacy-peer-deps flag does only very slightly (~10-20s) improve the timings.

[archfz]

@sonallux good summary.

For us this is a dealbreaker. As news were promising us better performance with npm7, we wanted to update immediately, but we have pipelines, most projects have pipelines, and it is there where performance matters the most.