S3 crt client timeouts and retry strategy are not working.

[Manjunathagopi]

Describe the bug

Below mentioned s3 crt client configs we set.

Aws::S3Crt::S3CrtClient *s3_crt_client;
Aws::S3Crt::Model::GetObjectRequest object_request;
Aws::SDKOptions options;
Aws::InitAPI(options);
Aws::S3Crt::ClientConfiguration config;
config.throughputTargetGbps = 1;
config.partSize = 10*1024*1024;
config.httpRequestTimeoutMs = 100;
config.connectTimeoutMs = 100;
config.requestTimeoutMs = 100;  
s3_crt_client = Aws::New<Aws::S3Crt::S3CrtClient>("test", config); 

We are reading 25MB at a time and we are measuring how much time it is taking for getObject.
average of 500ms taken for each getObject
Even though we set all the timeouts s3 crt client is taking more time?
We even tried with no retry strategy, but still there is no use and the behaviour is same.

  config.httpRequestTimeoutMs = 100;
  config.connectTimeoutMs = 100;
  config.requestTimeoutMs = 100;  
  std::shared_ptr<Aws::Client::RetryStrategy> retry;
  retry.reset(Aws::New<Aws::Client::DefaultRetryStrategy>("test", 0, 25));
  config.retryStrategy = retry;

GetObject() is not exiting even timeout is reached. One time we saw GetObject() for size 25MB took 10seconds.
Basically behavior is same even if we didn't set timeouts or assign custom retry strategy.
we are running this in a c5a4x large instance which is running in ap-south-1 region and s3 bucket is also in the same region and account.
Please tell whats wrong with this and suggest how to reduce time taken for GetObject().

Expected Behavior

With zero retries GetObject should exit once timeout is reached.

Current Behavior

With zero retries GetObject is not exiting even timeout is reached.

Reproduction Steps

zero retries

#include <fcntl.h>
#include <unistd.h>


#include <aws/core/Aws.h>
#include <aws/core/client/DefaultRetryStrategy.h>
#include <aws/s3-crt/S3CrtClient.h>
#include <aws/s3-crt/model/HeadObjectRequest.h>
#include <aws/s3-crt/model/GetObjectRequest.h>
#include <aws/s3-crt/S3CrtErrors.h>

void usage(const char *bin)
{
    printf("USAGE: %s <s3_uri> <part_size(in bytes)> <out_file(optional)>\n", bin);
}

uint64_t get_curr_time_ms(void)
{
    struct  timespec   ts;
    uint64_t           ts_64;
    clock_gettime(CLOCK_MONOTONIC, &ts);
    ts_64 = (uint64_t)((ts.tv_sec * 1000) + (ts.tv_nsec/1000000));
    return ts_64;
}

int main (int argc, char* argv[])
{
    char *s3_uri;
    uint64_t read_size = UINT64_MAX;
    uint64_t part_size;
    char *buf = NULL;
    uint64_t read_left;
    uint64_t to_read;
    uint64_t ret;
    uint64_t iter = 0;
    char *out_file = NULL;
    int out_fd = -1;

    if(argc < 5 || argc > 6)
    {
        usage(argv[0]);
        return 0;
    }

    s3_uri = argv[1];
    part_size = strtoull(argv[2], NULL, 10);
    if(argc == 6) out_file = argv[3];
    Aws::S3Crt::S3CrtClient *s3_crt_client;
    Aws::S3Crt::Model::GetObjectRequest object_request;
    Aws::SDKOptions options;
    Aws::InitAPI(options);
    Aws::S3Crt::ClientConfiguration config;
    config.httpRequestTimeoutMs = 100;
    config.connectTimeoutMs = 100;
    config.requestTimeoutMs = 100;  
    std::shared_ptr<Aws::Client::RetryStrategy> retry;
    retry.reset(Aws::New<Aws::Client::DefaultRetryStrategy>("test", 0, 25));
    config.retryStrategy = retry;
    config.throughputTargetGbps = 1;
    config.partSize = 10*1024*1024;
    s3_crt_client = Aws::New<Aws::S3Crt::S3CrtClient>("test", config);

    char bucket[128] = {0};
    char key[128] = {0};
    if(sscanf(s3_uri, "s3://%[^/]/%s", bucket, key) == 2)
    {
        Aws::S3Crt::Model::HeadObjectRequest head_object_request;
        Aws::S3Crt::Model::HeadObjectOutcome outcome;
        head_object_request.SetBucket(bucket);
        head_object_request.SetKey(key);
        outcome = s3_crt_client->HeadObject(head_object_request);
        if(outcome.IsSuccess())
            printf("Object found, size:%lu, etag %s\n", outcome.GetResult().GetContentLength(),  outcome.GetResult().GetETag().c_str());
        object_request.SetBucket(bucket);
        object_request.SetKey(key);
    }

    if(out_file)
    {
        out_fd = open(out_file, O_CREAT | O_WRONLY);
        if(out_fd <= 2)
        {
            printf("Error in opening %s in write mode", out_file);
            return 0;
        }
    }
    int64_t pos = 0;

    buf = new char[part_size];
    read_left = read_size;
    while(read_left != 0)
    {
        ret = 0;
        int64_t retry_count = -1;
        to_read = part_size <= read_left ? part_size : read_left;
        iter ++;
        uint64_t start,end;
        Aws::S3Crt::Model::GetObjectOutcome outcome;
        object_request.SetRange(std::string("bytes=") + std::to_string(pos) + "-" + std::to_string(pos+to_read-1));
        object_request.SetResponseStreamFactory(
                [buf, to_read]()
                {
                std::unique_ptr<Aws::StringStream>
                stream(Aws::New<Aws::StringStream>("test"));
                stream->rdbuf()->pubsetbuf(static_cast<char*>(buf),
                        to_read);

                return stream.release();
                });
        start = get_curr_time_ms();
        outcome = s3_crt_client->GetObject(object_request);
        end = get_curr_time_ms();
        printf("Time taken for GetObject %lums\n",end-start);
        if(outcome.IsSuccess())
        {
            ret = outcome.GetResult().GetContentLength();

            if(ret <= to_read)
            {
                pos += ret;
                //log_info("Testing data %02x %02x", ((uint8_t*)buf)[0], ((uint8_t*)buf)[1]);
            }
            else
            {
                printf("This should never happen, pos_:%lu, requested:%lu, read:%lu\n",
                        pos, to_read, ret);
                break;
            }
        }
        else
        {
            printf("Failed to read, pos_:%lu, requested:%lu, error:%s, error_type:%d, error_code:%d\n",
                    pos, to_read, outcome.GetError().GetMessage().c_str(), outcome.GetError().GetErrorType(), outcome.GetError().GetResponseCode()) ;
            break;
        }
        if(ret == 0)
        {
            printf("Nothing read, read_left:%lubytes, iter:%lu\n", read_left, iter);
            break;
        }
        else if(ret < to_read)
        {
            printf("Read %ldbytes instead of %ldbytes, iter:%lu\n", ret, to_read, iter);
        }
        else
        {
            printf("Read %ld bytes, iter:%lu\n", ret, iter);
        }
        read_left -= ret;

        if(ret > 0 && out_fd > 2)
        {
            if(write(out_fd, buf, ret) != ret)
            {
                printf("Error in write!!! (%lu bytes)\n", ret);
                return 0;
            }
            fdatasync(out_fd);
        }
    }

    if(s3_crt_client)
    {
        Aws::Delete(s3_crt_client);
        s3_crt_client = NULL;
    }
    Aws::ShutdownAPI(options);

    if(buf) delete[] buf;
    if(out_fd > 2) close(out_fd);
    return 0;
}

default strategy

#include <fcntl.h>
#include <unistd.h>


#include <aws/core/Aws.h>
#include <aws/core/client/DefaultRetryStrategy.h>
#include <aws/s3-crt/S3CrtClient.h>
#include <aws/s3-crt/model/HeadObjectRequest.h>
#include <aws/s3-crt/model/GetObjectRequest.h>
#include <aws/s3-crt/S3CrtErrors.h>

void usage(const char *bin)
{
    printf("USAGE: %s <s3_uri> <offset in bytes> <read size(0->till end)> <part_size(in bytes)> <out_file(optional)>\n", bin);
}

uint64_t get_curr_time_ms(void)
{
    struct  timespec   ts;
    uint64_t           ts_64;
    clock_gettime(CLOCK_MONOTONIC, &ts);
    ts_64 = (uint64_t)((ts.tv_sec * 1000) + (ts.tv_nsec/1000000));
    return ts_64;
}

int main (int argc, char* argv[])
{
    char *s3_uri;
    uint64_t offset;
    uint64_t read_size;
    uint64_t part_size;
    char *buf = NULL;
    uint64_t read_left;
    uint64_t to_read;
    uint64_t ret;
    uint64_t iter = 0;
    char *out_file = NULL;
    int out_fd = -1;

    if(argc < 5 || argc > 6)
    {
        usage(argv[0]);
        return 0;
    }

    s3_uri = argv[1];
    offset = strtoull(argv[2], NULL, 10);
    read_size = strtoull(argv[3], NULL, 10);
    if(read_size == 0) read_size = UINT64_MAX;
    part_size = strtoull(argv[4], NULL, 10);
    if(argc == 6) out_file = argv[5];
    Aws::S3Crt::S3CrtClient *s3_crt_client;
    Aws::S3Crt::Model::GetObjectRequest object_request;
    Aws::SDKOptions options;
    Aws::InitAPI(options);
    Aws::S3Crt::ClientConfiguration config;
    config.httpRequestTimeoutMs = 100;
    config.connectTimeoutMs = 100;
    config.requestTimeoutMs = 100;  
    config.throughputTargetGbps = 1;
    config.partSize = 10*1024*1024;
    s3_crt_client = Aws::New<Aws::S3Crt::S3CrtClient>("test", config);

    char bucket[128] = {0};
    char key[128] = {0};
    if(sscanf(s3_uri, "s3://%[^/]/%s", bucket, key) == 2)
    {
        Aws::S3Crt::Model::HeadObjectRequest head_object_request;
        Aws::S3Crt::Model::HeadObjectOutcome outcome;
        head_object_request.SetBucket(bucket);
        head_object_request.SetKey(key);
        outcome = s3_crt_client->HeadObject(head_object_request);
        if(outcome.IsSuccess())
            printf("Object found, size:%lu, etag %s\n", outcome.GetResult().GetContentLength(),  outcome.GetResult().GetETag().c_str());
        object_request.SetBucket(bucket);
        object_request.SetKey(key);
    }

    if(out_file)
    {
        out_fd = open(out_file, O_CREAT | O_WRONLY);
        if(out_fd <= 2)
        {
            printf("Error in opening %s in write mode", out_file);
            return 0;
        }
    }
    int64_t pos = 0;

    buf = new char[part_size];
    read_left = read_size;
    while(read_left != 0)
    {
        ret = 0;
        int64_t retry_count = -1;
        to_read = part_size <= read_left ? part_size : read_left;
        iter ++;
        uint64_t start,end;
        Aws::S3Crt::Model::GetObjectOutcome outcome;
        object_request.SetRange(std::string("bytes=") + std::to_string(pos) + "-" + std::to_string(pos+to_read-1));
        object_request.SetResponseStreamFactory(
                [buf, to_read]()
                {
                std::unique_ptr<Aws::StringStream>
                stream(Aws::New<Aws::StringStream>("test"));
                stream->rdbuf()->pubsetbuf(static_cast<char*>(buf),
                        to_read);

                return stream.release();
                });
        start = get_curr_time_ms();
        outcome = s3_crt_client->GetObject(object_request);
        end = get_curr_time_ms();
        printf("Time taken for GetObject %lums\n",end-start);
        if(outcome.IsSuccess())
        {
            ret = outcome.GetResult().GetContentLength();

            if(ret <= to_read)
            {
                pos += ret;
                //log_info("Testing data %02x %02x", ((uint8_t*)buf)[0], ((uint8_t*)buf)[1]);
            }
            else
            {
                printf("This should never happen, pos_:%lu, requested:%lu, read:%lu\n",
                        pos, to_read, ret);
                break;
            }
        }
        else
        {
            printf("Failed to read, pos_:%lu, requested:%lu, error:%s, error_type:%d, error_code:%d\n",
                    pos, to_read, outcome.GetError().GetMessage().c_str(), outcome.GetError().GetErrorType(), outcome.GetError().GetResponseCode()) ;
            break;
        }
        if(ret == 0)
        {
            printf("Nothing read, read_left:%lubytes, iter:%lu\n", read_left, iter);
            break;
        }
        else if(ret < to_read)
        {
            printf("Read %ldbytes instead of %ldbytes, iter:%lu\n", ret, to_read, iter);
        }
        else
        {
            printf("Read %ld bytes, iter:%lu\n", ret, iter);
        }
        read_left -= ret;

        if(ret > 0 && out_fd > 2)
        {
            if(write(out_fd, buf, ret) != ret)
            {
                printf("Error in write!!! (%lu bytes)\n", ret);
                return 0;
            }
            fdatasync(out_fd);
        }
    }

    if(s3_crt_client)
    {
        Aws::Delete(s3_crt_client);
        s3_crt_client = NULL;
    }
    Aws::ShutdownAPI(options);

    if(buf) delete[] buf;
    if(out_fd > 2) close(out_fd);
    return 0;
}

Possible Solution

No response

Additional Information/Context

No response

AWS CPP SDK version used

1.11.269

Compiler and Version used

gcc (GCC) 4.8.5

Operating System and version

CentOS Linux and version 7

[DmitriyMusatkin]

CRT retries and timeouts work differently from regular CPP SDK config option and CRT S3 client currently does not honor them. We have a backlog feature request here to improve the situation #2594.

As an alternative you can configure lowSpeedLimit to indicate to CRT to kill requests that are too slow.

[Manjunathagopi]

Hi @DmitriyMusatkin, i tried setting lowSpeedLimit to 75MBps which will kill the requests that are below 75MBps and tried running the test.
Still some requests were taking around 1second to read 25MB(bitrate of around 27MBps) from s3.

Aws::S3Crt::ClientConfiguration config;
config.lowSpeedLimit = 78643200; 

[Manjunathagopi]

Hi,
Any update on the above query?

[DmitriyMusatkin]

the way low speed limit is configured in sdk is to kill connection if throughput dips under the specified number for a given number of intervals (3 by default and otherwise derived from request timeout) - https://github.com/aws/aws-sdk-cpp/blob/main/generated/src/aws-cpp-sdk-s3-crt/source/S3CrtClient.cpp#L330.

Hard to tell exactly, whats going on and we might need trace level logs to debug it further. Note: CRT already breaks up get requests into part requests based on the configured part size and your code does the same thing, so there might be something weird interaction between the 2 going on.

[Manjunathagopi]

Hi @DmitriyMusatkin attaching the trace logs for this can you please check this?

Uploading aws_sdk_2024-06-04-11.log…

[DmitriyMusatkin]

bad link? it just points to this issue

[Manjunathagopi]

Sorry @DmitriyMusatkin here it is aws_sdk_2024-06-04-11.log