Why are requests so slow? #134

ztolley · 2017-09-21T21:19:24Z

I installed the package globally

Created a simple template and js file to say hello, copied from samples

Started with sam local start-api

After the first start which downloads the docker images I can fire a request to the server from a browser or command line.

Immediately says invoking index.handler

waits 10 seconds then Then START, END and REPORT.

Whats the gap between Invoke and START, and what can you do to bring that down? Every request that follows the first has the same delay.

The text was updated successfully, but these errors were encountered:

sanathkr · 2017-09-22T03:30:20Z

Are you using a Java Jar for the code? It unzips the jar on every invoke which might be the problem. We need to implement caching of the unzipped folder to make it faster.

ztolley · 2017-09-22T07:48:38Z

No, js a hello world js

exports.handler = (event, context, callback) => {
  console.log('Handler start')

  callback(null, {
      statusCode: 200,
      body: 'Hello world.'
  })
}

sanathkr · 2017-09-23T15:03:40Z

What OS are you on? And what version of Docker?

From what I observed most of the startup latency is in spinning up Docker itself. We need a better mechanism to cache and reuse containers so you don't take this penalty.

ztolley · 2017-09-23T19:43:36Z

Ubuntu 17.04 and current release version of docker. Does it start a new container for each request?

PaulMaddox · 2017-09-25T09:27:03Z

Hi @ztolley,

We do create a new container for each invocation - we deliberately chose to not re-use containers for simplicity in the implementation.

An overhead of 10 seconds is not normal though.
This should take < 1 second on most machines. For example, a full end-to-end request/response for a NodeJS function on my machine (through sam local start-api takes 0.9 seconds.

$ time curl localhost:3000
hello
curl localhost:3000  0.00s user 0.00s system 0% cpu **0.970** total

If you change the Timeout property on your Lambda function in your SAM template, does it change how long you're waiting for a response?

jugglingcats · 2017-10-02T17:41:02Z

@PaulMaddox I have the same issue as @ztolley. If anything mine is worse...

$ time curl localhost:3000
real    0m20.640s
user    0m0.000s
sys     0m0.004s

Similar delay on each invocation. I notice that during most of this time docker ps shows nothing, so perhaps there is some issue caching the docker container (just a guess)?

I'm also using a simple node lambda function. It runs fine after the delay.

I'm running Ubuntu 16.04.3 LTS in a VirtualBox VM on Windows.

$ sudo docker version
Client:
 Version:      17.09.0-ce
 API version:  1.32
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:42:18 2017
 OS/Arch:      linux/amd64

Server:
 Version:      17.09.0-ce
 API version:  1.32 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:40:56 2017
 OS/Arch:      linux/amd64
 Experimental: false

I'm building aws-sam-local from source:

$ sudo /home/alfie/go/bin/aws-sam-local --version
sam version snapshot

I'll try with the release version now...

EDIT: same results with v0.2.2

EDIT: sudo docker run hello-world is v. fast

jugglingcats · 2017-10-02T18:06:49Z

I increased the docker daemon debug level and can see the first pull of the image. This only happens on the first invocation.

Oct 02 18:53:33 ubuntu dockerd[988]: time="2017-10-02T18:53:33.935204589+01:00" level=debug msg="Trying to pull lambci/lambda from https://registry-1.docker.io v2"
Oct 02 18:53:35 ubuntu dockerd[988]: time="2017-10-02T18:53:35.837557589+01:00" level=debug msg="Pulling ref from V2 registry: lambci/lambda:nodejs4.3"

On each invocation there is nothing in the docker log until 20s later when I see:

Oct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.851466966+01:00" level=debug msg="Calling POST /v1.30/containers/create"
Oct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.852087120+01:00" level=debug msg="form data: {\"AttachStderr\":false,\"AttachStdin\":false,\"AttachStdout\":faOct 02 19:05:01 ubuntu dockerd[988]: \":\"\"},\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":null,\"NanoCpus\":0,\"NetworkMode\":\"\",\"OomKillDiOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.875103569+01:00" level=debug msg="container mounted via layerStore: /var/lib/docker/overlay2/d805b257ab3a3388aOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.881657771+01:00" level=debug msg="Calling POST /v1.30/containers/314eaea03124b393812ee787375aad3e4cbd32c493d72Oct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.884345881+01:00" level=debug msg="container mounted via layerStore: /var/lib/docker/overlay2/d805b257ab3a3388aOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.884690306+01:00" level=debug msg="Assigning addresses for endpoint jovial_bardeen's interface on network bridgOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.884840668+01:00" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
Oct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.889042145+01:00" level=debug msg="Assigning addresses for endpoint jovial_bardeen's interface on network bridgOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.907086603+01:00" level=debug msg="Programming external connectivity on endpoint jovial_bardeen (e2e147fbfd8dd4Oct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.909861288+01:00" level=debug msg="EnableService 314eaea03124b393812ee787375aad3e4cbd32c493d7282896a8dfbd32708fOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.909881413+01:00" level=debug msg="EnableService 314eaea03124b393812ee787375aad3e4cbd32c493d7282896a8dfbd32708fOct 02 19:05:01 ubuntu dockerd[988]: time="2017-10-02T19:05:01.989433717+01:00" level=debug msg="sandbox set key processing took 30.706067ms for container 314eaea03124b39381Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.022468704+01:00" level=debug msg="libcontainerd: received containerd event: &types.Event{Type:\"start-containeOct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.027110772+01:00" level=debug msg="libcontainerd: event unhandled: type:\"start-container\" id:\"314eaea03124b3Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.027819518+01:00" level=debug msg="Calling POST /v1.30/containers/314eaea03124b393812ee787375aad3e4cbd32c493d72Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.028139111+01:00" level=debug msg="attach: stdout: begin"
Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.028454941+01:00" level=debug msg="attach: stderr: begin"
Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.134642968+01:00" level=debug msg="libcontainerd: received containerd event: &types.Event{Type:\"exit\", Id:\"3Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.134985982+01:00" level=debug msg="attach: stdout: end"
Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.135364281+01:00" level=debug msg="Revoking external connectivity on endpoint jovial_bardeen (e2e147fbfd8dd4d6eOct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.135768914+01:00" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.136201835+01:00" level=debug msg="attach: stderr: end"
Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.137003682+01:00" level=debug msg="Calling POST /v1.30/containers/314eaea03124b393812ee787375aad3e4cbd32c493d72Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.164579263+01:00" level=debug msg="Releasing addresses for endpoint jovial_bardeen's interface on network bridgOct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.164619106+01:00" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
Oct 02 19:05:02 ubuntu dockerd[988]: time="2017-10-02T19:05:02.179511426+01:00" level=debug msg="Calling DELETE /v1.30/containers/314eaea03124b393812ee787375aad3e4cbd32c493d

You can see that this whole sequence takes <1s so it seems docker is not the culprit. Not sure where to look next?

jugglingcats · 2017-10-02T18:21:39Z

I also tried running the hello-world sample using invoke with similar results:

$ sudo time ~/aws-sam-local/sam local invoke --event event.json
2017/10/02 19:18:07 Successfully parsed template.yaml
2017/10/02 19:18:07 Connected to Docker 1.32
2017/10/02 19:18:07 Fetching lambci/lambda:nodejs6.10 image for nodejs6.10 runtime...
nodejs6.10: Pulling from lambci/lambda
Digest: sha256:7eb4ced6a15ae3c30effc4ec0cd3aabb2bd57c9a8330b37920c3d5d722d81083
Status: Image is up to date for lambci/lambda:nodejs6.10
2017/10/02 19:18:09 Invoking index.handler (nodejs6.10)
START RequestId: abadca01-4ed0-18a5-4f7a-5a0cd2af55e1 Version: $LATEST
2017-10-02T18:18:30.101Z        abadca01-4ed0-18a5-4f7a-5a0cd2af55e1    LOG: Name is Bob
END RequestId: abadca01-4ed0-18a5-4f7a-5a0cd2af55e1

"Hello Bob"
REPORT RequestId: abadca01-4ed0-18a5-4f7a-5a0cd2af55e1  Duration: 4.73 ms       Billed Duration: 0 ms   Memory Size: 0 MB       Max Memory Used: 28 MB


0.04user
0.00system
0:23.39elapsed
0%CPU (0avgtext+0avgdata 16268maxresident)k
0inputs+0outputs (0major+1688minor)pagefaults 
0swaps

m5 · 2017-10-05T00:45:36Z

@ztolley, @jugglingcats, do you have AWS credentials configured? If not, see if adding them speeds up your execution time.

Before each execution, sam attempts to gather credentials. If no local credentials are found, it falls back to gathering credentials from ec2 instance metadata, which can take a very long time to fail if you are not running on an ec2 instance.

jugglingcats · 2017-10-05T13:00:34Z

Thanks @m5 that fixed it for me! Worth adding to the docs.

sanathkr · 2017-10-05T15:26:24Z

Looks like this issue is resolved by supplying credentials. I will close the ticket..

dannymcpherson · 2017-10-20T14:44:05Z

Thanks for this thread... I had 6-7s total times, and adding the AWS creds environment variables brought the total times down to about ~1.3s ... I would love to see the response times be even lower, but honestly, I'll take aws sam local in any form. Incredibly helpful.

aravinds03 · 2017-12-02T20:30:11Z

I am facing the same issue.
Everytime url is hit, it says "Decompressing ..jar" and it waits for 5 to 8 seconds.
I have also set ENV variables, but it is still slow.

jebberjeb · 2017-12-04T14:08:25Z

@aranvinds03. The way I worked around this was to extract my jar to a temp dir, then point CodeUri at that temp dir.

Decompressing each time I make an API call is also pretty slow for me since my jar file is pretty large.

aravinds03 · 2017-12-04T19:27:50Z

I tried that as well. I extracted jar and run with CodeUri pointing to folder. Still, the requests are too slow. If i upload the jar to lambda, then requests hitting aws endpoint is much faster than local box.

I realized that "decompressing jar" step is not time consuming. There is something else which takes more time in local box.

jebberjeb · 2017-12-04T21:43:29Z

@aravinds03 That's true. There is a lot more going on. Each request involves spinning up a new container (they are not reused), and then running a java process. For me, since my Lambda is Clojure, it also involves loading the Clojure runtime. This all adds up to my requests taking several seconds at a minimum. At this point, I am more or less just living with that limitation.

dannymcpherson · 2017-12-04T22:23:59Z

Is it planned (or possible) to keep the containers warm?

…

On Dec 4, 2017, at 3:43 PM, Jeb Beich ***@***.***> wrote: @aravinds03 That's true. There is a lot more going on. Each request involves spinning up a new container (they are not reused), and then running a java process. For me, since my Lambda is Clojure, it also involves loading the Clojure runtime. This all adds up to my requests taking several seconds at a minimum. At this point, I am more or less just living with that limitation. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

jamescgibson · 2017-12-06T15:17:25Z

Just adding to this issue for future searchers: If you configured your credentials with a profile, as of sam v0.2.2, you need to pass --profile <profile_name> to use them.

This allowed me to get the speedups described in this thread.

aravinds03 · 2017-12-06T17:43:01Z

@jamescgibson ,
The requests are still slow even after setting credential and passing --profile argument.
Requests to actual api gateway server is faster than hitting local server.

orzechowskid · 2018-02-13T21:22:04Z

maybe it's obvious in hindsight, but sam couldn't find my credentials even using the --profile argument until I placed that argument before the SAM ID:

$ sam local invoke --profile=my-profile -e test-event.json MyFunction

pkasson · 2018-03-09T09:10:51Z

I find that the missing AWS credentials is not the issue I or seems are seeing which is causing the delay. Its clear that each invocation causes a decompressing of the JAR and then cleanup following the invocation.

I saw a post where someone used a folder in the CodeUri property but could not get that working -- IS THERE a way to point to a folder which has already been decompressed / unzipped and keeps it "warm" essentially.

Clearly, there needs to be a way to keep the lambda warm between invocations. I would be will to assist if given direction on this.

marczis · 2018-03-14T08:43:53Z

AWS Credential solved for me, but I think this still would worth some investigation, why the SAM local looks for the credentials ? Some of the developers in larger organizations may not have access to the AWS environment.

zhawei · 2018-04-02T08:02:25Z

I test lambda by running SAM local in centos7 with vagrant, ~/.aws/config and ~/.aws/credentials were configured.But it always cost 30s.
I tried every way in many issues but None worked.
Once I tried to set aws credentials in root not in the sudoer account, It worked, run time has decreased by 20s.
So if someone meet this problem, try copy ~/.aws to /home/root or exucte "aws configure" in root account, be sure /home/root/.aws has configured success before run sam local.
It looks like sam docker use root's home path as the configure path instead of sudoer's home path
Wish this comment will be helpful to others who trapped in this problem.

rchatsiri · 2018-04-27T05:48:23Z

It's the same @zhawei described problems from a Aws-sam-local run by use normal user in the local environment. I change normal to the root user. Response message send from binary running with aws-sam-local fast more run than normal user.

wishdevs · 2018-05-18T14:49:02Z

in my case
skip pull docker image
before 8s
after 1.5s

sam local start-api --skip-pull-image

gregaeq · 2018-06-01T21:21:19Z

I couldn't find it in the sam-local docs, but following the AWS SAM docs, you can increase the ram usage of your local service too.

Took me a while to find this answer, so I'll leave this here.

In your template.yml

Properties:
    MemorySize: 256

You can view the actual usage of this too using
docker stats
Invoke your sam-local request, and you'll see it spin up!

hendore · 2018-07-21T10:33:04Z

Although I wasn't suffering delays as bad as other reports, each request was taking over 2s but after setting the --skip-pull-image flag as recommended by @wishdevs it has brought that down to 1s 👍

kevanpng · 2018-10-11T05:17:24Z

I did an experiment with container reuse. This is just with a lambda in python, I'm developing on ubuntu 16.04. In summary, docker container spinning up only takes an extra second. So it is not worth making the feature for container reuse. Link to my code https://github.com/kevanpng/aws-sam-local .

For a fixed query, both my colleague and I have 4s invocation time on sam local. His is a windows machine. With giving the profile flag and the container reuse, it goes down to 2.5s in my ubuntu.

My colleague is running on mac and when he tried the same query with lambda reuse and profile flag, he still had 11-14 seconds to run.

Maybe it could be that docker is slow on mac?

skinofstars · 2021-04-28T14:55:14Z

For those finding this issue first, also useful is the --warm-containers EAGER flag.

Ref #239

bjorn-ove · 2021-08-30T13:17:38Z

I had this exact issue today, but did not find any indication what caused is. It turns out the fix in #159 only applies to golang, so the python environment does not warn about it. Also, being able to run without credentials is important to me as I want to be certain nothing affects what is in the cloud.

The problem is that the credentials cache is basically broken. It will try to get the credentials and then store them for use in later invocations. However, if no credentials are returned it keeps trying every time it is invoked because it does not know the difference between not initialized and not found.

I fixed this in a fork, but don't know if the solution breaks something else so I didn't post it as a pull-request. In case someone else has the capacity to do so, here is my fix: bjorn-ove@b9e5afe

ssousa33-OS · 2021-10-18T11:04:19Z

I had this exact issue today, but did not find any indication what caused is. It turns out the fix in #159 only applies to golang, so the python environment does not warn about it. Also, being able to run without credentials is important to me as I want to be certain nothing affects what is in the cloud.

The problem is that the credentials cache is basically broken. It will try to get the credentials and then store them for use in later invocations. However, if no credentials are returned it keeps trying every time it is invoked because it does not know the difference between not initialized and not found.

I fixed this in a fork, but don't know if the solution breaks something else so I didn't post it as a pull-request. In case someone else has the capacity to do so, here is my fix: bjorn-ove@b9e5afe

@BearOve, has this solution been stable for you since the time of this post?

bjorn-ove · 2021-10-18T12:05:57Z

@BearOve, has this solution been stable for you since the time of this post?

Yes, no issues since related to this.

Gefyaqiilah · 2023-07-05T03:15:28Z

i follow @skinofstars to use --warm-containers flag but the value is LAZY, and now the response time is decreased.

m5 mentioned this issue Oct 5, 2017

Add warning when no credentials found. #159

Merged

sanathkr closed this as completed Oct 5, 2017

sprt mentioned this issue Apr 16, 2018

Requests are slow #362

Closed

This was referenced Feb 28, 2020

Assistance troubleshooting sam local invoke #82

Closed

SAM deploy doesn't set environment variables #1163

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Why are requests so slow? #134

Why are requests so slow? #134

ztolley commented Sep 21, 2017

sanathkr commented Sep 22, 2017

ztolley commented Sep 22, 2017

sanathkr commented Sep 23, 2017

ztolley commented Sep 23, 2017

PaulMaddox commented Sep 25, 2017

jugglingcats commented Oct 2, 2017 •

edited

Loading

jugglingcats commented Oct 2, 2017

jugglingcats commented Oct 2, 2017

m5 commented Oct 5, 2017

jugglingcats commented Oct 5, 2017

sanathkr commented Oct 5, 2017

dannymcpherson commented Oct 20, 2017

aravinds03 commented Dec 2, 2017

jebberjeb commented Dec 4, 2017

aravinds03 commented Dec 4, 2017

jebberjeb commented Dec 4, 2017

dannymcpherson commented Dec 4, 2017 via email

jamescgibson commented Dec 6, 2017

aravinds03 commented Dec 6, 2017

orzechowskid commented Feb 13, 2018

pkasson commented Mar 9, 2018

marczis commented Mar 14, 2018

zhawei commented Apr 2, 2018 •

edited

Loading

rchatsiri commented Apr 27, 2018

wishdevs commented May 18, 2018

gregaeq commented Jun 1, 2018 •

edited

Loading

hendore commented Jul 21, 2018

kevanpng commented Oct 11, 2018 •

edited

Loading

skinofstars commented Apr 28, 2021

bjorn-ove commented Aug 30, 2021

ssousa33-OS commented Oct 18, 2021

bjorn-ove commented Oct 18, 2021

Gefyaqiilah commented Jul 5, 2023

Why are requests so slow? #134

Why are requests so slow? #134

Comments

ztolley commented Sep 21, 2017

sanathkr commented Sep 22, 2017

ztolley commented Sep 22, 2017

sanathkr commented Sep 23, 2017

ztolley commented Sep 23, 2017

PaulMaddox commented Sep 25, 2017

jugglingcats commented Oct 2, 2017 • edited Loading

jugglingcats commented Oct 2, 2017

jugglingcats commented Oct 2, 2017

m5 commented Oct 5, 2017

jugglingcats commented Oct 5, 2017

sanathkr commented Oct 5, 2017

dannymcpherson commented Oct 20, 2017

aravinds03 commented Dec 2, 2017

jebberjeb commented Dec 4, 2017

aravinds03 commented Dec 4, 2017

jebberjeb commented Dec 4, 2017

dannymcpherson commented Dec 4, 2017 via email

jamescgibson commented Dec 6, 2017

aravinds03 commented Dec 6, 2017

orzechowskid commented Feb 13, 2018

pkasson commented Mar 9, 2018

marczis commented Mar 14, 2018

zhawei commented Apr 2, 2018 • edited Loading

rchatsiri commented Apr 27, 2018

wishdevs commented May 18, 2018

gregaeq commented Jun 1, 2018 • edited Loading

hendore commented Jul 21, 2018

kevanpng commented Oct 11, 2018 • edited Loading

skinofstars commented Apr 28, 2021

bjorn-ove commented Aug 30, 2021

ssousa33-OS commented Oct 18, 2021

bjorn-ove commented Oct 18, 2021

Gefyaqiilah commented Jul 5, 2023

jugglingcats commented Oct 2, 2017 •

edited

Loading

zhawei commented Apr 2, 2018 •

edited

Loading

gregaeq commented Jun 1, 2018 •

edited

Loading

kevanpng commented Oct 11, 2018 •

edited

Loading