Node very slow since update from 16.17.1 to 16.18.0 #45202

JoranLive · 2022-10-27T08:46:52Z

Version

16.18.0

Platform

Ununtu server 22.0.4 arm64 (packer + plugin arm)

Subsystem

No response

What steps will reproduce the bug?

I have a cicd that build a Raspberry Pi 4 image (with packer and solo.io packer arm plugin) that embbed a node applications.

My build was taking approximatively 1h but grows to 4h after update of node from 16.17.1 to 16.18.0.

Time for "npm install" is 3 times longer than with the previous version.

I use npm version 8.

How often does it reproduce? Is there a required condition?

Always

What is the expected behavior?

No response

What do you see instead?

npm install and build is 4 times longer with node 16.18.0 than with node 16.17.1.

Additional information

No response

mscdex · 2022-10-27T12:32:03Z

There is no node v16.17.3.

Trott · 2022-10-27T12:44:03Z

Using Node.js 16.8.0, what is your build time with npm 7.x?

JoranLive · 2022-10-27T14:20:12Z

There is no node v16.17.3.

Sorry, it was 16.17.1. Changed in description.

JoranLive · 2022-10-27T14:28:07Z

arm-image: Node version: v14.20.1
arm-image: NPM version: 6.14.17

=> 85 minutes

arm-image: Node version: v16.17.1
arm-image: NPM version: 8.15.0

==> 80 minutes

arm-image: Node version: v16.18.0
arm-image: NPM version: 7.24.2

==> 247 minutes

arm-image: Node version: v16.18.0
arm-image: NPM version: 8.19.2

==> 229 minutes

Note that build time can depends on other factor (tasks, network and runner) so difference is not revelant when less than 15 minutes.
However, migration to node 16 has increase a lot the time and I tried it many times: build with node 14.x.x or 16.17.1 is always lower than 90 minutes but always upper to 220 minutes with node 16.18.0.

mscdex · 2022-10-27T17:49:57Z

What about v18.x?

Trott · 2022-10-27T18:25:47Z

arm-image: Node version: v16.17.1
arm-image: NPM version: 8.15.0

==> 80 minutes

arm-image: Node version: v16.18.0
arm-image: NPM version: 7.24.2

==> 247 minutes

arm-image: Node version: v16.18.0
arm-image: NPM version: 8.19.2

==> 229 minutes

OK, so that would seem to eliminate npm as the issue and put the focus on node and your dependencies.

Are you able to share the contents of your package.json?

JoranLive · 2022-10-27T18:27:15Z

What about v18.x?

I launched a build with node 18.12.0. I will keep you updated.

JoranLive · 2022-10-27T18:32:16Z

arm-image: Node version: v16.17.1
arm-image: NPM version: 8.15.0
==> 80 minutes
arm-image: Node version: v16.18.0
arm-image: NPM version: 7.24.2
==> 247 minutes
arm-image: Node version: v16.18.0
arm-image: NPM version: 8.19.2
==> 229 minutes
OK, so that would seem to eliminate npm as the issue and put the focus on node and your dependencies.

Are you able to share the contents of your package.json?

I have 4 applications built in my image: 2 backends (tsoa + node) an 2 front applications (ionic + angular).
'npm install' is slower for all of them.

But, this is one of "package.json":

{
  "name": "sre-c-scan",
  "version": "0.0.0",
  "description": "SRE C Scan",
  "main": "dist/app.ts",
  "scripts": {
    "start": "npm run tsoa && npm install && ts-node ./src/app/app.ts",
    "start:server": "npm run tsoa && npm install && ts-node ./src/app/app.ts server",
    "start:cs": "npm run tsoa && npm install && ts-node ./src/app/app.ts cs",
    "start:test": "npm run tsoa && ts-node ./src/app/app.ts",
    "build": "rm -rf ./dist/ && npm run tsoa && tsc --project tsconfig.app.json && cp .env ./dist/",
    "test": "npm run tsoa && jasmine-ts --config=jasmine.json",
    "test:coverage": "npm run tsoa && nyc npm test --reporter=html",
    "tsoa": "tsoa spec-and-routes",
    "seed:run": "ts-node ./node_modules/typeorm-seeding/dist/cli.js seed",
    "migration:run": "ts-node ./node_modules/typeorm/cli.js migration:run",
    "migration:revert": "ts-node ./node_modules/typeorm/cli.js migration:revert"
  },
  "repository": {
    "type": "git",
    "url": "git@git.vall.com:digital-at-vall/Wind/aws.sre-c-scan.git"
  },
  "author": "",
  "license": "ISC",
  "dependencies": {
    "axios": "^0.27.2",
    "body-parser": "^1.20.0",
    "chokidar": "^3.5.3",
    "cors": "^2.8.5",
    "date-fns": "^2.29.1",
    "dotenv": "^16.0.1",
    "envfile": "^6.18.0",
    "express": "^4.18.1",
    "http-status-codes": "^2.2.0",
    "inversify": "^6.0.1",
    "inversify-binding-decorators": "^4.0.0",
    "jimp": "^0.16.1",
    "lodash": "^4.17.21",
    "mock-fs": "^5.1.4",
    "multer": "^1.4.5-lts.1",
    "node-fetch": "^2.6.7",
    "query-string": "^7.1.1",
    "reflect-metadata": "^0.1.13",
    "sqlite3": "^5.0.10",
    "tsoa": "^4.1.0",
    "typeorm": "^0.2.7",
    "typeorm-seeding": "^1.6.1",
    "xml2js": "^0.4.23"
  },
  "devDependencies": {
    "@types/body-parser": "^1.19.2",
    "@types/cors": "^2.8.12",
    "@types/express": "^4.17.13",
    "@types/jasmine": "^3.10.6",
    "@types/node": "^17.0.27",
    "@types/node-fetch": "^2.6.1",
    "@types/xml2js": "^0.4.11",
    "@typescript-eslint/eslint-plugin": "^5.27.1",
    "@typescript-eslint/parser": "^5.27.1",
    "cortexdecoder_web": "file:src/packages/cortexdecoder_web-1.14.0.tgz",
    "jasmine": "^3.99.0",
    "jasmine-reporters": "^2.5.0",
    "jasmine-spec-reporter": "^7.0.0",
    "jasmine-ts": "^0.3.0",
    "nyc": "^15.1.0",
    "swagger-ui-express": "^4.1.4",
    "ts-node": "^8.10.2",
    "tslib": "^2.4.0",
    "tslint": "^6.1.3",
    "typescript": "~4.7.3"
  },
  "nyc": {
    "sourceMap": true,
    "reporter": [
      "lcov",
      "text",
      "text-summary"
    ],
    "extension": [
      ".ts",
      ".tsx"
    ],
    "include": [
      "src/**"
    ],
    "exclude": [
      "src/**/*.spec.**",
      "src/**/*.e2e-spec.**"
    ],
    "cache": false,
    "all": true
  }
}

Trott · 2022-10-27T18:49:31Z

Is it at all possible the issue is caching? Is it possible only the first build takes that long after you update? Are all these builds on fresh operating system/device installations and so everything is an empty cache?

JoranLive · 2022-10-27T18:56:01Z

Good track but all builds starts with an empty cache...

JoranLive · 2022-10-27T19:03:24Z

All build is done in packer with solo.io arm plugin.
Base image is https://cdimage.ubuntu.com/releases/22.04/release/ubuntu-22.04.1-preinstalled-server-arm64+raspi.img.xz
First operation is apt-get update & apt-get upgrade.
So, its a fresh operating system

JoranLive · 2022-10-28T07:12:30Z

Build with node 18 take time too.

arm-image: Node version: v18.12.0
arm-image: NPM version: 8.19.2

Build has failed because my application is not yet compatible but it occurs after 175 minutes and other steps were expected to finish the job.

Trott · 2022-10-28T17:27:39Z

Are we troubleshooting npm install here or npm run build? I'd be astonished if any npm install took 80 minutes. But you specifically say that npm install takes three times longer now. Is that "it took 3 seconds but now takes 9 seconds" or is it more "it took 10 minutes and now takes 30 minutes" or what?

JoranLive · 2022-10-28T22:25:26Z

Are we troubleshooting npm install here or npm run build?
Both.

80 minutes is the build time for all (it includes 'npm install', 'node build' and others (os update & setup).

I noticed that 'npm install' takes 15 minutes instead of 5 minutes. But node build is also taking more time.

Is it possible that node does not detect properly the architecture and do not use prebuilt binaries?

Trott · 2022-10-28T22:57:41Z

Is it possible that node does not detect properly the architecture and do not use prebuilt binaries?

@nodejs/releasers @nodejs/build Any ideas as to what might be going on here or how to best troubleshoot?

jbergstroem · 2022-10-28T23:17:09Z

It would be helpful to see where time is spent! As suggested in the thread; removing network as a factor would provide relevant insight. What does for instance time npm install tell you about how the cpu usage is? Are you in a position where you can use a cache for all packages to skip network waiting times?

bnoordhuis · 2022-11-29T17:44:38Z

No followup, closing.

JoranLive · 2022-12-12T09:24:43Z

Hello @Trott @jbergstroem @bnoordhuis ,

Sorry for my lately reply but I think we should reopen this issue.

I can give you the step to reproduce it.

Create a json file, packer-template.json with this:

{
    "variables": {
        "image_template_dir": "node-perf-issue-packer-template.json",
        "node_version": "16.17.1"
    },
    "builders": [
        {
            "type": "arm-image",
            "image_type": "raspberrypi",
            "qemu_binary": "qemu-aarch64-static",
            "iso_url": "https://cdimage.ubuntu.com/releases/22.04/release/ubuntu-22.04.2-preinstalled-server-arm64+raspi.img.xz",
            "iso_checksum": "sha256:22705473ab9c1ca19012fe2d42f917218b823d1a815dabb8a240681c51d143a5",
            "target_image_size": "8000000000",
            "output_filename": "output-arm-image/node_perf_issue.img"
        }
    ],
    "provisioners": [
        {
            "type": "shell",
            "inline": [
                "export DEBIAN_FRONTEND=noninteractive",
                "echo '*** OS UPDATE ***'",
                "echo",
                "rm /etc/resolv.conf && echo \"nameserver 8.8.8.8\n\" > /etc/resolv.conf",
                "apt-get update",
                "#apt-get -y upgrade",
                "echo",
                "echo 'OS update done'"
            ]
        },
        {
            "type": "shell",
            "inline": [
                "export DEBIAN_FRONTEND=noninteractive",
                "echo '*** NODE INSTALLATION ***'",
                "echo",
                "echo 'Installing build tools requirements..'",
                "apt-get install -y build-essential python-is-python3",
                "echo",
                "echo 'Installing node & npm...'",
                "NODE_VERSION={{user `node_version`}}",
                "curl -L https://raw.githubusercontent.com/tj/n/master/bin/n | bash -s -- lts",
                "npm install -g n",
                "n ${NODE_VERSION}",
                "echo \"Node version: $(node --version)\"",
                "echo \"NPM version: $(npm --version)\"",
                "echo",
                "echo 'Installing typescript and tsnode...'",
                "npm install -g typescript && npm install -g ts-node",
                "echo",
                "echo 'Running environment installation done'"
            ]
        },
        {
            "type": "shell",
            "inline": [
                "export DEBIAN_FRONTEND=noninteractive",
                "echo '*** BUILDING APPLICATION ***'",
                "echo",
                "echo 'The following command is longer with node 16.18.x that with node 16.17.1...'",
                "time npm install --loglevel silly --global http-server",
                "echo"
            ]
        }
    ]
}

It's a packer template that build a Linux server image for Raspberry built.

Then run the build with:

time docker run --rm --privileged -v /dev:/dev -v ${PWD}:/build:ro -v ${PWD}/packer_cache:/build/packer_cache -v ${PWD}/output-arm-image:/build/output-arm-image -e PACKER_CACHE_DIR=/build/packer_cache packer-builder-arm build packer-template.json

What is interresting is that the last step: "npm install --global http-server".

It takes arround 15s with my running environment (pc, network, ...) but takes arround 1 minute if I switch from Node 16.17.1 to Node 16.18.1 (in variables section).

All my tests gave the same results, whatever the test environment configuration.

I have a full project ready where we have "npm install" and "npm build" and both operation are significally longer (x3).

bnoordhuis · 2022-12-12T10:47:02Z

If it's specifically npm that's slow, then the prime suspect is the upgrade from npm 8.15.1 to 8.19.2. npm is an external dependency so issues with it should be reported to them.

Are you also seeing slowdowns with node itself? I mean after npm has done its thing and your app is up and running?

JoranLive · 2022-12-12T11:09:23Z

Thanks for your reply.

I will try to fix the npm version when I will be at the office.

For the second point (performance at running time) I have to do a test because I didnt take care.

I keep you updated.

Thanks again

JoranLive · 2022-12-16T17:31:55Z

Hello @bnoordhuis @Trott @jbergstroem ,

Definitly, it doesn't seem to be related to npm.

With the packer tempate shared just above, I used the --preserve option of "n" to fix the npm-cli version.

With node 16.17.1 => npm install http-server takes arround 20s
With node 16.18.1, whatever the npm cli version (8.15.0 or 8.19.2), => npm install http-server takes arround 1 minute

I enabled verbosity.
I didn't find any error or differences but as you can see in the attached files, all operations are slower with node 16.18.1...

node_16_18_1_with_npm_8_15_0.txt
node_16_17_1_with_npm_8_15_0.txt
node_16_17_1_with_npm_8_19_2.txt

You can look at it with meld or any other comparaison tool.

Thanks again for your support !

bnoordhuis · 2022-12-16T21:34:54Z

But that's all while npm is running, right? My question was whether you're still seeing slowdowns afterwards, when npm is gone and your app is running.

JoranLive · 2022-12-18T20:38:29Z

Hi @bnoordhuis
Whatever the result about performance with running application, the fact that npm install and npm build is slower is an issue for me.
My build time was 80 minutes and is 240 minutes now. It's not acceptable for me.

bnoordhuis · 2022-12-18T21:10:07Z

I can see from your logs that npm downloads the same number of dependencies in all three cases but that for some reason it takes almost 4x as long with v16.18.1. I can't see why though.

If you can profile it somehow, maybe we can identify the cause.

JoranLive · 2022-12-18T21:49:32Z

Yes, it is what I noticed too.
I will try to enable the silly log level but I dont really know how to profile.
Please @bnoordhuis , could you reopen this ticket as it seems to be related to node and as it is reproducible?

JoranLive · 2022-12-19T08:51:23Z

@bnoordhuis @Trott @jbergstroem

With silly loglevel I didnt found anything more.

But what is strange is that the time increase for all operation (not especially http fetch).

As an example, this is the first logs with node 16.17.1:

arm-image: The following command is longer with node 16.18.x that with node 16.17.1...
==> arm-image: npm verb cli /usr/local/bin/node /usr/local/bin/npm
==> arm-image: npm info using npm@8.15.0
==> arm-image: npm info using node@v16.17.1
==> arm-image: npm timing npm:load:whichnode Completed in 5ms
==> arm-image: npm timing config:load:defaults Completed in 28ms
==> arm-image: npm timing config:load:file:/usr/local/lib/node_modules/npm/npmrc Completed in 16ms
==> arm-image: npm timing config:load:builtin Completed in 22ms

Against those for node 16.18.1 (same with 16.18.0):

arm-image: The following command is longer with node 16.18.x that with node 16.17.1...
==> arm-image: npm verb cli /usr/local/bin/node /usr/local/bin/npm
==> arm-image: npm info using npm@8.19.2
==> arm-image: npm info using node@v16.18.1
==> arm-image: npm timing npm:load:whichnode Completed in 29ms
==> arm-image: npm timing config:load:defaults Completed in 599ms
==> arm-image: npm timing config:load:file:/usr/local/lib/node_modules/npm/npmrc Completed in 102ms
==> arm-image: npm timing config:load:builtin Completed in 150ms

Please, could you reopen the issue ? However I will have to create a new one and we will loose history...

bnoordhuis · 2022-12-19T13:08:33Z

Please, could you reopen the issue ?

Done, but as expectation management: don't expect anyone but yourself to investigate. There haven't been more reports like yours so it's likely something unique to your setup.

bnoordhuis · 2023-08-03T20:12:57Z

There have been no other reports like this one and v16.x is end-of-life soon so I'll go ahead and close this.

jdfm · 2023-09-18T17:11:56Z

@JoranLive I'm wondering if the following issues may be relevant to you:

#45662
#44186
#48822

I know the versions being mentioned here may be outside of the versions you were using and on different architectures, but, it seems other people are seeing performance regressions when comparing to v14.

VoltrexKeyva changed the title ~~Node very slow since update from 16.17.3 to 16.18.0~~ Node very slow since update from 16.17.1 to 16.18.0 Oct 27, 2022

bnoordhuis closed this as not planned Won't fix, can't repro, duplicate, stale Nov 29, 2022

targos reopened this Dec 19, 2022

bnoordhuis closed this as not planned Won't fix, can't repro, duplicate, stale Aug 3, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Node very slow since update from 16.17.1 to 16.18.0 #45202

Node very slow since update from 16.17.1 to 16.18.0 #45202

JoranLive commented Oct 27, 2022 •

edited

Loading

mscdex commented Oct 27, 2022

Trott commented Oct 27, 2022 •

edited

Loading

JoranLive commented Oct 27, 2022

JoranLive commented Oct 27, 2022 •

edited

Loading

mscdex commented Oct 27, 2022

Trott commented Oct 27, 2022

JoranLive commented Oct 27, 2022

JoranLive commented Oct 27, 2022 •

edited by Trott

Loading

Trott commented Oct 27, 2022

JoranLive commented Oct 27, 2022 •

edited

Loading

JoranLive commented Oct 27, 2022

JoranLive commented Oct 28, 2022

Trott commented Oct 28, 2022

JoranLive commented Oct 28, 2022 •

edited

Loading

Trott commented Oct 28, 2022

jbergstroem commented Oct 28, 2022

bnoordhuis commented Nov 29, 2022

JoranLive commented Dec 12, 2022 •

edited by Trott

Loading

bnoordhuis commented Dec 12, 2022

JoranLive commented Dec 12, 2022

JoranLive commented Dec 16, 2022 •

edited

Loading

bnoordhuis commented Dec 16, 2022

JoranLive commented Dec 18, 2022

bnoordhuis commented Dec 18, 2022

JoranLive commented Dec 18, 2022 •

edited

Loading

JoranLive commented Dec 19, 2022 •

edited

Loading

bnoordhuis commented Dec 19, 2022

bnoordhuis commented Aug 3, 2023

jdfm commented Sep 18, 2023

Node very slow since update from 16.17.1 to 16.18.0 #45202

Node very slow since update from 16.17.1 to 16.18.0 #45202

Comments

JoranLive commented Oct 27, 2022 • edited Loading

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior?

What do you see instead?

Additional information

mscdex commented Oct 27, 2022

Trott commented Oct 27, 2022 • edited Loading

JoranLive commented Oct 27, 2022

JoranLive commented Oct 27, 2022 • edited Loading

mscdex commented Oct 27, 2022

Trott commented Oct 27, 2022

JoranLive commented Oct 27, 2022

JoranLive commented Oct 27, 2022 • edited by Trott Loading

Trott commented Oct 27, 2022

JoranLive commented Oct 27, 2022 • edited Loading

JoranLive commented Oct 27, 2022

JoranLive commented Oct 28, 2022

Trott commented Oct 28, 2022

JoranLive commented Oct 28, 2022 • edited Loading

Trott commented Oct 28, 2022

jbergstroem commented Oct 28, 2022

bnoordhuis commented Nov 29, 2022

JoranLive commented Dec 12, 2022 • edited by Trott Loading

bnoordhuis commented Dec 12, 2022

JoranLive commented Dec 12, 2022

JoranLive commented Dec 16, 2022 • edited Loading

bnoordhuis commented Dec 16, 2022

JoranLive commented Dec 18, 2022

bnoordhuis commented Dec 18, 2022

JoranLive commented Dec 18, 2022 • edited Loading

JoranLive commented Dec 19, 2022 • edited Loading

bnoordhuis commented Dec 19, 2022

bnoordhuis commented Aug 3, 2023

jdfm commented Sep 18, 2023

JoranLive commented Oct 27, 2022 •

edited

Loading

Trott commented Oct 27, 2022 •

edited

Loading

JoranLive commented Oct 27, 2022 •

edited

Loading

JoranLive commented Oct 27, 2022 •

edited by Trott

Loading

JoranLive commented Oct 27, 2022 •

edited

Loading

JoranLive commented Oct 28, 2022 •

edited

Loading

JoranLive commented Dec 12, 2022 •

edited by Trott

Loading

JoranLive commented Dec 16, 2022 •

edited

Loading

JoranLive commented Dec 18, 2022 •

edited

Loading

JoranLive commented Dec 19, 2022 •

edited

Loading