aws / aws-cdk

The AWS Cloud Development Kit is a framework for defining cloud infrastructure in code
https://aws.amazon.com/cdk
Apache License 2.0
11.38k stars 3.79k forks source link

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

Open dambaron opened 1 year ago

dambaron commented 1 year ago

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:

⇒  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

peterwoodworth commented 1 year ago

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

dambaron commented 1 year ago

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

peterwoodworth commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

@peterwoodworth any news after I provided you the logs ?

dambaron commented 1 year ago

@peterwoodworth uping this thread once again

peterwoodworth commented 1 year ago

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?

dambaron commented 1 year ago

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 (https://github.com/aws/aws-cdk/issues/19021)

peterwoodworth commented 1 year ago

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

dambaron commented 1 year ago

@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.