Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

(aws-lambda-nodejs): slowdown at esbuild bundling #23930

Open
dambaron opened this issue Jan 31, 2023 · 10 comments
Open

(aws-lambda-nodejs): slowdown at esbuild bundling #23930

dambaron opened this issue Jan 31, 2023 · 10 comments
Labels
@aws-cdk/aws-lambda-nodejs bug This issue is a bug. needs-reproduction This issue needs reproduction. p1

Comments

@dambaron
Copy link

dambaron commented Jan 31, 2023

Describe the bug

When bumping aws-cdk from 2.55.1 to 2.56.1 my team witnessed a significant slowdown during the esbuild bundling. The bundling increased more than 3x. This behavior has been observed all the way up to 2.62.2.

Expected Behavior

Bundling time should remain consistent between versions (or decrease).

Current Behavior

Bundling time has been multiplied by 3 only by bumping the aws-cdk version in the package.json.

Reproduction Steps

  1. Synthesize or deploy a stack with a NodeJs Lambda inside using aws-cdk 2.51.1.
  2. Run the same command using version 2.61.1.
    3.Examine synthesis time

In my case:

  • with 2.55.1: 12.02s
  • with 2.56.1: 65.07s
⇒  yarn cdk deploy -e oxp-dbn-api-engagement-lambda-stack --hotswap -c env=feature/dbn --profile voila-dbn
yarn run v1.22.19
warning ../../../../package.json: No license field
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/cdk deploy -e oxp-dbn-api-engagement-lambda-stack --hotswap -c env=feature/dbn --profile voila-dbn
Bundling asset oxp-dbn-api-engagement-lambda-stack/HandleInteractionsFunction/Code/Stage...
warning ../../../../package.json: No license field
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/esbuild --bundle /Users/dbaron/Projects/voila/backend/oxp-api/engagement/src/interaction/InteractionHandler.ts --target=node18 --platform=node --outfile=/Users/dbaron/Projects/voila/backend/oxp-api/cdk.out/bundling-temp-6cdfe7655c7745338ff0bb31f7835257d757245287d91c0efb5b492bd62c1856/index.js --main-fields=module,main

  cdk.out/bundling-temp-6cdfe7655c7745338ff0bb31f7835257d757245287d91c0efb5b492bd62c1856/index.js  925.3kb

Bundling asset oxp-dbn-api-engagement-lambda-stack/IncrementEngagementsFunction/Code/Stage...
warning ../../../../package.json: No license field
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/esbuild --bundle /Users/dbaron/Projects/voila/backend/oxp-api/engagement/src/engagement/EngagementHandler.ts --target=node18 --platform=node --outfile=/Users/dbaron/Projects/voila/backend/oxp-api/cdk.out/bundling-temp-4ff2215903da0442bafd5ffef7e2ce9ab0ecec693dc945c995cac9c68c14d5a1/index.js --main-fields=module,main

  cdk.out/bundling-temp-4ff2215903da0442bafd5ffef7e2ce9ab0ecec693dc945c995cac9c68c14d5a1/index.js  996.8kb


✨  Synthesis time: 12.02s

⚠️ The --hotswap flag deliberately introduces CloudFormation drift to speed up deployments
⚠️ It should only be used for development - never use it for your production Stacks!
oxp-dbn-api-engagement-lambda-stack: building assets...

[0%] start: Building e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1
[0%] start: Building 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[0%] start: Building 37ff6dd2ed7f1b891b07bbeb015fa702e812e566d6ac4c1012e01ea7108534b6:847792134458-eu-west-1
[33%] success: Built e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1
[66%] success: Built 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[100%] success: Built 37ff6dd2ed7f1b891b07bbeb015fa702e812e566d6ac4c1012e01ea7108534b6:847792134458-eu-west-1

oxp-dbn-api-engagement-lambda-stack: assets built

oxp-dbn-api-engagement-lambda-stack: deploying... [1/1]
[0%] start: Publishing e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1
[0%] start: Publishing 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[0%] start: Publishing 37ff6dd2ed7f1b891b07bbeb015fa702e812e566d6ac4c1012e01ea7108534b6:847792134458-eu-west-1
[33%] success: Published 37ff6dd2ed7f1b891b07bbeb015fa702e812e566d6ac4c1012e01ea7108534b6:847792134458-eu-west-1
[66%] success: Published 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[100%] success: Published e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1

✨ hotswapping resources:

 ✅  oxp-dbn-api-engagement-lambda-stack (no changes)

✨  Deployment time: 2.85s

Stack ARN:
arn:aws:cloudformation:eu-west-1:847792134458:stack/oxp-dbn-api-engagement-lambda-stack/749981b0-5c5b-11ed-9e0c-065028ef3283

✨  Total time: 14.87s


✨  Done in 17.89s.
⇒  yarn cdk deploy -e oxp-dbn-api-engagement-lambda-stack --hotswap -c env=feature/dbn --profile voila-dbn     
yarn run v1.22.19
warning ../../../../package.json: No license field
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/cdk deploy -e oxp-dbn-api-engagement-lambda-stack --hotswap -c env=feature/dbn --profile voila-dbn
Bundling asset oxp-dbn-api-engagement-lambda-stack/HandleInteractionsFunction/Code/Stage...
warning ../../../../package.json: No license field
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/esbuild --bundle /Users/dbaron/Projects/voila/backend/oxp-api/engagement/src/interaction/InteractionHandler.ts --target=node18 --platform=node --outfile=/Users/dbaron/Projects/voila/backend/oxp-api/cdk.out/bundling-temp-6cdfe7655c7745338ff0bb31f7835257d757245287d91c0efb5b492bd62c1856/index.js --main-fields=module,main

  cdk.out/bundling-temp-6cdfe7655c7745338ff0bb31f7835257d757245287d91c0efb5b492bd62c1856/index.js  925.3kb

Bundling asset oxp-dbn-api-engagement-lambda-stack/IncrementEngagementsFunction/Code/Stage...
warning ../../../../package.json: No license field
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/esbuild --bundle /Users/dbaron/Projects/voila/backend/oxp-api/engagement/src/engagement/EngagementHandler.ts --target=node18 --platform=node --outfile=/Users/dbaron/Projects/voila/backend/oxp-api/cdk.out/bundling-temp-4ff2215903da0442bafd5ffef7e2ce9ab0ecec693dc945c995cac9c68c14d5a1/index.js --main-fields=module,main

  cdk.out/bundling-temp-4ff2215903da0442bafd5ffef7e2ce9ab0ecec693dc945c995cac9c68c14d5a1/index.js  996.8kb


✨  Synthesis time: 65.07s

⚠️ The --hotswap flag deliberately introduces CloudFormation drift to speed up deployments
⚠️ It should only be used for development - never use it for your production Stacks!
oxp-dbn-api-engagement-lambda-stack: building assets...

[0%] start: Building e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1
[0%] start: Building 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[0%] start: Building 68fe847471a77709d0a00b5aafdd8145b81d3e2938cf1e5ef3b0da39104bce12:847792134458-eu-west-1
[33%] success: Built e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1
[66%] success: Built 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[100%] success: Built 68fe847471a77709d0a00b5aafdd8145b81d3e2938cf1e5ef3b0da39104bce12:847792134458-eu-west-1

oxp-dbn-api-engagement-lambda-stack: assets built

oxp-dbn-api-engagement-lambda-stack: deploying... [1/1]
[0%] start: Publishing e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1
[0%] start: Publishing 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[0%] start: Publishing 68fe847471a77709d0a00b5aafdd8145b81d3e2938cf1e5ef3b0da39104bce12:847792134458-eu-west-1
[33%] success: Published 6e10e4a4bc74c85636bd782fb3e232c3a52c995fdbc93aaec84eaf735cd567d1:847792134458-eu-west-1
[66%] success: Published 68fe847471a77709d0a00b5aafdd8145b81d3e2938cf1e5ef3b0da39104bce12:847792134458-eu-west-1
[100%] success: Published e6a701a7a05b614ef610bbd67208e1a35a883bb46fec5571df82fbc48b570a47:847792134458-eu-west-1

✨ hotswapping resources:

 ✅  oxp-dbn-api-engagement-lambda-stack (no changes)

✨  Deployment time: 3.52s

Stack ARN:
arn:aws:cloudformation:eu-west-1:847792134458:stack/oxp-dbn-api-engagement-lambda-stack/749981b0-5c5b-11ed-9e0c-065028ef3283

✨  Total time: 68.59s


✨  Done in 72.11s.

Possible Solution

No response

Additional Information/Context

package.json

{
  "name": "oxp-api",
  "version": "0.1.0",
  "license": "UNLICENSED",
  "private": true,
  "bin": {
    "rest-api": "bin/rest-api.js"
  },
  "scripts": {
    "build": "tsc",
    "watch": "tsc -w",
    "main": "ts-node",
    "clean": "rm -rf cdk.out",
    "test": "jest --maxWorkers=50% --silent",
    "test:clean": "jest --clearCache",
    "test:next": "jest --maxWorkers=50% --silent -c ./jest.config.next.ts --cacheDirectory \".jestcache\"",
    "test:diff": "jest -o --maxWorkers=50% --silent",
    "test:ci:next": "jest --runInBand --silent --no-cache -c ./jest.config.next.ts",
    "test:ci": "jest --maxWorkers=10% --silent --cacheDirectory \".jestcache\"",
    "test:coverage": "jest --ci --coverage",
    "test:report": "jest --ci --reporters=default --reporters=jest-junit",
    "lint": "eslint .",
    "prettify": "prettier --write --ignore-path .gitignore \"{**/*,*}.{ts,json,yaml,yml}\"",
    "cdk:diff": "cdk diff \"*\"",
    "cdk:deploy": "cdk deploy \"*\" --concurrency 10 --require-approval never",
    "cdk:synth": "cdk synth \"*\""
  },
  "engines": {
    "node": "^18",
    "yarn": "^1.22"
  },
  "lint-staged": {
    "*.ts": "eslint"
  },
  "devDependencies": {
    "@aws-sdk/credential-provider-ini": "3.229.0",
    "@commitlint/cli": "17.4.2",
    "@commitlint/config-conventional": "17.4.2",
    "@jest/types": "29.4.0",
    "@types/jest": "29.4.0",
    "@types/lodash.clonedeep": "4.5.6",
    "@types/lodash.merge": "4.6.6",
    "@types/node": "18.11.18",
    "@types/nodemailer": "6.4.4",
    "@types/uuid": "8.3.4",
    "@types/ws": "8.2.2",
    "@typescript-eslint/eslint-plugin": "5.49.0",
    "@typescript-eslint/parser": "5.49.0",
    "aws-cdk": "2.55",
    "aws-cdk-lib": "2.56.1",
    "aws-sdk-client-mock": "2.0.1",
    "aws-sdk-client-mock-jest": "2.0.1",
    "chalk": "4.1.2",
    "constructs": "10.1.235",
    "esbuild": "0.17.5",
    "eslint": "8.32.0",
    "eslint-config-prettier": "8.6.0",
    "eslint-plugin-prettier": "4.2.1",
    "eslint-plugin-simple-import-sort": "9.0.0",
    "husky": "8.0.3",
    "jest": "29.4.0",
    "jest-diff": "29.4.0",
    "jest-each": "29.4.0",
    "jest-extended": "3.2.3",
    "jest-junit": "15.0.0",
    "lint-staged": "13.1.0",
    "prettier": "2.8.3",
    "ts-jest": "29.0.5",
    "ts-node": "10.9.1",
    "typescript": "4.9.4",
    "yargs": "17.3.1"
  },
  "dependencies": {
    "@aws-sdk/client-cloudfront": "3.229.0",
    "@aws-sdk/client-cloudwatch-logs": "3.229.0",
    "@aws-sdk/client-dynamodb": "3.229.0",
    "@aws-sdk/client-ec2": "3.229.0",
    "@aws-sdk/client-eventbridge": "3.229.0",
    "@aws-sdk/client-ivs": "3.229.0",
    "@aws-sdk/client-lambda": "3.229.0",
    "@aws-sdk/client-resource-groups-tagging-api": "3.229.0",
    "@aws-sdk/client-s3": "3.229.0",
    "@aws-sdk/client-secrets-manager": "3.229.0",
    "@aws-sdk/client-ses": "3.229.0",
    "@aws-sdk/client-sqs": "3.229.0",
    "@aws-sdk/client-ssm": "3.229.0",
    "@aws-sdk/client-translate": "3.229.0",
    "@aws-sdk/lib-dynamodb": "3.229.0",
    "@aws-sdk/s3-request-presigner": "3.229.0",
    "@aws-sdk/util-dynamodb": "3.229.0",
    "@slack/web-api": "^6.7.2",
    "@types/aws-lambda": "8.10.109",
    "ably": "1.2.14",
    "axios": "0.23.0",
    "csv-parse": "4.16.3",
    "date-fns": "2.28.0",
    "date-fns-tz": "1.3.4",
    "exceljs": "4.3.0",
    "fp-ts": "2.11.5",
    "googleapis": "100.0.0",
    "ics": "2.37.0",
    "joi": "17.4.2",
    "jose": "4.11.0",
    "jwt-decode": "3.1.2",
    "ksuid": "3.0.0",
    "lodash": "4.17.21",
    "nanoid": "3.3.4",
    "node-cache": "5.1.2",
    "node-saml": "4.0.0-beta.2",
    "nodemailer": "6.7.7",
    "source-map-support": "0.5.20",
    "urlcat": "2.0.4",
    "uuid": "9.0.0",
    "ws": "8.4.2",
    "yarn": "^1.22.19",
    "zlib": "1.0.5"
  }
}

CDK CLI Version

2.56.1

Framework Version

No response

Node.js Version

v18.12.1

OS

Mac OS 13

Language

Typescript

Language Version

4.9.4

Other information

No response

@dambaron dambaron added bug This issue is a bug. needs-triage This issue or PR still needs to be triaged. labels Jan 31, 2023
@peterwoodworth
Copy link
Contributor

I'm not noticing any difference @dambaron, the time seems to remain about the same for me. Could you post reproduction info like your nodejsfunction definition, as well as the actual handler file? Thanks

@peterwoodworth peterwoodworth added p1 response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 7 days. needs-reproduction This issue needs reproduction. and removed needs-triage This issue or PR still needs to be triaged. p1 labels Feb 1, 2023
@dambaron
Copy link
Author

dambaron commented Feb 1, 2023

Hi @peterwoodworth, I won't be able to post the handler itself but the definition goes like this

const nodejsFunction = new NodejsFunction(scope, `${lambdaReference.name}Function`, {
       depsLockFilePath: join(__dirname, '../yarn.lock'),
       runtime: Runtime.NODEJS_18_X,
       tracing: Tracing.ACTIVE,
      timeout: Duration.seconds(10),
      memorySize: 256,
      bundling: {
        minify: false,
        esbuildArgs: {
          '--main-fields': 'module,main',
        },
        externalModules: []
      },
      // truncated
    })

I must add that what we are experiencing happends during a hotswap with a command like:

yarn run cdk deploy -e my-stack --hotswap --profile my-sso-profile

I'm also attaching to CPU profiles I made for the same command using v2.51.1 then v2.63.0

What I see is that the bundling seems to work fine but then a very long idle time happens.

cdk-2.51.1.cpuprofile.txt
cdk-2.63.0.cpuprofile.txt

@github-actions github-actions bot removed the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 7 days. label Feb 1, 2023
@peterwoodworth
Copy link
Contributor

thanks for the additional info,

I'm also curious if you notice anything during the idle time you mention if you use the -v option, could you try this?

@dambaron
Copy link
Author

dambaron commented Feb 2, 2023

thanks for the additional info,

I'm also curious if you notice anything during the idle time you mention if you use the -v option, could you try this?

Here you are, I cranked the logs all the way up but the outputs are quite similar.
cdk.deploy.hotswap.v2.63.0.log
cdk.deploy.hotswap.v2.55.1.log

@dambaron
Copy link
Author

@peterwoodworth any news after I provided you the logs ?

@dambaron
Copy link
Author

dambaron commented Mar 1, 2023

@peterwoodworth uping this thread once again

@peterwoodworth
Copy link
Contributor

Thanks for sharing your logs, and sorry for the delay here @dambaron

Looking at the logs, it doesn't seem to show anything helpful. I'm curious, at this point in the logs:

BLOCK A

Bundling asset oxp-dbn-api-engagement-lambda-stack/HandleInteractionsFunction/Code/Stage...
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/esbuild --bundle /Users/dbaron/Projects/voila/backend/oxp-api/engagement/src/interaction/InteractionHandler.ts --target=node18 --platform=node --outfile=/Users/dbaron/Projects/voila/backend/oxp-api/cdk.out/bundling-temp-6cdfe7655c7745338ff0bb31f7835257d757245287d91c0efb5b492bd62c1856/index.js --main-fields=module,main

  ...c7745338ff0bb31f7835257d757245287d91c0efb5b492bd62c1856/index.js  925.3kb

BLOCK B

Bundling asset oxp-dbn-api-engagement-lambda-stack/IncrementEngagementsFunction/Code/Stage...
$ /Users/dbaron/Projects/voila/backend/oxp-api/node_modules/.bin/esbuild --bundle /Users/dbaron/Projects/voila/backend/oxp-api/engagement/src/engagement/EngagementHandler.ts --target=node18 --platform=node --outfile=/Users/dbaron/Projects/voila/backend/oxp-api/cdk.out/bundling-temp-4ff2215903da0442bafd5ffef7e2ce9ab0ecec693dc945c995cac9c68c14d5a1/index.js --main-fields=module,main

  ...3da0442bafd5ffef7e2ce9ab0ecec693dc945c995cac9c68c14d5a1/index.js  996.8kb

BLOCK C

✨  Synthesis time: 65.75s

does the "very long idle time" you describe occur in Block A, B, or C? Based on everything I'd guess C, is this right?

@peterwoodworth peterwoodworth added p1 response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 7 days. labels Mar 13, 2023
@dambaron
Copy link
Author

dambaron commented Mar 15, 2023

Exact @peterwoodworth , the slowdown occurs in block C. I've been able to retrieve the esbuild commands and run them outside the deploy phase and duration is the same inside or outside cdk. What I'm experiencing is awfully close to this (#19021)

@github-actions github-actions bot removed the response-requested Waiting on additional info and feedback. Will move to "closing-soon" in 7 days. label Mar 15, 2023
@peterwoodworth
Copy link
Contributor

If it's similar, could you check CloudTrail to see if a bunch of duplicate calls are going off?

@dambaron
Copy link
Author

@peterwoodworth CloudTrail was not enabled but through an http proxy I was able to determine that I have the same number of requests with roughly the same execution times.

The only thing I see now is that a significant amount of time is spent here in the selectStacksForDeploy function.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
@aws-cdk/aws-lambda-nodejs bug This issue is a bug. needs-reproduction This issue needs reproduction. p1
Projects
None yet
Development

No branches or pull requests

2 participants