aws / aws-sam-cli

CLI tool to build, test, debug, and deploy Serverless applications using AWS SAM
https://aws.amazon.com/serverless/sam/
Apache License 2.0
6.48k stars 1.16k forks source link

sam-build is slow even with cached, skip pull image flags #3432

Open ayushchd opened 2 years ago

ayushchd commented 2 years ago

Description:

I am using sam-build to build a SAM application that has a lambda with package type as Image. Every time I execute sam-build (event with --cached --parallel --skip-pull-image) it seems to take a lot of time at a certain step. From verbose logs, it looks like there's some step that takes time after this line:

2021-11-01 17:09:46,846 | Setting DockerBuildArgs: {} for ReportsGeneratorFunction function

and then after about 3-4 minutes, I see this lines that quickly execute:

Step 1/20 : FROM public.ecr.aws/lambda/python:3.8
 ---> ca2592cfa705
Step 2/20 : ....
...
...

It seems to me that it's pulling the base image public.ecr.aws/lambda/python:3.8 on every build request.

Steps to reproduce:

Dockerfile:

FROM public.ecr.aws/lambda/python:3.8

COPY src/app_core ./app_core

ENV ENV_TYPE prod

# copy the dependencies file to the working directory
COPY src/app_core/lambda_requirements.txt .

# install dependencies
RUN python3.8 -m pip install -r lambda_requirements.txt -t .

# Command can be overwritten by providing a different command in the template directly.
CMD ["app_core.serverless.latest_reports_scheduler.lambda_handler"]

Observed result:

2021-11-01 17:09:46,468 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2021-11-01 17:09:46,468 | Using config file: samconfig.toml, config environment: default
2021-11-01 17:09:46,468 | Expand command line arguments to:
2021-11-01 17:09:46,468 | --template_file=/Users/ayusc/app/template.yaml --cached --parallel --skip_pull_image --build_dir=.aws-sam/build --cache_dir=.aws-sam/cache
2021-11-01 17:09:46,678 | 'build' command is called
2021-11-01 17:09:46,678 | Starting Build use cache
2021-11-01 17:09:46,696 | No Parameters detected in the template
2021-11-01 17:09:46,728 | 5 stacks found in the template
2021-11-01 17:09:46,728 | No Parameters detected in the template
2021-11-01 17:09:46,754 | 5 resources found in the stack
2021-11-01 17:09:46,754 | No Parameters detected in the template
2021-11-01 17:09:46,787 | Found Serverless function with name='LatestReportsSchedulerFunction' and ImageUri='None'
2021-11-01 17:09:46,787 | --base-dir is not presented, adjusting uri ./ relative to /Users/ayusc/app/template.yaml
2021-11-01 17:09:46,787 | --base-dir is not presented, adjusting uri . relative to /Users/ayusc/app/template.yaml
2021-11-01 17:09:46,787 | Found Serverless function with name='ReportsGeneratorFunction' and ImageUri='None'
2021-11-01 17:09:46,787 | --base-dir is not presented, adjusting uri ./ relative to /Users/ayusc/app/template.yaml
2021-11-01 17:09:46,787 | --base-dir is not presented, adjusting uri . relative to /Users/ayusc/app/template.yaml
2021-11-01 17:09:46,787 | No Parameters detected in the template
2021-11-01 17:09:46,826 | Instantiating build definitions
2021-11-01 17:09:46,831 | Unique function build definition found, adding as new (Function Build Definition: BuildDefinition(None, /Users/ayusc/app, Image, , fb41ba1e-8fbd-4a56-bf7b-b789a0818a67, {'Dockerfile': 'LambdaDockerfile', 'DockerContext': '/Users/ayusc/app', 'DockerTag': 'python3.8-v1-latest-reports-scheduler'}, {}, x86_64, []), Function: Function(name='LatestReportsSchedulerFunction', functionname='LatestReportsSchedulerFunction', runtime=None, memory=None, timeout=60, handler=None, imageuri=None, packagetype='Image', imageconfig={'Command': ['app_core.serverless.latest_reports_scheduler.lambda_handler']}, codeuri='/Users/ayusc/app', environment=None, rolearn=None, layers=[], events={'LatestReportSchedule': {'Type': 'Schedule', 'Properties': {'Schedule': 'rate(5 minutes)', 'Name': 'LatestReportSchedule', 'DeadLetterConfig': {'Arn': 'arn:aws:lambda:us-east-1:123456789012:function:LatestReportScheduleDLQ'}, 'RetryPolicy': {'MaximumRetryAttempts': 1}}}}, metadata={'Dockerfile': 'LambdaDockerfile', 'DockerContext': '/Users/ayusc/app', 'DockerTag': 'python3.8-v1-latest-reports-scheduler'}, inlinecode=None, codesign_config_arn=None, architectures=['x86_64'], stack_path=''))
2021-11-01 17:09:46,831 | Unique function build definition found, adding as new (Function Build Definition: BuildDefinition(None, /Users/ayusc/app, Image, , 60bb3d96-7a85-48c2-8568-68b476a77ca2, {'Dockerfile': 'LambdaDockerfile', 'DockerContext': '/Users/ayusc/app', 'DockerTag': 'python3.8-v1-reports-generator-'}, {}, x86_64, []), Function: Function(name='ReportsGeneratorFunction', functionname='ReportsGeneratorFunction', runtime=None, memory=None, timeout=60, handler=None, imageuri=None, packagetype='Image', imageconfig={'Command': ['app_core.serverless.reports_generator.lambda_handler']}, codeuri='/Users/ayusc/app', environment=None, rolearn=None, layers=[], events={'SQSEvent': {'Type': 'SQS', 'Properties': {'Queue': 'arn:aws:lambda:us-east-1:123456789012:function:ReportsGenerationEventsQueue', 'BatchSize': 10, 'Enabled': False}}}, metadata={'Dockerfile': 'LambdaDockerfile', 'DockerContext': '/Users/ayusc/app', 'DockerTag': 'python3.8-v1-reports-generator-'}, inlinecode=None, codesign_config_arn=None, architectures=['x86_64'], stack_path=''))
2021-11-01 17:09:46,833 | Async execution started
2021-11-01 17:09:46,833 | Invoking function functools.partial(<bound method CachedOrIncrementalBuildStrategyWrapper.build_single_function_definition of <samcli.lib.build.build_strategy.CachedOrIncrementalBuildStrategyWrapper object at 0x103a11a90>>, <samcli.lib.build.build_graph.FunctionBuildDefinition object at 0x103a11f10>)
2021-11-01 17:09:46,834 | Running incremental build for runtime None for build definition fb41ba1e-8fbd-4a56-bf7b-b789a0818a67
2021-11-01 17:09:46,834 | Invoking function functools.partial(<bound method CachedOrIncrementalBuildStrategyWrapper.build_single_function_definition of <samcli.lib.build.build_strategy.CachedOrIncrementalBuildStrategyWrapper object at 0x103a11a90>>, <samcli.lib.build.build_graph.FunctionBuildDefinition object at 0x103a11d30>)
2021-11-01 17:09:46,834 | Building codeuri: /Users/ayusc/app runtime: None metadata: {'Dockerfile': 'LambdaDockerfile', 'DockerContext': '/Users/ayusc/app', 'DockerTag': 'python3.8-v1-latest-reports-scheduler'} architecture: x86_64 functions: ['LatestReportsSchedulerFunction']
2021-11-01 17:09:46,834 | Running incremental build for runtime None for build definition 60bb3d96-7a85-48c2-8568-68b476a77ca2
2021-11-01 17:09:46,834 | Building to following folder /Users/ayusc/app/.aws-sam/build/LatestReportsSchedulerFunction
2021-11-01 17:09:46,834 | Waiting for async results
2021-11-01 17:09:46,835 | Building codeuri: /Users/ayusc/app runtime: None metadata: {'Dockerfile': 'LambdaDockerfile', 'DockerContext': '/Users/ayusc/app', 'DockerTag': 'python3.8-v1-reports-generator-'} architecture: x86_64 functions: ['ReportsGeneratorFunction']
2021-11-01 17:09:46,835 | Building image for LatestReportsSchedulerFunction function
2021-11-01 17:09:46,835 | Building to following folder /Users/ayusc/app/.aws-sam/build/ReportsGeneratorFunction
2021-11-01 17:09:46,835 | Building image for ReportsGeneratorFunction function
2021-11-01 17:09:46,846 | Setting DockerBuildArgs: {} for LatestReportsSchedulerFunction function
2021-11-01 17:09:46,846 | Setting DockerBuildArgs: {} for ReportsGeneratorFunction function
Step 1/20 : FROM public.ecr.aws/lambda/python:3.8
 ---> ca2592cfa705
Step 2/20 : COPY src/app_core ./app_core
 ---> Using cache
 ---> 20e8e259f013

...

The latency/delay is after Setting DockerBuildArgs: {} for ReportsGeneratorFunction function

Expected result:

It should reuse the previous image (if that's the reason for the delay)

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

  1. OS: MacOS
  2. sam --version: SAM CLI, version 1.34.1
  3. AWS region: eu-west-1

Add --debug flag to command you are running

CoshUS commented 2 years ago

If docker is pulling new images, the delay should come after Step 1/20 : FROM public.ecr.aws/lambda/python:3.8 is printed. This seems to be a docker issue as SAM CLI directly calls docker build after Setting DockerBuildArgs. What is your docker version? Can you try updating it to a newer version and/or factory reset the settings?

joyacv2 commented 2 years ago

Hi,

sam build or sam build --cached are extremely slow. No matter what I try it results in a very slow process.

Thank You very much!

ssenchenko commented 2 years ago

Have you looked into your docker version? Have you tried to update your docker or factory reset it?

It might be a local system issue.

janrito commented 2 years ago

I have the same issue on an M1 mac.

It's definitely not docker, I can build the image just fine using docker build.

On the other hand, i've tried:

sam build
sam build --parallel
sam build --parallel --skip-pull-image

And they are all extremely slow, it also momentarily blocks my machine as it consumes an inordinate amount of memory.

Every once in a while i also get this error,

unfold ```python Traceback (most recent call last): File "/opt/homebrew/bin/sam", line 8, in sys.exit(cli()) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/core.py", line 829, in __call__ return self.main(*args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/core.py", line 782, in main rv = self.invoke(ctx) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/core.py", line 1259, in invoke return _process_result(sub_ctx.command.invoke(sub_ctx)) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/core.py", line 1066, in invoke return ctx.invoke(self.callback, **ctx.params) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/core.py", line 610, in invoke return callback(*args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/decorators.py", line 73, in new_func return ctx.invoke(f, obj, *args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/click/core.py", line 610, in invoke return callback(*args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/telemetry/metric.py", line 166, in wrapped raise exception # pylint: disable=raising-bad-type File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/telemetry/metric.py", line 124, in wrapped return_value = func(*args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/utils/version_checker.py", line 41, in wrapped actual_result = func(*args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/cli/main.py", line 87, in wrapper return func(*args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/commands/build/command.py", line 182, in cli do_cli( File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/commands/build/command.py", line 262, in do_cli ctx.run() File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/commands/build/build_context.py", line 248, in run build_result = builder.build() File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/app_builder.py", line 221, in build return ApplicationBuildResult(build_graph, build_strategy.build()) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/build_strategy.py", line 358, in build return super().build() File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/build_strategy.py", line 79, in build result.update(self._build_functions(self._build_graph)) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/build_strategy.py", line 364, in _build_functions return self._run_builds_async( File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/build_strategy.py", line 380, in _run_builds_async async_results = async_context.run_async() File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/utils/async_utils.py", line 131, in run_async return run_given_tasks_async(self._async_tasks, event_loop) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/utils/async_utils.py", line 90, in run_given_tasks_async return event_loop.run_until_complete(_run_given_tasks_async(tasks, event_loop, executor)) File "/opt/homebrew/Cellar/python@3.8/3.8.13_1/Frameworks/Python.framework/Versions/3.8/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete return future.result() File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/utils/async_utils.py", line 58, in _run_given_tasks_async raise result File "/opt/homebrew/Cellar/python@3.8/3.8.13_1/Frameworks/Python.framework/Versions/3.8/lib/python3.8/concurrent/futures/thread.py", line 57, in run result = self.fn(*self.args, **self.kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/build_strategy.py", line 391, in build_single_function_definition return self._delegate_build_strategy.build_single_function_definition(build_definition) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/build_strategy.py", line 160, in build_single_function_definition result = self._build_function( File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/app_builder.py", line 611, in _build_function return self._build_lambda_image( File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/samcli/lib/build/app_builder.py", line 423, in _build_lambda_image build_logs = self._docker_client.api.build(**build_args) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/docker/api/build.py", line 263, in build response = self._post( File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/docker/utils/decorators.py", line 46, in inner return f(self, *args, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/docker/api/client.py", line 226, in _post return self.post(url, **self._set_request_timeout(kwargs)) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/requests/sessions.py", line 590, in post return self.request('POST', url, data=data, json=json, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/requests/sessions.py", line 542, in request resp = self.send(prep, **send_kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/requests/sessions.py", line 655, in send r = adapter.send(request, **kwargs) File "/opt/homebrew/Cellar/aws-sam-cli/1.53.0/libexec/lib/python3.8/site-packages/requests/adapters.py", line 498, in send raise ConnectionError(err, request=request) requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))```
kwaminaop commented 2 years ago

I'm also seeing this; a huge delay (4-5 minutes) after the DockerBuildArgs step before (as far as I can tell) it actually starts doing the docker build. Last couple of lines of log before the pause, and then first couple of lines of the actual docker build running below.

...
2022-08-07 23:44:08,229 | Building codeuri: /Users/kwamina/givedirectly/ubi/image_updater runtime: None metadata: {'Dockerfile': 'tools/Dockerfile', 'DockerContext': '/Users/kwamina/givedirectly', 'DockerTag': 'latest', 'DockerBuildArgs': {'IMAGE_BASE': 'public.ecr.aws/lambda/python:3.9', 'PROJECT_ROOT': 'ubi/image_updater', 'PROJECT_SOURCE': 'ubi/image_updater/image_updater', 'PROJECT_CMD': 'image_updater.lambda_function.lambda_handler'}} architecture: x86_64 functions: ImageUpdaterFunction
2022-08-07 23:44:08,229 | Building to following folder /Users/kwamina/givedirectly/ubi/image_updater/.aws-sam/build/ImageUpdaterFunction
2022-08-07 23:44:08,229 | Building image for ImageUpdaterFunction function
2022-08-07 23:44:08,234 | Setting DockerBuildArgs: {'IMAGE_BASE': 'public.ecr.aws/lambda/python:3.9', 'PROJECT_ROOT': 'ubi/image_updater', 'PROJECT_SOURCE': 'ubi/image_updater/image_updater', 'PROJECT_CMD': 'image_updater.lambda_function.lambda_handler'} for ImageUpdaterFunction function

[4-5 MINUTE PAUSE HERE]

Step 1/32 : ARG IMAGE_BASE=python:3.9-alpine
Step 2/32 : FROM alpine as collect_local_deps
 ---> d7d3d98c851f
Step 3/32 : ARG PROJECT_ROOT
 ---> Using cache
 ---> ac073187e354
Step 4/32 : RUN apk add --no-cache coreutils
 ---> Using cache
 ---> 9935386e8e0c
...
sriram-mv commented 1 year ago

This is interesting, I'm not able to reproduce this at this time. Do you see this happening for every build or for a certain image?

punithmailme commented 1 year ago

I am facing same issue on M1 system

torresxb1 commented 1 year ago

Hi, could anyone experiencing this issue provide us with a sample project and steps to reproduce?

rmaccrimm commented 1 year ago

I was having this issue as well, but I was able to resolve it just by adding a .dockerignore file. In my SAM template I had DockerContext set to the project root for every function, which contains a lot of unrelated files. Ignoring everything but the function source files dramatically sped things up

janrito commented 1 year ago

yes!

janrito commented 1 year ago

i'm using this alongside https://github.com/iterative/dvc

I have a cache of possibly gigabytes of data. There might be some rogue process going through these files

atishshahrouniyar commented 6 months ago

Any update in this issue?

ohbeep commented 5 months ago

I fixed this issue by following @rmaccrimm's solution. I added large folders such as "node_modules" and cache folders to the .dockerignore file, making the build much faster.

According to Docker's official document:

This helps avoid sending unwanted files and directories to the builder, improving build speed, especially when using a remote builder.