8
votes

I have a lambda function that will be called infrequently in Production, but it will be public-facing, so I want to avoid cold-starts. So I thought I could use provisioned concurrency to avoid this issue. My Cloudformation template looks as follows:

QuoteLinkServiceFunction:
    Type: AWS::Serverless::Function
    Properties:
      # other lambda properties...
      ProvisionedConcurrencyConfig:
        ProvisionedConcurrentExecutions: 1

When I create this stack in my Test environment though (where I am the only user, and so there are no other calls happening concurrently), I still experience cold starts when returning to use this function after a few hours. Subsequent calls immediately after the first call run faster as the lambda is now warmed up.

The lambda console shows that the alias for this function has actually been set up with a provisioned concurrency of 1, and I have verified the ALB target group is pointed at the alias. So why am I still getting cold starts?

3
Are you sure these are really cold star latencies rather than problem with db connection for instances? Have you think of using X-Ray for tracing? - BAD_SEED
@BAD_SEED I don't have X-Ray set up on it yet, but you're probably right. In keeping with docs.aws.amazon.com/lambda/latest/dg/best-practices.html, I do some initial heavy lifting outside of the function handler in my handler constructor (it's a .NET Core lambda), so that the function handler itself is very lightweight for each call. I'm realising now that I just assumed that the handler constructor would get invoked when the lambda was warmed up, but I guess it doesn't do that - lambda probably just keeps a container ready, and delays invoking constructor and handler until first call. - Ronan Moriarty
@BAD_SEED If you want to repost your comment as an answer, I'd be happy to accept it. - Ronan Moriarty
I am also seeing the same issue and it clearly doesn't have to do with the answer here because in cloudwatch it has for the initial call after no calls for a while has: REPORT RequestId: 3c0d1c43-4dc3-4059-9e51-203ed4387756 Duration: 492.12 ms Billed Duration: 493 ms Memory Size: 256 MB Max Memory Used: 101 MB Init Duration: 4831.59 ms. Other calls don't have Init Duration. Because of the provisioned concurrency I should never see Init Duration in cloudwatch. Any ideas? Do you have Init Duration in cloudwatch? - Rafi
Actually I assume Init Duration include the time of the constructor but still provisionedConcurrency should prevent it from being recalled? - Rafi

3 Answers

2
votes

We're experiencing the same issue, and haven't found any way around it. In the end, Lambda instances are transient, so there's no guaranteed continuous uptime (even with provisioned concurrency).

What provisioned concurrency does give you though is the guarantee of a number of running instances - although these can be swapped with other instances at any point in time (and incur a cold start when that happens). The frequency of the swaps seems pretty arbitrary, and I assume, completely up to AWS.


A good way to tell if Lambda is indeed doing a cold start is to look at the logs in CloudWatch. Each request should have a REPORT log that looks like this:

REPORT RequestId: f840a316-cf35-42ec-8f4d-c03a6cde9192  Duration: 368.80 ms Billed Duration: 369 ms Memory Size: 128 MB Max Memory Used: 93 MB  Init Duration: 3569.10 ms

If you see Init Duration at the end of the log, then it is indeed a cold start.

Also, a new CloudWatch log stream seems to be created each time AWS spins up a new Lambda "instance" - which incurs a cold start, confirmed by the fact that the first request of each log stream has an Init Duration. So just taking a look at the "First event time" column will show you all your cold starts (the column can be added via the preferences/gear icon).


It can also be a good idea to look at the START log, to make sure that the intended version is being called (the one with provisioned concurrency configured):

START RequestId: f840a316-cf35-42ec-8f4d-c03a6cde9192   Version: 15

It's especially important to make sure that the version is not $LATEST (which cannot benefit from provisioned concurrency):

Each version of a function can only have one provisioned concurrency configuration. This can be directly on the version itself, or on an alias that points to the version. Two aliases can't allocate provisioned concurrency for the same version. Also, you can't allocate provisioned concurrency on an alias that points to the unpublished version ($LATEST).

1
votes

Are you sure these are really cold start latencies rather than problem with database connection? Have you think of using X-Ray for tracing? You could wrap the instruction you want to mesure inside a segment.

Here an example application.

0
votes

A colleague of mine ran a test to figure out what is going on here and the cloudwatch logs are misleading. When you have provisionedConcurrency and you see Init Duration it doesn't mean that it actually took that amount of extra time but what it would have been if there wasn't provisionedConcurrency. I know that's counterintuitive but that's what the test showed.

Test Setup

  1. Lambda #1 - Has ProvisionConcurency = 1
  2. Lambda #2 - Executes Lambda #1 and log the in this lambda how long the execution of lambda #1 took.
  3. Execute Lambda #2 when both lambda #1 and lambda #2 have been idle for a long time too make sure it will trigger a cold start.

Test Result

Lambda #1 Cloud Watch Logs:

2021-06-11T12:09:22.427+03:00   START RequestId: 8f90de41-3c2b-4baf-b843-99173d5862ba Version: 7
2021-06-11T12:09:22.600+03:00   Lambda #1 request: {"Key1":null,"Key2":null,"Key3":null}
2021-06-11T12:09:22.617+03:00   END RequestId: 8f90de41-3c2b-4baf-b843-99173d5862ba
2021-06-11T12:09:22.618+03:00   REPORT RequestId: 8f90de41-3c2b-4baf-b843-99173d5862ba Duration: 189.24 ms Billed Duration: 190 ms Memory Size: 256 MB Max Memory Used: 110 MB Init Duration: 5079.01 ms

Lambda #2 Cloud Watch Logs:

2021-06-11T12:09:21.861+03:00   START RequestId: 3cf51d5a-816b-4319-8db9-c9fee88e3e09 Version: $LATEST
2021-06-11T12:09:22.177+03:00   Lambda#2 request: {"Key1":"value1","Key2":"value2","Key3":"value3"}
2021-06-11T12:09:22.624+03:00   Lambda#1 time taken: 00:00:00.4294049
2021-06-11T12:09:22.635+03:00   END RequestId: 3cf51d5a-816b-4319-8db9-c9fee88e3e09
2021-06-11T12:09:22.635+03:00   REPORT RequestId: 3cf51d5a-816b-4319-8db9-c9fee88e3e09 Duration: 772.90 ms Billed Duration: 773 ms Memory Size: 256 MB Max Memory Used: 109 MB Init Duration: 837.07 ms

Notice: Lambda#1 time taken: 00:00:00.4294049 but the the init duration for lambda #1 is 5079.01 ms. So provisionedConcurrency works like it should just the cloudwatch logs are deceiving.