Bug: Sam Local invoke has deliberate delay of 1s

[andyfase]

Description:

I typically use SAM Local within a mocked integration test framework passing in a number of events using pytest. I mock dependencies using DynamoDB local or Moto so that a full test suite can be run - typically this involves 40-50 test invokes of different events. The entire environment is run within a number of docker containers within a docker network - with SAM, DDB Local and Moto all sitting in containers connected over a docker network.

Running this on a linux environment (or seemingly any x86 environment) this will typically take ~2 seconds to run, with each invoke being measured in < 50ms. I can see this when run within Codebuild for example.

However when run locally on my M1 Mac, the tests takes over 1 second each to run, making it non optimal for local development.

SAM version

~/.../arch/src/web-api> sam --version
SAM CLI, version 1.100.0

Run using

sam local start-lambda --docker-network lambda-local -t build/template.yaml --warm-containers EAGER --debug

Debug logs show

2023-10-31 08:43:37,119 | Found one Lambda function with name 'app'
2023-10-31 08:43:37,122 | Invoking index.handler (python3.10)
2023-10-31 08:43:37,124 | Resolving code path. Cwd=/path/to/arch/src/web-api/build,
CodeUri=/path/to/arch/src/web-api/build/app
2023-10-31 08:43:37,125 | Resolved absolute path to code is /path/to/arch/src/web-api/build/app
2023-10-31 08:43:37,147 | Reuse the created warm container for Lambda function 'app'
2023-10-31 08:43:37,164 | Lambda function 'app' is already running
2023-10-31 08:43:37,167 | Starting a timer for 90 seconds for function 'app'
START RequestId: a30c1bb5-375c-45a7-b4e7-d5a4bc0347e4 Version: $LATEST
END RequestId: a30c1bb5-375c-45a7-b4e7-d5a4bc0347e4
REPORT RequestId: a30c1bb5-375c-45a7-b4e7-d5a4bc0347e4	Duration: 24.22 ms	Billed Duration: 25 ms	Memory Size: 128 MB	Max Memory Used: 128 MB

2023-10-31 08:43:38 127.0.0.1 - - [31/Oct/2023 08:43:38] "POST /2015-03-31/functions/app/invocations HTTP/1.1" 200 -

The event comes in "08:43:37,119", function invoked at "08:43:37,167" - which seemingly runs for 24.22ms. However the HTTP response to "functions/app/invocations" seems to occur almost 900ms after the lambda completes. If I add debug logging to my function and log when the response is given back out of the handler I can confirm the delay from the exit of the handler until the time of the HTTP payload is sent back from "functions/app/invocations"

Steps to reproduce:

As mentioned run "sam local start-lambda" on a M1 mac and notice the delay in a invoke coming in and the response being sent back on the HTTP response out of the SAM framework.

Observed result:

See above

Expected result:

The time for a given invoke to be a maximum of + 50ms above the actual time for the lambda code to complete.

Paste the output of sam --info here

~/.../arch/src/api> sam --info
{
  "version": "1.100.0",
  "system": {
    "python": "3.8.13",
    "os": "macOS-13.5.2-arm64-arm-64bit"
  },
  "additional_dependencies": {
    "docker_engine": "dev",
    "aws_cdk": "2.72.0 (build 397e46c)",
    "terraform": "1.5.5"
  },
  "available_beta_feature_env_vars": [
    "SAM_CLI_BETA_FEATURES",
    "SAM_CLI_BETA_BUILD_PERFORMANCE",
    "SAM_CLI_BETA_TERRAFORM_SUPPORT",
    "SAM_CLI_BETA_RUST_CARGO_LAMBDA"
  ]
}

[moelasmar]

Thanks @andyfase for raising this issue.
I assume your lambda functions configured to run on x86_64 architecture, and I believe the reason of this issue is the docker containers are running on different architecture. Can you try to change the functions architecture to arm64, and see if this enhance the performance some how or not (I just want to confirm my understanding, and not suggesting this as a solution).

[andyfase]

@moelasmar thanks for responding. I actually tried both x86_64 and arm64 based lambda functions (which would run the different arch SAM container) and it made no difference.

Actually I now don't believe this is a arm vs x86 issue. Perhaps I didn't see this before on codebuild as the packaged version in codebuild is older? Anyway I believe I tracked this down to a deliberate 1 second sleep in the code which was introduced approx ~4 months ago.

I've tested re-building locally commenting out this line and the impact on my test suite is dramatic, see log snippets below but I go from a test suite taking ~50 seconds down to one taking ~3 seconds. The sleep seemingly was added to ensure the payload of the lambda is outputted to stdout last - however this seems like crazy overkill when a simple additional stdout.flush() would guarantee that?

I'll attempt to change the title of the BUG to reflect the actual issue.

Output of testing:

using sam from pip

 sam local start-lambda --docker-network lambda-local -t build/template.yaml --warm-containers EAGER

Results in

--------------------------------------- generated xml file: /path/to/pytest_report.xml ----------------------------------------
============================================================================= 36 passed in 49.91s =============================================================================
~/.../arch/src/web-api>

using locally built sam with the 1 second sleep commented out

samdev local start-lambda --docker-network lambda-local -t build/template.yaml --warm-containers EAGER

--------------------------------------- generated xml file: /path/to/pytest_report.xml ----------------------------------------
============================================================================= 36 passed in 3.21s ==============================================================================

[moelasmar]

thanks @andyfase for the deep investigation. sorry for my misunderstanding, I thought that your problem related to difference between executing in linux X86 environment, and Mac Arm.

I will check your suggested solution, and run our integration test cases to make sure that it will not break our logic.

[10bo]

Is there any update on this?

[andyfase]

+1 any update on removing this deliberate delay?

[sidhujus]

I've opened a pr #6418 that should address this issue, once it is merged it should be out in the next release

[github-actions]

Patch is released in v1.105.0. Closing