RanVaknin
commented
11 months ago Hi @adityachandla ,
Thanks for opening this issue and for the detailed analysis. Are you seeing any explicit server errors after the 10,000 request mark? I would try enabling the logger to see if there are any obvious patterns you can see from the raw request /response.
cfg, err := config.LoadDefaultConfig(context.TODO(), config.WithRegion("eu-west-1"), config.WithClientLogMode(aws.LogRequestWithBody|aws.LogResponseWithBody))I assume that 10,000 invocations would produce lots of logs, so I would be mindful of any financial implications if you are storing logs from the applications context.
As it stands, while interesting, the data is not really actionable for now. We need to understand where the bulk of the delay is happening, distinguishing between the time spent in the overall operation and the time spent on the HTTP call itself.
Here is an example of a probe @lucix-aws put together to help us better understand the nature of the delay. Can you integrate this example into your use case and share the result with us?
package main
import (
"context"
"fmt"
"log"
"net/http"
"sync"
"time"
awsmiddleware "github.com/aws/aws-sdk-go-v2/aws/middleware"
awshttp "github.com/aws/aws-sdk-go-v2/aws/transport/http"
"github.com/aws/aws-sdk-go-v2/config"
"github.com/aws/aws-sdk-go-v2/service/sqs"
"github.com/aws/smithy-go/middleware"
smithyrand "github.com/aws/smithy-go/rand"
)
// WithOperationTiming instruments an SQS client to dump timing information for
// the following spans:
// - overall operation time
// - HTTPClient call time
//
// This instrumentation will also emit the request ID, service name, and
// operation name for each invocation.
//
// Accepts a message "handler" which is invoked with formatted messages to be
// handled externally, you can use the declared PrintfMSGHandler to simply dump
// these values to stdout.
func WithOperationTiming(msgHandler func(string)) func(*sqs.Options) {
return func(o *sqs.Options) {
o.APIOptions = append(o.APIOptions, addTimingMiddlewares(msgHandler))
o.HTTPClient = &timedHTTPClient{
client: awshttp.NewBuildableClient(),
msgHandler: msgHandler,
}
}
}
// PrintfMSGHandler writes messages to stdout.
func PrintfMSGHandler(msg string) {
fmt.Printf("%s\n", msg)
}
type invokeIDKey struct{}
func setInvokeID(ctx context.Context, id string) context.Context {
return middleware.WithStackValue(ctx, invokeIDKey{}, id)
}
func getInvokeID(ctx context.Context) string {
id, _ := middleware.GetStackValue(ctx, invokeIDKey{}).(string)
return id
}
func timeSpan(ctx context.Context, name string, consumer func(string)) func() {
start := time.Now()
return func() {
elapsed := time.Now().Sub(start)
consumer(fmt.Sprintf("[%s] %s: %s", getInvokeID(ctx), name, elapsed))
}
}
type timedHTTPClient struct {
client *awshttp.BuildableClient
msgHandler func(string)
}
func (c *timedHTTPClient) Do(r *http.Request) (*http.Response, error) {
defer timeSpan(r.Context(), "http", c.msgHandler)()
resp, err := c.client.Do(r)
if err != nil {
return nil, fmt.Errorf("inner client do: %v", err)
}
return resp, nil
}
type addInvokeIDMiddleware struct {
msgHandler func(string)
}
func (*addInvokeIDMiddleware) ID() string { return "addInvokeID" }
func (*addInvokeIDMiddleware) HandleInitialize(ctx context.Context, in middleware.InitializeInput, next middleware.InitializeHandler) (
out middleware.InitializeOutput, md middleware.Metadata, err error,
) {
id, err := smithyrand.NewUUID(smithyrand.Reader).GetUUID()
if err != nil {
return out, md, fmt.Errorf("new uuid: %v", err)
}
return next.HandleInitialize(setInvokeID(ctx, id), in)
}
type timeOperationMiddleware struct {
msgHandler func(string)
}
func (*timeOperationMiddleware) ID() string { return "timeOperation" }
func (m *timeOperationMiddleware) HandleInitialize(ctx context.Context, in middleware.InitializeInput, next middleware.InitializeHandler) (
middleware.InitializeOutput, middleware.Metadata, error,
) {
defer timeSpan(ctx, "operation", m.msgHandler)()
return next.HandleInitialize(ctx, in)
}
type emitMetadataMiddleware struct {
msgHandler func(string)
}
func (*emitMetadataMiddleware) ID() string { return "emitMetadata" }
func (m *emitMetadataMiddleware) HandleInitialize(ctx context.Context, in middleware.InitializeInput, next middleware.InitializeHandler) (
middleware.InitializeOutput, middleware.Metadata, error,
) {
out, md, err := next.HandleInitialize(ctx, in)
invokeID := getInvokeID(ctx)
requestID, _ := awsmiddleware.GetRequestIDMetadata(md)
service := awsmiddleware.GetServiceID(ctx)
operation := awsmiddleware.GetOperationName(ctx)
m.msgHandler(fmt.Sprintf(`[%s] requestID = "%s"`, invokeID, requestID))
m.msgHandler(fmt.Sprintf(`[%s] service = "%s"`, invokeID, service))
m.msgHandler(fmt.Sprintf(`[%s] operation = "%s"`, invokeID, operation))
return out, md, err
}
func addTimingMiddlewares(mh func(string)) func(*middleware.Stack) error {
return func(s *middleware.Stack) error {
if err := s.Initialize.Add(&timeOperationMiddleware{msgHandler: mh}, middleware.Before); err != nil {
return fmt.Errorf("add time operation middleware: %v", err)
}
if err := s.Initialize.Add(&addInvokeIDMiddleware{msgHandler: mh}, middleware.Before); err != nil {
return fmt.Errorf("add invoke id middleware: %v", err)
}
if err := s.Initialize.Insert(&emitMetadataMiddleware{msgHandler: mh}, "RegisterServiceMetadata", middleware.After); err != nil {
return fmt.Errorf("add emit metadata middleware: %v", err)
}
return nil
}
}
func main() {
cfg, err := config.LoadDefaultConfig(context.Background())
if err != nil {
log.Fatal(fmt.Errorf("load default config: %v", err))
}
svc := sqs.NewFromConfig(cfg, WithOperationTiming(PrintfMSGHandler))
var wg sync.WaitGroup
for i := 0; i < 6; i++ {
wg.Add(1)
go func() {
defer wg.Done()
_, err = svc.ListQueues(context.Background(), nil)
if err != nil {
fmt.Println(fmt.Errorf("list queues: %v", err))
}
}()
}
wg.Wait()
}Thank you very much, Ran~
adityachandla
lucix-aws
github-actions[bot]
Describe the bug
I am performing a benchmark wherein I am fetching a byte range of an S3 object. This benchmark takes in the number of goroutines that will concurrently be fetching some bytes, the size of the byte range and the number of runs that each goroutine will perform.
This benchmark was performed on a c7gn.2xlarge instance in Ireland and the S3 bucket is also present in the same region.
Expected Behavior
When I run the benchmark, I expect to get latency times that are similar to the latency times on cloudwatch's S3 request metrics. This is indeed what I get when I fetch 512 bytes with 20 goroutines 1000 times each, this is the graph for the latency:
And this is the total request latency in cloudwatch:
The request latency that I observe is more but not by that much and this is fine. However, something wierd happens when I change the fetch range from 512 bytes to 512 kilobytes.
Current Behavior
When I run the same benchmark with 512 kilobytes, 20 goroutines, each fetching the byte range 1000 times each, I see the following graph:
As you can see, after around 10k requests, the latency increases drastically for some requests. However, according to the cloudwatch metrics, it was more or less constant:
I have repeated this benchmark multiple times and at exactly 10k requests, I start to see this clustering of requests into higher latency buckets as can be seen in the graph.
Only two things can happen between the
startandendtime, garbage collection and execution of SDK code. The former does not appear to be the problem as I have ran this benchmark with GOGC=500 and GOMEMLIMIT=4096MiB and got almost the same result. This leads me to believe that there is something happening in the SDK that is causing this behaviour.Reproduction Steps
I am running the code on a c7gn.2xlarge instance and on a 128MB file that is in an S3 bucket in the same region as the EC2 instance.
Possible Solution
No response
Additional Information/Context
I have already checked the following things:
AWS Go SDK V2 Module Versions Used
Compiler and Version used
go version go1.20.4 linux/amd64
Operating System and version
ubuntu 23.04