Skip to content

Trim per-request logger overhead - #4569

Merged
dscpinheiro merged 2 commits into
aws:developmentfrom
martincostello:logger-lookup-trims
Oct 28, 2026
Merged

dscpinheiro merged 2 commits into
aws:developmentfrom
martincostello:logger-lookup-trims

Conversation

@martincostello

Copy link
Copy Markdown
Contributor

Description

Split out of #4566 as requested.

Two small per-request trims in logging:

  • Logger.GetLogger(Type) wrapped a ConcurrentDictionary lookup in a lock on every call. The dictionary already synchronizes, so the lookup now uses GetOrAdd and no longer serializes every caller on the hot path.
  • AWSSDKUtils.CanonicalizeResourcePathV2 built the arguments for a debug message on every signed request, including a string concatenation of the endpoint, even though no debug logger is normally attached. A new internal Logger.IsEnabled(SdkLogLevel) check gates that work.

Motivation and Context

Profiling showed Logger.GetLogger (with its lock) and the debug-argument construction on the signing path of every request. On their own the two trims are below the noise floor of a single-threaded harness, so this PR is best read as a cleanup that removes a lock from a hot path rather than a measured throughput win; the lock removal matters more under concurrent load, which the harness does not exercise.

Measured with a mocked-HTTP harness (no network) that drives a full client call through the pipeline: branch vs development (9ab8dcf), three interleaved baseline/branch rounds of 20 × 2000 operations after a 6 s warm-up, process pinned to the P-cores of an i7-13700H, .NET 10 runtime against the net8.0 build of the SDK. Timings are the best round per side; allocations are exact (GC.GetAllocatedBytesForCurrentThread) and identical across rounds. Ratios are branch ÷ baseline.

Operation Baseline min / median / alloc Branch min / median / alloc Time ratio (min / median) Alloc ratio
DynamoDB GetItem 19.5 µs / 20.2 µs / 28.70 KB 19.9 µs / 20.4 µs / 28.70 KB 1.02 / 1.01 1.00
SQS SendMessage 16.9 µs / 17.6 µs / 26.02 KB 16.9 µs / 17.4 µs / 26.02 KB 1.00 / 0.99 1.00
S3 PutObject (40 B body) 44.8 µs / 46.2 µs / 205.36 KB 45.0 µs / 46.8 µs / 205.17 KB 1.00 / 1.01 1.00
S3 ListBuckets 31.7 µs / 33.6 µs / 48.70 KB 32.5 µs / 34.1 µs / 48.76 KB 1.03 / 1.01 1.00

The only deterministic difference is 0.19 KB less per S3 PutObject (the debug-message arguments); all timing differences are within the ±3% run-to-run noise of this machine.

Benchmark code

The harness is not checked in. It is a console project that references the SDK projects directly, replaces the HTTP client with a canned-response handler, and measures a full client call through the pipeline. Build it once from the default branch and copy bin/Release/net10.0 to CoreBench-base, then build it from the branch and run ab.sh "ddb sqs put list" 3.

CoreBench.csproj

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net10.0</TargetFramework>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>disable</Nullable>
    <LangVersion>latest</LangVersion>
    <ServerGarbageCollection>false</ServerGarbageCollection>
    <TieredPGO>true</TieredPGO>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="BenchmarkDotNet" Version="0.15.2" />
  </ItemGroup>
  <ItemGroup>
    <ProjectReference Include="D:\Coding\aws\aws-sdk-net\sdk\src\Core\AWSSDK.Core.NetStandard.csproj" />
    <ProjectReference Include="D:\Coding\aws\aws-sdk-net\sdk\src\Services\DynamoDBv2\AWSSDK.DynamoDBv2.NetStandard.csproj" />
    <ProjectReference Include="D:\Coding\aws\aws-sdk-net\sdk\src\Services\S3\AWSSDK.S3.NetStandard.csproj" />
    <ProjectReference Include="D:\Coding\aws\aws-sdk-net\sdk\src\Services\SQS\AWSSDK.SQS.NetStandard.csproj" />
  </ItemGroup>
</Project>

Benchmarks.cs

using Amazon;
using Amazon.DynamoDBv2;
using Amazon.DynamoDBv2.Model;
using Amazon.Runtime;
using Amazon.S3;
using Amazon.S3.Model;
using Amazon.SQS;
using Amazon.SQS.Model;
using BenchmarkDotNet.Attributes;

namespace CoreBench;

[MemoryDiagnoser]
public class PipelineBenchmarks
{
    private AmazonDynamoDBClient _ddb;
    private AmazonS3Client _s3;
    private AmazonSQSClient _sqs;
    private GetItemRequest _getItem;
    private PutObjectRequest _putObject;
    private ListBucketsRequest _listBuckets;
    private SendMessageRequest _sendMessage;

    [GlobalSetup]
    public void Setup()
    {
        var creds = new BasicAWSCredentials("AKIAIOSFODNN7EXAMPLE", "wJalrXUtnFEMI/K7MDENG/bPxRfiCYEXAMPLEKEY");
        var factory = new MockHttpClientFactory();
        _ddb = new AmazonDynamoDBClient(creds, new AmazonDynamoDBConfig { RegionEndpoint = RegionEndpoint.USEast1, HttpClientFactory = factory });
        _s3 = new AmazonS3Client(creds, new AmazonS3Config { RegionEndpoint = RegionEndpoint.USEast1, HttpClientFactory = factory });
        _sqs = new AmazonSQSClient(creds, new AmazonSQSConfig { RegionEndpoint = RegionEndpoint.USEast1, HttpClientFactory = factory });

        _getItem = new GetItemRequest
        {
            TableName = "BenchmarkTable",
            Key = new Dictionary<string, AttributeValue>
            {
                ["pk"] = new AttributeValue { S = "id-1" },
                ["sk"] = new AttributeValue { S = "sort-1" },
            },
            ConsistentRead = true,
        };
        _putObject = new PutObjectRequest
        {
            BucketName = "my-bucket",
            Key = "some/key.txt",
            ContentBody = "hello world, this is a small object body",
            ContentType = "text/plain",
        };
        _listBuckets = new ListBucketsRequest();
        _sendMessage = new SendMessageRequest
        {
            QueueUrl = "https://sqs.us-east-1.amazonaws.com/123456789012/my-queue",
            MessageBody = MockHttpMessageHandler.SqsBody,
        };

        // warm once to fail fast on bad mock wiring
        DynamoGetItem().GetAwaiter().GetResult();
        S3PutObject().GetAwaiter().GetResult();
        S3ListBuckets().GetAwaiter().GetResult();
        SqsSendMessage().GetAwaiter().GetResult();
    }

    [Benchmark] public Task<GetItemResponse> DynamoGetItem() => _ddb.GetItemAsync(_getItem);
    [Benchmark] public Task<PutObjectResponse> S3PutObject() => _s3.PutObjectAsync(_putObject);
    [Benchmark] public PutObjectResponse S3PutObjectSync() => _s3.PutObjectAsync(_putObject).GetAwaiter().GetResult();
    [Benchmark] public Task<ListBucketsResponse> S3ListBuckets() => _s3.ListBucketsAsync(_listBuckets);
    [Benchmark] public Task<SendMessageResponse> SqsSendMessage() => _sqs.SendMessageAsync(_sendMessage);
}

MockHttp.cs

using System.Net;
using System.Security.Cryptography;
using System.Text;
using Amazon.Runtime;

namespace CoreBench;

public sealed class MockHttpClientFactory : HttpClientFactory
{
    public override HttpClient CreateHttpClient(IClientConfig clientConfig)
        => new HttpClient(new MockHttpMessageHandler(), disposeHandler: true);

    public override bool UseSDKHttpClientCaching(IClientConfig clientConfig) => true;
}

public sealed class MockHttpMessageHandler : HttpMessageHandler
{
    public const string SqsBody = "hello world";
    public static readonly byte[] DdbGetItemBytes = Encoding.UTF8.GetBytes(
        "{\"Item\":{\"pk\":{\"S\":\"id-1\"},\"sk\":{\"S\":\"sort-1\"},\"payload\":{\"S\":\"" + new string('a', 256) + "\"},\"count\":{\"N\":\"42\"},\"flag\":{\"BOOL\":true}}}");
    private static readonly byte[] SqsSendMessage = Encoding.UTF8.GetBytes(
        "{\"MD5OfMessageBody\":\"" + Convert.ToHexString(MD5.HashData(Encoding.UTF8.GetBytes(SqsBody))).ToLowerInvariant() + "\",\"MessageId\":\"5fea7756-0ea4-451a-a703-a558b933e274\"}");
    private static readonly byte[] S3ListBuckets = Encoding.UTF8.GetBytes(
        "<?xml version=\"1.0\" encoding=\"UTF-8\"?><ListAllMyBucketsResult xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\"><Owner><ID>abc</ID><DisplayName>me</DisplayName></Owner><Buckets><Bucket><Name>bucket-a</Name><CreationDate>2020-01-01T00:00:00.000Z</CreationDate></Bucket><Bucket><Name>bucket-b</Name><CreationDate>2020-01-02T00:00:00.000Z</CreationDate></Bucket></Buckets></ListAllMyBucketsResult>");
    private static readonly byte[] Empty = Array.Empty<byte>();

    protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        var host = request.RequestUri.Host;
        HttpResponseMessage response;
        if (host.StartsWith("dynamodb", StringComparison.Ordinal))
        {
            response = new HttpResponseMessage(HttpStatusCode.OK) { Content = new ByteArrayContent(DdbGetItemBytes) };
            response.Content.Headers.ContentType = new System.Net.Http.Headers.MediaTypeHeaderValue("application/x-amz-json-1.0");
        }
        else if (host.StartsWith("sqs", StringComparison.Ordinal))
        {
            response = new HttpResponseMessage(HttpStatusCode.OK) { Content = new ByteArrayContent(SqsSendMessage) };
            response.Content.Headers.ContentType = new System.Net.Http.Headers.MediaTypeHeaderValue("application/x-amz-json-1.0");
        }
        else if (request.Method == HttpMethod.Put)
        {
            response = new HttpResponseMessage(HttpStatusCode.OK) { Content = new ByteArrayContent(Empty) };
            response.Headers.TryAddWithoutValidation("ETag", "\"9a0364b9e99bb480dd25e1f0284c8555\"");
        }
        else
        {
            response = new HttpResponseMessage(HttpStatusCode.OK) { Content = new ByteArrayContent(S3ListBuckets) };
            response.Content.Headers.ContentType = new System.Net.Http.Headers.MediaTypeHeaderValue("application/xml");
        }
        response.Headers.TryAddWithoutValidation("x-amzn-RequestId", "0123456789abcdef");
        response.Headers.TryAddWithoutValidation("x-amz-id-2", "abcdefghijklmnopqrstuvwxyz");
        response.RequestMessage = request;
        return Task.FromResult(response);
    }
}

Program.cs

using BenchmarkDotNet.Running;
using CoreBench;

if (args.Length > 0 && args[0] == "bench")
{
    // Hybrid CPU (P + E cores): keep the process on the performance cores so the single benchmark
    // thread is not scheduled onto an efficiency core mid-run. Override with BENCH_AFFINITY (hex mask).
    var mask = Environment.GetEnvironmentVariable("BENCH_AFFINITY");
    System.Diagnostics.Process.GetCurrentProcess().ProcessorAffinity =
        (IntPtr)(mask != null ? Convert.ToInt64(mask, 16) : 0xFFF);

    // Self-contained steady-state harness: time-based warm-up (so tiered compilation settles), then
    // measures blocks and reports min / median / mean per operation plus allocated bytes per operation.
    var b = new PipelineBenchmarks();
    b.Setup();
    var which = args.Length > 1 ? args[1] : "put";
    var warmupSeconds = args.Length > 2 ? double.Parse(args[2]) : 6;
    var blocks = args.Length > 3 ? int.Parse(args[3]) : 20;
    var blockIters = args.Length > 4 ? int.Parse(args[4]) : 2000;
    Func<Task> op = which switch
    {
        "ddb" => () => b.DynamoGetItem(),
        "put" => () => b.S3PutObject(),
        "list" => () => b.S3ListBuckets(),
        "sqs" => () => b.SqsSendMessage(),
        _ => throw new ArgumentException(which),
    };
    var sw = System.Diagnostics.Stopwatch.StartNew();
    long warmIters = 0;
    while (sw.Elapsed.TotalSeconds < warmupSeconds || warmIters < 20000)
    {
        op().GetAwaiter().GetResult();
        warmIters++;
    }
    var results = new List<double>();
    long allocBefore = GC.GetAllocatedBytesForCurrentThread();
    for (int k = 0; k < blocks; k++)
    {
        var t0 = System.Diagnostics.Stopwatch.GetTimestamp();
        for (int i = 0; i < blockIters; i++) op().GetAwaiter().GetResult();
        var t1 = System.Diagnostics.Stopwatch.GetTimestamp();
        results.Add((t1 - t0) * 1_000_000.0 / System.Diagnostics.Stopwatch.Frequency / blockIters);
    }
    long allocAfter = GC.GetAllocatedBytesForCurrentThread();
    results.Sort();
    var median = results[results.Count / 2];
    var mean = results.Average();
    var allocPerOp = (allocAfter - allocBefore) / (double)(blocks * blockIters);
    Console.WriteLine($"{which,-5} min {results[0],7:F2} us  median {median,7:F2} us  mean {mean,7:F2} us  alloc {allocPerOp / 1024,7:F2} KB  (warmup {warmIters} iters)");
    return;
}

// BenchmarkDotNet (use --inProcess so the saved baseline binaries are the ones measured)
BenchmarkSwitcher.FromAssembly(typeof(PipelineBenchmarks).Assembly).Run(args);

ab.sh

#!/bin/bash
# Usage: ab.sh "<ops>" [rounds] [warmupSeconds]
# Runs the harness for the baseline build (CoreBench-base, built from the default branch)
# and the candidate build alternately, so machine noise affects both the same way.
BASE="./CoreBench-base/CoreBench.exe"
NEW="./CoreBench/bin/Release/net10.0/CoreBench.exe"
OPS="$1"; ROUNDS="${2:-2}"; WARM="${3:-6}"
for op in $OPS; do
  for r in $(seq 1 $ROUNDS); do
    for v in base new; do
      if [ $v = base ]; then exe="$BASE"; else exe="$NEW"; fi
      echo "[$v r$r] $("$exe" bench $op $WARM 20 2000 | tail -1)"
    done
  done
done

Testing

  • AWSSDK.Core.NetStandard.csproj builds for all targets with no warnings.
  • The net8.0 test target compiles but could not be executed locally (MSTest adapter/framework mismatch in this environment), so CI is the first run of that target.
  • AWSSDK.UnitTests.Core on net472, filtered to AWS4Signer and Logger: 31 passed.
  • No new tests: the logger cache keeps its behavior (ClearLoggerCache and adaptor registration still clear it) and the debug message is still emitted whenever a debug-enabled adaptor logger is registered.

Dry-runs

  • DotNet Dry-run ID: N/A (external contribution)
    • Pending
    • Completed successfully
    • Failed
  • PowerShell Dry-run ID: N/A (external contribution)
    • Pending
    • Completed successfully
    • Failed

Breaking Changes Assessment

  1. No public API changes and no behavior change: the debug message is still logged when a debug-enabled adaptor is registered, and the logger cache semantics are unchanged.
  2. Reviewer assignment is at the maintainers' discretion.

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to change)

Checklist

  • My code follows the code style of this project
  • My change requires a change to the documentation
  • I have updated the documentation accordingly
  • I have read the README document
  • I have added tests to cover my changes
  • All new and existing tests passed

License

  • I confirm that this pull request can be released under the Apache 2 license

This change was generated by AI tools (Claude Code), and reviewed by Martin Costello (@martincostello).

🤖 Generated with Claude Code

Logger.GetLogger took a lock around a ConcurrentDictionary lookup on every
call; use GetOrAdd. CanonicalizeResourcePathV2 built the arguments for a debug
message (including a string concatenation of the endpoint) on every signed
request; only build them when a debug logger is attached, via a new internal
Logger.IsEnabled check.
@martincostello
martincostello marked this pull request as ready for review October 27, 2026 10:18
@martincostello
martincostello requested review from a team as code owners October 27, 2026 10:18
@martincostello
martincostello requested review from boblodgett and peterrsongg and a balanced review from Copilot and removed request for a team October 27, 2026 10:18

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

@normj
normj requested a balanced review from Copilot October 27, 2026 16:29

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Warning

Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.

Copilot review overview

3 open issues

Review effort: Lite

Comment thread sdk/src/Core/Amazon.Runtime/Internal/Util/Logger.cs Outdated
Comment thread sdk/src/Core/Amazon.Runtime/Internal/Util/Logger.cs
Comment thread sdk/src/Core/Amazon.Util/AWSSDKUtils.cs Outdated
Apply 2/3 GitHub Copilot feedback suggestions.
@jnunn-aws
jnunn-aws self-requested a review October 27, 2026 17:59

@peterrsongg peterrsongg left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

looks good. thanks for the PR!

@peterrsongg

Copy link
Copy Markdown
Contributor

Internal build kicked off: 06086ecb-2cc5-464e-b4fc-8ba16b480ae0

@dscpinheiro

Copy link
Copy Markdown
Contributor

Thanks for the contribution again, will merge it once the GitHub action runs and it'll be included in tomorrow's release.

Also, if you're curious these are the benchmarks we set up: https://github.com/aws/aws-sdk-net/tree/main/sdk/test/Performance/SerdeBenchmarks (they're a bit more complex than "normal" BenchmarkDotNet but allow us to compare with other SDK languages).

@dscpinheiro
dscpinheiro merged commit b95d020 into aws:development Oct 28, 2026
5 checks passed
@martincostello
martincostello deleted the logger-lookup-trims branch October 29, 2026 06:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants