aws / aws-sdk-net

The official AWS SDK for .NET. For more information on the AWS SDK for .NET, see our web site:
http://aws.amazon.com/sdkfornet/
Apache License 2.0
2.07k stars 862 forks source link

Performance Issues: Slow Initial Calls #3555

Open MuadDib opened 4 days ago

MuadDib commented 4 days ago

Describe the bug

We've observed that the initial call to DynamoDB is quite slow, often exceeding 2000ms, and sometimes even approaching 10,000ms. Subsequent calls improve significantly (usually under 20ms), but we occasionally see slower calls (500ms+) after periods of inactivity.

We are seeing the same performance using both IDynamoDBContext and the IAmazonDynamoDB. We tried using strategies outlined here to improve the situation but no luck. I even tried hardcoding the accessKey but to no avail.

Regression Issue

Expected Behavior

Client execution time even for the first request should not be an outlier by such a huge margin.

Current Behavior

Example of metrics for the first request vs followup request

[
    {
        "properties": {
            "AsyncCall": "True",
            "CanonicalRequest": "",
            "StringToSign": "AWS4-HMAC-SHA256",
            "ServiceName": "Amazon.DynamoDBv2",
            "ServiceEndpoint": "https://dynamodb.eu-west-1.amazonaws.com/",
            "MethodName": "GetItemRequest",
            "RequestSize": "126",
            "StatusCode": "OK",
            "BytesProcessed": "209",
            "AWSRequestID": "K19J5R1DG85P5U40973N60VP7VVV4KQNSO5AEMVJF66Q9ASUAAJG"
        },
        "timings": {
            "CredentialsRequestTime": 0.9548,
            "RequestSigningTime": 244.6937,
            "HttpRequestTime": 502.974,
            "ResponseUnmarshallTime": 5.8003,
            "ResponseProcessingTime": 21.274,
            "ClientExecuteTime": 879.363
        },
        "counters": {}
    },
    {
        "properties": {
            "AsyncCall": "True",
            "CanonicalRequest": "",
            "ServiceName": "Amazon.DynamoDBv2",
            "ServiceEndpoint": "https://dynamodb.eu-west-1.amazonaws.com/",
            "MethodName": "GetItemRequest",
            "RequestSize": "126",
            "StatusCode": "OK",
            "BytesProcessed": "209",
            "AWSRequestID": "03U2E2TDLSRB3T87ACBEP0BEN3VV4KQNSO5AEMVJF66Q9ASUAAJG"
        },
        "timings": {
            "CredentialsRequestTime": 0.0058,
            "RequestSigningTime": 0.2945,
            "HttpRequestTime": 2.7207,
            "ResponseUnmarshallTime": 0.0642,
            "ResponseProcessingTime": 0.2808,
            "ClientExecuteTime": 3.6218
        },
        "counters": {}
    }
]

Reproduction Steps

Minimal code directly copied from tutorials exhibit the same issue. I pasted an example in lambda for IDynamoDBContext, but it's the same executing from ECS container.

public class Functions
{
    private IDynamoDBContext _dynamoDbContext;
    public Functions()
    {
        _dynamoDbContext = new DynamoDBContext(new AmazonDynamoDBClient());
    }
    [LambdaFunction]
    [RestApi(LambdaHttpMethod.Get, "/")]
    public async Task<IHttpResult> Get(ILambdaContext context)
    {
        var queryConfig = new DynamoDBOperationConfig
        {
            OverrideTableName = "paywall-cwwebsite-subscriptions-qa",
            QueryFilter = new List<ScanCondition>
            {
                new("sk", ScanOperator.Equal, "GLOBAL")
            }
        };

        var subscriberInfo = await _dynamoDbContext.QueryAsync<SubscriberInfoDto>("google.com", queryConfig).GetRemainingAsync();

        return HttpResults.Ok();
    }
}

Possible Solution

No response

Additional Information/Context

No response

AWS .NET SDK and/or Package version used

Targeted .NET Platform

net8.0

Operating System and version

Lambda
ashishdhingra commented 3 days ago

@MuadDib Good afternoon. Could you please review if your issue is similar to https://github.com/aws/aws-sdk-net/issues/3551.

Also, could you enable verbose logs and metrics using below code and share the same:

Amazon.AWSConfigs.LoggingConfig.LogResponses = Amazon.ResponseLoggingOption.Always;
Amazon.AWSConfigs.LoggingConfig.LogTo = Amazon.LoggingOptions.Console;
Amazon.AWSConfigs.LoggingConfig.LogMetrics = true;
 Amazon.AWSConfigs.AddTraceListener("Amazon", new System.Diagnostics.ConsoleTraceListener());

Verbose logs would enable us to measure the latency on .NET SDK side.

Also refer to https://github.com/aws/aws-sdk-net/issues/3551#issuecomment-2480253275 if that helps.

Looks like your execution environment is Lambda. Initial latency could also be caused by Lambda cold starts.

You may also explore new feature Improving startup performance with Lambda SnapStart to improve initial latency.

Thanks, Ashish

MuadDib commented 4 hours ago

Hello Ashish,

Thank you for your reply!

Could you please let me know the approximate response time expected for the first request? I’m specifically wondering whether it falls within a range of tens of milliseconds or hundreds of milliseconds.

Additionally, do you know of any resources that showcase the performance of the .NET client? I’m particularly interested in understanding the expected response time for the first request. I understand that this has been identified as an issue, and you’re working to improve it in the next version of the client. However, it would be extremely helpful to know the expected response times for both the current version and the improved version. Even if you don’t have precise data, an approximate timing would still be very valuable to me.

To give some context about our tech stack: We are moving towards a fully serverless architecture. Our clients connect to AWS API Gateway, which uses simple mapping lambdas to retrieve data directly from read models in DynamoDB. The client workload is relatively low volume, with extended periods of inactivity.

Our lambdas are optimized for minimal cold-start times, typically just a few milliseconds. However, this optimization becomes irrelevant if the connection to DynamoDB takes a long time to initialize. Since lambdas have a very short lifecycle (often only a few minutes before AWS destroys the running container), a lengthy initialization time for DynamoDB becomes a critical issue that could halt our progress.

Thank you for your insights and assistance!

PS as per your request I added the logging and simplified the code:

public class Functions
{
    private readonly AmazonDynamoDBClient _dynamoDbClient = new ();
    public Functions()
    {
        Amazon.AWSConfigs.LoggingConfig.LogResponses = Amazon.ResponseLoggingOption.Always;
        Amazon.AWSConfigs.LoggingConfig.LogTo = Amazon.LoggingOptions.Console;
        Amazon.AWSConfigs.LoggingConfig.LogMetrics = true;
        Amazon.AWSConfigs.AddTraceListener("Amazon", new System.Diagnostics.ConsoleTraceListener());
    }
    [LambdaFunction]
    [RestApi(LambdaHttpMethod.Get, "/")]
    public async Task<IHttpResult> Get(ILambdaContext context)
    {
        var queryConfig = new GetItemRequest()
        {
            TableName = "test-table",
            Key = {
                { "pk", new AttributeValue { S = "@google.com" } },
                { "sk", new AttributeValue { S = "GLOBAL" } }}
        };

        var subscriberInfo = await _dynamoDbClient.GetItemAsync(queryConfig);
        return HttpResults.Ok();
    }
}

Full log: log.txt When deployed to AWS: logAws.txt

AmazonDynamoDBClient 1|2024-11-25T10:47:00.011Z|DEBUG|Received response (truncated to 1024 bytes): [{"Item":{"subscriptionStatus":{"S":"Active"},"sk":{"S":"GLOBAL"},"pk":{"S":"@google.com"},"subscriptionStartDate":{"S":"2024-05-28T00:00:00.0000000"},"subscriptionEndDate":{"S":"2025-05-28T00:00:00.0000000"}}}]

These are example metrics that we see for the Initial call vs subsequent call:

[
    //call 1
    {
        "properties": {
            "AsyncCall": "True",
            "CanonicalRequest": "",
            "StringToSign": "AWS4-HMAC-SHA256",
            "ServiceName": "Amazon.DynamoDBv2",
            "ServiceEndpoint": "https://dynamodb.eu-west-1.amazonaws.com/",
            "MethodName": "GetItemRequest",
            "RequestSize": "126",
            "StatusCode": "OK",
            "BytesProcessed": "209",
            "AWSRequestID": "K19J5R1DG85P5U40973N60VP7VVV4KQNSO5AEMVJF66Q9ASUAAJG"
        },
        "timings": {
            "CredentialsRequestTime": 0.9548,
            "RequestSigningTime": 244.6937,
            "HttpRequestTime": 502.974,
            "ResponseUnmarshallTime": 5.8003,
            "ResponseProcessingTime": 21.274,
            "ClientExecuteTime": 879.363
        },
        "counters": {}
    },
    //call 2
    {
        "properties": {
            "AsyncCall": "True",
            "CanonicalRequest": "",
            "ServiceName": "Amazon.DynamoDBv2",
            "ServiceEndpoint": "https://dynamodb.eu-west-1.amazonaws.com/",
            "MethodName": "GetItemRequest",
            "RequestSize": "126",
            "StatusCode": "OK",
            "BytesProcessed": "209",
            "AWSRequestID": "03U2E2TDLSRB3T87ACBEP0BEN3VV4KQNSO5AEMVJF66Q9ASUAAJG"
        },
        "timings": {
            "CredentialsRequestTime": 0.0058,
            "RequestSigningTime": 0.2945,
            "HttpRequestTime": 2.7207,
            "ResponseUnmarshallTime": 0.0642,
            "ResponseProcessingTime": 0.2808,
            "ClientExecuteTime": 3.6218
        },
        "counters": {}
    }
]