Unexpectedly high execution times with extension layer v91

[jo-me]

Hy there,

we're seeing some strange effects with the latest extension versions that we can't really explain.

The function execution takes significantly longer than expected - apparently due to overhead related to tracing/metrics so that the total time of execution hits our 3s function timeout for our typical 0.5-1.5s workload.
Hitting the timeout results in lambda instance shutdown and subsequent cold starts.

There are a couple of ways to turn on/off this "behavior" with v90 and v91, but I've boiled down my function code to a minimal handler that sleeps for 1s before returning a positive result (to the AWS LoadBalancer that triggered it). It uses DD extension layer v91 .

Expected would be a cold start (e.g. 500ms) and then execution time of slightly above 1000ms, but xray shows times closer to 4000ms!

I can "fix" this minimal function by:

• increasing RAM (e.g. to 192 MB) or
• increasing the timeout to 5s or
• disabling DD_ENHANCED_METRICS and DD_TRACE_ENABLED (one OR the other is not sufficient)

All of which is not really desired and should not be necessary.

My lambda function is

• written in Golang,
• uses runtime provided.al2023
• is happy with 128 MB ram (logs say Max Memory Used: 78 MB)
• running in a VPC (with internet connectivity)
• tiggered by ALB requests
• in region eu-central-1

The env variables set are (among others)

• DD_API_KEY_SECRET_ARN | arn:aws:secretsmanager:….
• DD_ENHANCED_METRICS | true
• DD_RUNTIME_METRICS_ENABLED | true
• DD_SERVERLESS_LOGS_ENABLED | false
• DD_SITE | datadoghq.com
• DD_TRACE_ENABLED | true

The minimal handler function that I use to reproduce this is:

import (
	"context"
	"time"

	ddlambda "github.com/DataDog/dd-trace-go/contrib/aws/datadog-lambda-go/v2"
	"github.com/aws/aws-lambda-go/events"
	"github.com/aws/aws-lambda-go/lambda"
)

func main() {
	handler := func(ctx context.Context, req events.ALBTargetGroupRequest) (events.ALBTargetGroupResponse, error) {
		time.Sleep(1000 * time.Millisecond)

		return events.ALBTargetGroupResponse{
			StatusCode:        200,
			StatusDescription: "200 OK",
			Body:              "{\"message\": \"Hello world\"}",
			MultiValueHeaders: map[string][]string{
				"Content-Type": {"application/json"},
			},
			IsBase64Encoded: false,
		}, nil
	}

	lambda.Start(ddlambda.WrapFunction(handler, nil))
}

My actual function is still on extension v90 and I can see a similar pattern if the function code initializes very quickly (e.g. without any network I/O. Adding a 100ms sleep during initialization (not in the handler) "fixed" this there, but this trick does not work with v91 anymore.

Thanks for any hints!

Jochen

Jochen Mehlhorn jochen.mehlhorn@mercedes-benz.com, Mercedes-Benz Tech Innovation GmbH
 
Provider Information

[astuyve]

Hi @jo-me thanks for the note.

The best way to work with us on this is to open a support ticket so we can share debug logs and a reproduction tests. That said, I can make a few guesses. Firstly I would try disabling runtime metrics as those aren't supported in Lambda at this time.

Generally speaking if increasing the RAM improves the performance, there's a CPU bottleneck. In Lambda, CPU and RAM are tied together so even if the function is happily within the memory limits, you're likely exhausting the available 1/8th vCPU you've provisioned. 128mb functions have a teeny sliver of available CPU and it's likely that you'll actually save money by increasing resources (see lambda powertuning)

I further suspect this because of your experiment using sleep in the init phase helping. Lambda doesn't document this but they provide 1 full uncapped vCPU during the init phase, so you get more vCPU during this phase than during the normal execution phase. When users provide an AWS Secrets Manager key, we have to not only compute the necessary signature to fetch it, but also wait on the network time - this is even more painful if your secret is stored in a different region than your function. Because of this we only force the key to resolve at flush time.

Finally by default we'll flush telemetry data at the end of a function invocation for the first 20 or so, before adapting to nonblocking functions if they are busy enough. This is more painful for you as you're flushing data across the Atlantic, so there's even more network time which is included in the duration period. Because your function initializes quickly, we likely ALSO have to resolve the API key at the end of the transaction with far lower vCPU resources than we would get during the init phase.

I think you can make a few changes. Firstly I'd suggest setting DD_SERVERLESS_FLUSH_STRATEGY:periodically,60000 for intermittent functions or DD_SERVERLESS_FLUSH_STRATEGY:continuously,20000 for busier functions. You could also consider simply testing this with a single-purpose API key as an environment variable. Finally you could try increasing the RAM setting to provide more vCPU resources.

Either way please do open a ticket so we can track and replicate these experiments with your actual business logic (which certainly will use more CPU resources).

Thanks!
AJ