search

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.06k stars 856 forks source link

Event Bus PutEventsAsync is slow on first execution #3046

Open michaelakin opened 1 year ago

michaelakin commented 1 year ago

Describe the bug

On the first execution, the PutEventsAsync is running slow.

My lambda with a Dotnet api project was running slow, so I created a single function to send an event and it also runs slow and I tracked the slowest part to the AWS Command PutEventsAsync.

Here is my code:

Expected Behavior

I expected this command to run in less than 50ms.

Current Behavior

It takes over 5 seconds to issue the command the first time.

Reproduction Steps

Execute the lambda function

using Amazon.CloudWatchEvents;
using Amazon.CloudWatchEvents.Model;
using Amazon.Lambda.Core;
using Microsoft.Extensions.DependencyInjection;
using System.Text.Json.Serialization;
using System.Text.Json;
using System.Diagnostics;

// Assembly attribute to enable the Lambda function's JSON input to be converted into a .NET class.
[assembly: LambdaSerializer(typeof(Amazon.Lambda.Serialization.SystemTextJson.DefaultLambdaJsonSerializer))]

namespace PutEventTimingTest;

public class Function
{
    private class TestClass
    {
        public int Id { get; set; }
        public string Name { get; set; }
    }

    public async Task FunctionHandler(string input, ILambdaContext context)
    {
        var services = new ServiceCollection();
        services.AddAWSService<IAmazonCloudWatchEvents>();

        ServiceProvider serviceProvider = services.BuildServiceProvider();

        var eventService = serviceProvider.GetRequiredService<IAmazonCloudWatchEvents>();

        var test = new TestClass { Id = 1, Name = "Slow Function Test" };

        var putEvent = new PutEventsRequest
        {
            Entries = new List<PutEventsRequestEntry> {
                new PutEventsRequestEntry {
                    Source = "testSource",
                    Detail = JsonSerializer.Serialize<TestClass>(test, new JsonSerializerOptions {
                        MaxDepth = 10,
                        ReferenceHandler = ReferenceHandler.Preserve,
                        PropertyNamingPolicy = JsonNamingPolicy.CamelCase,
                        PropertyNameCaseInsensitive = true,
                    }),
                    DetailType = "slowTestEvent",
                    Time = DateTime.UtcNow,
                    EventBusName = "testBus"
                } }
        };

        var stopwatch = Stopwatch.StartNew();
        await eventService.PutEventsAsync(putEvent);
        stopwatch.Stop();
        Console.WriteLine($"put took {stopwatch.ElapsedMilliseconds}ms");
    }
}

Possible Solution

unknown.

Additional Information/Context

No response

AWS .NET SDK and/or Package version used

<PackageReference Include="Amazon.Lambda.Core" Version="2.1.0" />
<PackageReference Include="Amazon.Lambda.Serialization.SystemTextJson" Version="2.3.1" />
<PackageReference Include="AWSSDK.CloudWatchEvents" Version="3.7.200.27" />
<PackageReference Include="AWSSDK.Extensions.NETCore.Setup" Version="3.7.7" />
<PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="7.0.0" />

Targeted .NET Platform

.net 6

Operating System and version

Amazon Linux (Lambda)

michaelakin commented 1 year ago

Here is the log showing the times:

INIT_START Runtime Version: dotnet:6.v20 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:cc188eef0afc9baf44ce1d6bd4559c2d28b14aa063885a2f3b2bd2ba64788992 START RequestId: a4c5cf23-5cf4-42cc-9806-60348319516f Version: $LATEST 2023-09-11T21:47:59.768Z a4c5cf23-5cf4-42cc-9806-60348319516f info put took 1,779 ms END RequestId: a4c5cf23-5cf4-42cc-9806-60348319516f REPORT RequestId: a4c5cf23-5cf4-42cc-9806-60348319516f Duration: 2780.77 ms Billed Duration: 2781 ms Memory Size: 256 MB Max Memory Used: 97 MB Init Duration: 243.25 ms
START RequestId: 8a39dfd7-0ef2-4e50-8d3d-d2a945598d45 Version: $LATEST 2023-09-11T21:48:20.986Z 8a39dfd7-0ef2-4e50-8d3d-d2a945598d45 info put took 99 ms END RequestId: 8a39dfd7-0ef2-4e50-8d3d-d2a945598d45 REPORT RequestId: 8a39dfd7-0ef2-4e50-8d3d-d2a945598d45 Duration: 130.54 ms Billed Duration: 131 ms Memory Size: 256 MB Max Memory Used: 98 MB

michaelakin commented 1 year ago

Now the example above basically took 2 seconds and that is too slow for an api call, but the actual code in my test environment is taking between 5 and 11 seconds to run the first time.

Here is 1, and the whole api process took 11 seconds. Which is totally unacceptable for an api call. I don't know what else is taking so long but this piece is the longest.

put took 5,796.000ms

image

ashishdhingra commented 1 year ago

@michaelakin Thanks for opening the issue. Could you please enable verbose logging in your code so that we could examine what operation is taking most time.

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

SDK would try to resolve credentials (usually via attached IAM role) and region endpoint, before making the service API call.

Thanks, Ashish

michaelakin commented 1 year ago

Sure, here it is:

INIT_START Runtime Version: dotnet:6.v20 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:cc188eef0afc9baf44ce1d6bd4559c2d28b14aa063885a2f3b2bd2ba64788992 START RequestId: 1ae90f3a-533b-4828-b8f9-e80bef41889f Version: $LATEST Amazon Information: 0 : 2023-09-12T23:33:46.770Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info UserCrypto is not supported. This may be due to use of a non-Windows operating system or Windows Nano Server, or the current user account may not have its profile loaded. Unable to load shared library 'Crypt32.dll' or one of its dependencies. In order to help diagnose loading problems, consider setting the LD_DEBUG environment variable: libCrypt32.dll: cannot open shared object file: No such file or directory Amazon Information: 0 : 2023-09-12T23:33:46.881Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Credentials found using environment variables. Amazon Information: 0 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_ENABLE_ENDPOINT_DISCOVERY was not set with a value. Amazon Information: 1 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_MAX_ATTEMPTS was not set with a value. Amazon Information: 2 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_RETRY_MODE was not set with a value. Amazon Information: 3 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_EC2_METADATA_SERVICE_ENDPOINT was not set with a value. Amazon Information: 4 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_EC2_METADATA_SERVICE_ENDPOINT_MODE was not set with a value. Amazon Information: 5 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_USE_DUALSTACK_ENDPOINT was not set with a value. Amazon Information: 6 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_USE_FIPS_ENDPOINT was not set with a value. Amazon Information: 7 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_IGNORE_CONFIGURED_ENDPOINT_URLS was not set with a value. Amazon Information: 0 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Unable to find a profile named 'default' in store Amazon.Runtime.CredentialManagement.CredentialProfileStoreChain Amazon Information: 0 : 2023-09-12T23:33:46.982Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Region found using environment variable. Amazon Information: 0 : 2023-09-12T23:33:46.982Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Resolved DefaultConfigurationMode for RegionEndpoint [us-east-2] to [Legacy]. Amazon Information: 1 : 2023-09-12T23:33:47.382Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Credentials found using environment variables. Amazon Verbose: 0 : 2023-09-12T23:33:49.021Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Received response (truncated to 1024 bytes): [ { "Entries": [ { "EventId": "aa8dce84-02c5-09c9-399b-2694a0fb1d3c" } ], "FailedEntryCount": 0 } ] 2023-09-12T23:33:49.042Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info put took 1781ms END RequestId: 1ae90f3a-533b-4828-b8f9-e80bef41889f REPORT RequestId: 1ae90f3a-533b-4828-b8f9-e80bef41889f Duration: 2772.58 ms Billed Duration: 2773 ms Memory Size: 256 MB Max Memory Used: 97 MB Init Duration: 258.28 ms
START RequestId: ec64484a-1dc0-4649-96f7-43d2e69d9193 Version: $LATEST Amazon Information: 1 : 2023-09-12T23:33:57.610Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info Resolved DefaultConfigurationMode for RegionEndpoint [us-east-2] to [Legacy]. Amazon Information: 2 : 2023-09-12T23:33:57.612Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info Credentials found using environment variables. Amazon Verbose: 1 : 2023-09-12T23:33:57.735Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info Received response (truncated to 1024 bytes): [ { "Entries": [ { "EventId": "6fe22bf8-4f03-b009-8090-4756b7bb84cf" } ], "FailedEntryCount": 0 } ] 2023-09-12T23:33:57.735Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info put took 123ms END RequestId: ec64484a-1dc0-4649-96f7-43d2e69d9193 REPORT RequestId: ec64484a-1dc0-4649-96f7-43d2e69d9193 Duration: 128.06 ms Billed Duration: 129 ms Memory Size: 256 MB Max Memory Used: 98 MB

michaelakin commented 1 year ago

Here's the one that started all this in a minimal api. Not sure the format you need here.

timestamp,message 1694622583135,"INIT_START Runtime Version: dotnet:6.v20 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:506d05e64635e29564050c864e65e71056f9b490ab564c9d40c9b73cdd9f030d " 1694622583825,"START RequestId: 9826a85c-da3d-4d49-af9d-55631019b157 Version: $LATEST " 1694622586502,"info: AWSSDK[0] " 1694622586502,"Found AWS options in IConfiguration " 1694622586683,"Amazon Information: 0 : UserCrypto is not supported. This may be due to use of a non-Windows operating system or Windows Nano Server, or the current user account may not have its profile loaded. Unable to load shared library 'Crypt32.dll' or one of its dependencies. In order to help diagnose loading problems, consider setting the LD_DEBUG environment variable: libCrypt32.dll: cannot open shared object file: No such file or directory " 1694622586863,"Amazon Information: 0 : Credentials found using environment variables. " 1694622586864,"info: AWSSDK[0] " 1694622586864,"Found credentials using the AWS SDK's default credential search " 1694622587043,"Amazon Information: 0 : The environment variable AWS_ENABLE_ENDPOINT_DISCOVERY was not set with a value. " 1694622587044,"Amazon Information: 1 : The environment variable AWS_MAX_ATTEMPTS was not set with a value. " 1694622587044,"Amazon Information: 2 : The environment variable AWS_RETRY_MODE was not set with a value. " 1694622587045,"Amazon Information: 3 : The environment variable AWS_EC2_METADATA_SERVICE_ENDPOINT was not set with a value. " 1694622587045,"Amazon Information: 4 : The environment variable AWS_EC2_METADATA_SERVICE_ENDPOINT_MODE was not set with a value. " 1694622587045,"Amazon Information: 5 : The environment variable AWS_USE_DUALSTACK_ENDPOINT was not set with a value. " 1694622587045,"Amazon Information: 6 : The environment variable AWS_USE_FIPS_ENDPOINT was not set with a value. " 1694622587062,"Amazon Information: 7 : The environment variable AWS_IGNORE_CONFIGURED_ENDPOINT_URLS was not set with a value. " 1694622587065,"Amazon Information: 0 : Unable to find a profile named 'default' in store Amazon.Runtime.CredentialManagement.CredentialProfileStoreChain " 1694622587183,"Amazon Information: 0 : Region found using environment variable. " 1694622587702,"2023-09-13T16:29:47.663Z 9826a85c-da3d-4d49-af9d-55631019b157 info Send Event " 1694622588103,"Amazon Information: 0 : Resolved DefaultConfigurationMode for RegionEndpoint [us-east-2] to [Legacy]. " 1694622588662,"Amazon Information: 1 : Credentials found using environment variables. " 1694622591544,"Amazon Verbose: 0 : Received response (truncated to 1024 bytes): [{""Entries"":[{""EventId"":""8a742d0c-15fe-8511-a61e-c482c188b295""}],""FailedEntryCount"":0}] " 1694622592304,"END RequestId: 9826a85c-da3d-4d49-af9d-55631019b157 " 1694622592304,"REPORT RequestId: 9826a85c-da3d-4d49-af9d-55631019b157 Duration: 8478.87 ms Billed Duration: 8479 ms Memory Size: 256 MB Max Memory Used: 130 MB Init Duration: 688.18 ms
" 1694622670891,"START RequestId: 7a51f851-556b-4ac1-89e6-5848e4cf86ab Version: $LATEST " 1694622670943,"2023-09-13T16:31:10.943Z 7a51f851-556b-4ac1-89e6-5848e4cf86ab info Send Event " 1694622670981,"Amazon Information: 2 : Credentials found using environment variables. " 1694622671142,"Amazon Verbose: 1 : Received response (truncated to 1024 bytes): [{""Entries"":[{""EventId"":""972b0c74-7063-7560-1d42-427fce1015bf""}],""FailedEntryCount"":0}] " 1694622671146,"END RequestId: 7a51f851-556b-4ac1-89e6-5848e4cf86ab " 1694622671146,"REPORT RequestId: 7a51f851-556b-4ac1-89e6-5848e4cf86ab Duration: 254.29 ms Billed Duration: 255 ms Memory Size: 256 MB Max Memory Used: 131 MB "

ashishdhingra commented 1 year ago

Sure, here it is:

INIT_START Runtime Version: dotnet:6.v20 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:cc188eef0afc9baf44ce1d6bd4559c2d28b14aa063885a2f3b2bd2ba64788992 START RequestId: 1ae90f3a-533b-4828-b8f9-e80bef41889f Version: $LATEST Amazon Information: 0 : 2023-09-12T23:33:46.770Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info UserCrypto is not supported. This may be due to use of a non-Windows operating system or Windows Nano Server, or the current user account may not have its profile loaded. Unable to load shared library 'Crypt32.dll' or one of its dependencies. In order to help diagnose loading problems, consider setting the LD_DEBUG environment variable: libCrypt32.dll: cannot open shared object file: No such file or directory Amazon Information: 0 : 2023-09-12T23:33:46.881Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Credentials found using environment variables. Amazon Information: 0 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_ENABLE_ENDPOINT_DISCOVERY was not set with a value. Amazon Information: 1 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_MAX_ATTEMPTS was not set with a value. Amazon Information: 2 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_RETRY_MODE was not set with a value. Amazon Information: 3 : 2023-09-12T23:33:46.962Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_EC2_METADATA_SERVICE_ENDPOINT was not set with a value. Amazon Information: 4 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_EC2_METADATA_SERVICE_ENDPOINT_MODE was not set with a value. Amazon Information: 5 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_USE_DUALSTACK_ENDPOINT was not set with a value. Amazon Information: 6 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_USE_FIPS_ENDPOINT was not set with a value. Amazon Information: 7 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info The environment variable AWS_IGNORE_CONFIGURED_ENDPOINT_URLS was not set with a value. Amazon Information: 0 : 2023-09-12T23:33:46.963Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Unable to find a profile named 'default' in store Amazon.Runtime.CredentialManagement.CredentialProfileStoreChain Amazon Information: 0 : 2023-09-12T23:33:46.982Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Region found using environment variable. Amazon Information: 0 : 2023-09-12T23:33:46.982Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Resolved DefaultConfigurationMode for RegionEndpoint [us-east-2] to [Legacy]. Amazon Information: 1 : 2023-09-12T23:33:47.382Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Credentials found using environment variables. Amazon Verbose: 0 : 2023-09-12T23:33:49.021Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info Received response (truncated to 1024 bytes): [ { "Entries": [ { "EventId": "aa8dce84-02c5-09c9-399b-2694a0fb1d3c" } ], "FailedEntryCount": 0 } ] 2023-09-12T23:33:49.042Z 1ae90f3a-533b-4828-b8f9-e80bef41889f info put took 1781ms END RequestId: 1ae90f3a-533b-4828-b8f9-e80bef41889f REPORT RequestId: 1ae90f3a-533b-4828-b8f9-e80bef41889f Duration: 2772.58 ms Billed Duration: 2773 ms Memory Size: 256 MB Max Memory Used: 97 MB Init Duration: 258.28 ms START RequestId: ec64484a-1dc0-4649-96f7-43d2e69d9193 Version: $LATEST Amazon Information: 1 : 2023-09-12T23:33:57.610Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info Resolved DefaultConfigurationMode for RegionEndpoint [us-east-2] to [Legacy]. Amazon Information: 2 : 2023-09-12T23:33:57.612Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info Credentials found using environment variables. Amazon Verbose: 1 : 2023-09-12T23:33:57.735Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info Received response (truncated to 1024 bytes): [ { "Entries": [ { "EventId": "6fe22bf8-4f03-b009-8090-4756b7bb84cf" } ], "FailedEntryCount": 0 } ] 2023-09-12T23:33:57.735Z ec64484a-1dc0-4649-96f7-43d2e69d9193 info put took 123ms END RequestId: ec64484a-1dc0-4649-96f7-43d2e69d9193 REPORT RequestId: ec64484a-1dc0-4649-96f7-43d2e69d9193 Duration: 128.06 ms Billed Duration: 129 ms Memory Size: 256 MB Max Memory Used: 98 MB

@michaelakin I'm unsure if I see the same delay. Are you able to reproduce the issue consistently at your end?

michaelakin commented 1 year ago

Yes, it is very consistent.

Here are the two lines that highlight the problem.

1694622592304,"REPORT RequestId: 9826a85c-da3d-4d49-af9d-55631019b157 Duration: 8478.87 ms Billed Duration: 8479 ms Memory Size: 256 MB Max Memory Used: 130 MB Init Duration: 688.18 ms " 1694622671146,"REPORT RequestId: 7a51f851-556b-4ac1-89e6-5848e4cf86ab Duration: 254.29 ms Billed Duration: 255 ms Memory Size: 256 MB Max Memory Used: 131 MB

Im5tu commented 8 months ago

I'm seeing something very similar with the dynamo client as well. Logged the metrics:

First call: image

Second call: image

I expect the first call to be a little slower, by like 1-200ms for the HTTP setup etc, not having a difference of 2-3 seconds. Checked the metrics on DynamoDB on all response times are under 50ms. So to me, this is definitely looks like an SDK issue.

My stack: .NET 8 AOT, AL2023 on arm64, SourceGenerators for anything where I can. Latest packages etc.

Happy to try out things out to help get this resolved as this will ultimately cost me and others money :)

Im5tu commented 8 months ago

Any ideas @normj @ashishdhingra ? :)