[Migrated] Unpredictable function execution/APIGW response times

[jneves]

Originally from: Miserlou/Zappa#418 by smoll

This is more of a question/investigatory issue rather than a bug report per se, but I've noticed this behavior on 2 different Zappa-based APIs I have started working on.

Basically, I've noticed that when I call an endpoint after not using it for a while, I will get a very long response time, e.g.

$ time http https://abcd.execute-api.us-east-1.amazonaws.com/dev/
HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 19
Content-Type: text/html; charset=utf-8
Date: Thu, 20 Oct 2016 07:18:17 GMT
Set-Cookie: zappa=AQ4; Path=/
Via: 1.1 2e4bb09f82d346fc09032cfb35e3c3e4.cloudfront.net (CloudFront)
X-Amz-Cf-Id: lEhkWktpPID6i-IflVRUPALDgCRF8agsL7CI2jnyvD1CcPVKSjG1OQ==
X-Cache: Miss from cloudfront
x-amzn-Remapped-Content-Length: 19
x-amzn-RequestId: 5f184bf1-9695-11e6-9e74-b70f8d856374

This is the index!


real    0m5.518s
user    0m0.275s
sys     0m0.255s

but if I call it again immediately after I get a much faster response

$ time http https://abcd.execute-api.us-east-1.amazonaws.com/dev/
HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 19
Content-Type: text/html; charset=utf-8
Date: Thu, 20 Oct 2016 07:18:19 GMT
Set-Cookie: zappa=AQ4; Path=/
Via: 1.1 031c38bec1e4f8401157e1d767a53637.cloudfront.net (CloudFront)
X-Amz-Cf-Id: wTr7B0ZTGHTY7GRm-Uw2IY76pcPhc8Bnb7wMLiDhFR9wwd4XFuWd5w==
X-Cache: Miss from cloudfront
x-amzn-Remapped-Content-Length: 19
x-amzn-RequestId: 6077b516-9695-11e6-a92a-657b31009f49

This is the index!


real    0m0.771s
user    0m0.264s
sys     0m0.168s

The "API" implementation is a simple print statement so it's not worth showing, but here are my Zappa settings:

{
    "dev": {
        "project_name": "myapi",
        "app_function": "myapi.app",
        "manage_roles": false,
        "role_name": "ZappaLambdaExecution",
        "s3_bucket": "dev-myapi-bucket",
        "domain": "myapi.com",
        "lets_encrypt_key": "s3://mybucket/account.key",
        "lets_encrypt_expression": "rate(2 days)",
        "keep_warm": true,
        "keep_warm_expression": "rate(1 minute)",
        "timeout_seconds": 69
    }
}

^ I increased the frequency on the keep_warm_expression key to see if it helps, but it doesn't seem to.

Don't see anything in CloudWatch either, all of the log lines look like this:

REPORT RequestId: dde080d0-9695-11e6-9593-ab204f2952ay  Duration: 0.62 ms   Billed Duration: 100 ms Memory Size: 512 MB Max Memory Used: 21 MB

any ideas where to look for more info?