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

[ayushchd]

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]

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]

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]

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]

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

Traceback (most recent call last):
  File "/opt/homebrew/bin/sam", line 8, in <module>
    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/[email protected]/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/[email protected]/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'))```

</details>

[kwaminaop]

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]

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]

I am facing same issue on M1 system

[torresxb1]

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

[rmaccrimm]

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]

yes!

[janrito]

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]

Any update in this issue?

[ohbeep]

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.