Skip to content

sdk's deep call stacks (>128 frames) render Go's profiling tools unhelpful #3099

Closed
Closed
sdk's deep call stacks (>128 frames) render Go's profiling tools unhelpful#3099
@rhysh

Description

@rhysh
rhysh
opened on May 28, 2025

Acknowledgements

Describe the bug

aws-sdk-go-v2 is built with many layers of middleware. The middleware is structured as nested function calls. By the time the SDK has an HTTP request ready to send over the network (s3.GetObject for example, without extra configuration), it's added about 120 functions to the active call stack. The net/http package adds about 8 more.

Go's built-in tools for profiling and execution tracing have limits on how much of the call stack they'll look at. One (the CPU profiler) looks at 64 frames, and the others (without extra configuration, where possible) will look at 128 frames.

When Go apps that use aws-sdk-go-v2 do things that warrant an entry in those profiles (use CPU, allocate memory, wait for data from the network, etc), the SDK itself often fills the entirety of the call stack with its own functions. That doesn't leave any available for describing which part of the SDK user's application is responsible for the cost.

Regression Issue

  • Select this option if this issue appears to be a regression.

Expected Behavior

The SDK should be more frugal with the frames it puts on the function call stack. It should put fewer than 100 nested function calls on the stack. Better would be to get it below 50 (for the CPU profiler to work). It should not waste frames with github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize (and similar) calls.

The entry point to the SDK (such as github.com/aws/aws-sdk-go-v2/service/s3.(*Client).GetObject) should be visible on the call stack of the heap profile, goroutine profiles, execution tracer, etc.

Multiple frames of the caller of the SDK should be visible with those tools.

Current Behavior

The call stacks in Go apps that use aws-sdk-go-v2 are so deep that Go's built-in observability/diagnostic tools have no choice but to truncate them (to around 128 frames). Below is a call stack from an execution trace from a real production app. It includes 116 visible frames, and the root-most visible frame is something inside the AWS SDK, rather than the name of a function that was passed to the go keyword. The application appears to be using github.com/aws/aws-sdk-go-v2/service/[email protected], github.com/aws/[email protected], and github.com/aws/[email protected]

Several of the function names are from the github.com/aws/aws-sdk-go-v2/service/s3 package, so it's clear enough which AWS service the app is using. One of the function names is github.com/aws/aws-sdk-go-v2/service/s3.(*awsRestxml_serializeOpGetObject).HandleSerialize, so with a keen eye it's possible to get the name of the method (GetObject) that the app is invoking on that service.

But there's no context on which part of the app is responsible for calling into the AWS SDK.

runtime.chansend1
net/http.(*persistConn).roundTrip
net/http.(*Transport).roundTrip
net/http.(*Transport).RoundTrip
github.com/aws/aws-sdk-go-v2/aws/transport/http.suppressBadHTTPRedirectTransport.RoundTrip
net/http.send
net/http.(*Client).send
net/http.(*Client).do
net/http.(*Client).Do
github.com/aws/aws-sdk-go-v2/aws/transport/http.(*BuildableClient).Do
github.com/aws/smithy-go/transport/http.(*timedClientDo).Do
github.com/aws/smithy-go/transport/http.ClientHandler.Handle
github.com/aws/smithy-go/middleware.deserializeWrapHandler.HandleDeserialize
github.com/aws/smithy-go/transport/http.(*RequestResponseLogger).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/service/internal/checksum.(*validateOutputPayloadChecksum).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/aws/middleware.RecordResponseTiming.HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/internal/middleware.(*AddTimeOffsetMiddleware).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/service/s3.(*awsRestxml_deserializeOpGetObject).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/service/internal/s3shared.(*metadataRetriever).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/service/internal/s3shared.(*errorWrapper).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/smithy-go/transport/http.(*errorCloseResponseBodyMiddleware).HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/aws-sdk-go-v2/aws/middleware.AddRawResponse.HandleDeserialize
github.com/aws/smithy-go/middleware.decoratedDeserializeHandler.HandleDeserialize
github.com/aws/smithy-go/middleware.(*DeserializeStep).HandleMiddleware
github.com/aws/smithy-go/middleware.decoratedHandler.Handle
github.com/aws/smithy-go/middleware.finalizeWrapHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*signRequestMiddleware).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*setLegacyContextSigningOptionsMiddleware).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/aws/retry.MetricsHeader.HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/aws/retry.(*Attempt).handleAttempt
github.com/aws/aws-sdk-go-v2/aws/retry.(*Attempt).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*spanRetryLoop).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/aws/signer/v4.(*ContentSHA256Header).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/aws/signer/v4.(*ComputePayloadSHA256).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*disableHTTPSMiddleware).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*resolveEndpointV2Middleware).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*getIdentityMiddleware).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/s3.(*resolveAuthSchemeMiddleware).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/aws-sdk-go-v2/service/internal/accept-encoding.(*DisableGzip).HandleFinalize
github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize
github.com/aws/smithy-go/middleware.(*FinalizeStep).HandleMiddleware
github.com/aws/smithy-go/middleware.decoratedHandler.Handle
github.com/aws/smithy-go/middleware.buildWrapHandler.HandleBuild
github.com/aws/aws-sdk-go-v2/service/s3.(*spanBuildRequestEnd).HandleBuild
github.com/aws/smithy-go/middleware.decoratedBuildHandler.HandleBuild
github.com/aws/aws-sdk-go-v2/aws/middleware.(*RecursionDetection).HandleBuild
github.com/aws/smithy-go/middleware.decoratedBuildHandler.HandleBuild
github.com/aws/aws-sdk-go-v2/internal/middleware.AddTimeOffsetMiddleware.HandleBuild
github.com/aws/smithy-go/middleware.decoratedBuildHandler.HandleBuild
github.com/aws/aws-sdk-go-v2/aws/middleware.(*RequestUserAgent).HandleBuild
github.com/aws/smithy-go/middleware.decoratedBuildHandler.HandleBuild
github.com/aws/smithy-go/transport/http.(*ComputeContentLength).HandleBuild
github.com/aws/smithy-go/middleware.decoratedBuildHandler.HandleBuild
github.com/aws/aws-sdk-go-v2/aws/middleware.ClientRequestID.HandleBuild
github.com/aws/smithy-go/middleware.decoratedBuildHandler.HandleBuild
github.com/aws/smithy-go/middleware.(*BuildStep).HandleMiddleware
github.com/aws/smithy-go/middleware.decoratedHandler.Handle
github.com/aws/smithy-go/middleware.serializeWrapHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*isExpressUserAgent).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3/internal/customizations.(*removeBucketFromPathMiddleware).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3/internal/customizations.(*updateEndpoint).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*awsRestxml_serializeOpGetObject).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*serializeImmutableHostnameBucketMiddleware).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3/internal/customizations.(*s3ObjectLambdaEndpoint).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3/internal/customizations.(*processARNResource).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*ResolveEndpoint).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*setOperationInputMiddleware).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*putBucketContextMiddleware).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/aws-sdk-go-v2/service/s3.(*spanBuildRequestStart).HandleSerialize
github.com/aws/smithy-go/middleware.decoratedSerializeHandler.HandleSerialize
github.com/aws/smithy-go/middleware.(*SerializeStep).HandleMiddleware
github.com/aws/smithy-go/middleware.decoratedHandler.Handle
github.com/aws/smithy-go/middleware.initializeWrapHandler.HandleInitialize
github.com/aws/aws-sdk-go-v2/service/s3.(*spanInitializeEnd).HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize
github.com/aws/aws-sdk-go-v2/service/s3.(*validateOpGetObject).HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize
github.com/aws/smithy-go/middleware.(*setLogger).HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize
github.com/aws/aws-sdk-go-v2/service/internal/s3shared.(*ARNLookup).HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize
github.com/aws/aws-sdk-go-v2/service/s3.(*legacyEndpointContextSetter).HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize
github.com/aws/aws-sdk-go-v2/aws/middleware.RegisterServiceMetadata.HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize
github.com/aws/aws-sdk-go-v2/service/internal/checksum.(*setupOutputContext).HandleInitialize
github.com/aws/smithy-go/middleware.decoratedInitializeHandler.HandleInitialize

Reproduction Steps

package main

import (
	"bytes"
	"context"
	"fmt"
	"net/http/httptrace"
	"runtime"
	"runtime/pprof"
	"sync"

	"github.com/aws/aws-sdk-go-v2/aws"
	"github.com/aws/aws-sdk-go-v2/service/s3"
)

func main() {
	var (
		mu    sync.Mutex
		pcs   []uintptr
		gprof bytes.Buffer
		hprof bytes.Buffer
		sink  []byte
	)

	ctx := context.Background()
	ctx, cancel := context.WithCancel(ctx)
	defer cancel()
	ctx = httptrace.WithClientTrace(ctx,
		&httptrace.ClientTrace{
			GetConn: func(hostPort string) {
				// make ourselves visible in several ways while the AWS SDK
				// functions are on the call stack

				mu.Lock()
				defer mu.Unlock()

				cancel()

				// collect the function call stack ourselves
				s := make([]uintptr, 1024)
				s = s[0:runtime.Callers(0, s)]
				pcs = s

				// take a goroutine profile
				pprof.Lookup("goroutine").WriteTo(&gprof, 1)

				// allocate some memory, then take a heap profile
				sink = make([]byte, 1<<20)
				for range 2 {
					runtime.GC() // heap profile hides recent allocations
				}
				pprof.Lookup("allocs").WriteTo(&hprof, 1)
				_ = sink
			},
		},
	)

	client := s3.New(s3.Options{Region: "us-west-2"})
	_, err := client.GetObject(ctx, &s3.GetObjectInput{
		Bucket: aws.String("foo"),
		Key:    aws.String("bar"),
	})
	if err != nil && ctx.Err() == nil {
		fmt.Printf("encountered error before GetConn callback: %v", err)
		return
	}

	frames := runtime.CallersFrames(pcs)
	var funcs []string
	for {
		frame, more := frames.Next()
		funcs = append(funcs, frame.Function)
		if !more {
			break
		}
	}

	fmt.Printf("pcs=%d funcs=%d\n", len(pcs), len(funcs))
	for _, fn := range funcs {
		fmt.Printf("%s\n", fn)
	}
	fmt.Printf("--- goroutine ---\n%s\n", gprof.String())
	fmt.Printf("--- allocs ---\n%s\n", hprof.String())
}

Possible Solution

smithy-go isn't very frugal with its call frames. In the reproducer's output, I see 12 instances of github.com/aws/smithy-go/middleware.decoratedFinalizeHandler.HandleFinalize, 11 of ...decoratedSerializeHandler.HandleSerialize, 9 of ...decoratedDeserializeHandler.HandleDeserialize, 8 each of ...decoratedInitializeHandler.HandleInitialize and ...decoratedBuildHandler.HandleBuild, and 6 of ...decoratedHandler.Handle. Eliminating those would save 54 frames, which could instead be used on putting the SDK's resource usage into context within customers' applications. That might be enough for everything but the CPU profiler (which has a limit of 64 frames).

Additional Information/Context

Below is the output of the reproducer on my machine (to be added as a comment, it's too long to post in this box). The traceback I take by hand (with runtime.Callers and a huge buffer) shows 132 return PCs and expands into 132 function calls. The manual traceback includes github.com/aws/aws-sdk-go-v2/service/s3.(*Client).GetObject (the entry point to the SDK), and main.main (representing the point within the user app that called the SDK). The allocs/heap profile has github.com/aws/aws-sdk-go-v2/service/s3.(*Client).GetObject as its root-most frame; the application doesn't appear at all. The goroutine profile has a few more functions at the leaf (within the runtime's implementation), so it shows github.com/aws/smithy-go/middleware.(*InitializeStep).HandleMiddleware as the root-most frame.

The limit for most profiles is documented as profstackdepth in https://pkg.go.dev/runtime . The limits for the execution tracer and CPU profiler are set at https://github.com/golang/go/blob/go1.24.3/src/internal/trace/event/go122/event.go#L509 and https://github.com/golang/go/blob/go1.24.3/src/runtime/cpuprof.go#L22

AWS Go SDK V2 Module Versions Used

module example.com/call-stack-depth

go 1.24

require github.com/aws/aws-sdk-go-v2/service/s3 v1.79.4

require (
github.com/aws/aws-sdk-go-v2 v1.36.3 // indirect
github.com/aws/aws-sdk-go-v2/aws/protocol/eventstream v1.6.10 // indirect
github.com/aws/aws-sdk-go-v2/internal/configsources v1.3.34 // indirect
github.com/aws/aws-sdk-go-v2/internal/endpoints/v2 v2.6.34 // indirect
github.com/aws/aws-sdk-go-v2/internal/v4a v1.3.34 // indirect
github.com/aws/aws-sdk-go-v2/service/internal/accept-encoding v1.12.3 // indirect
github.com/aws/aws-sdk-go-v2/service/internal/checksum v1.7.2 // indirect
github.com/aws/aws-sdk-go-v2/service/internal/presigned-url v1.12.15 // indirect
github.com/aws/aws-sdk-go-v2/service/internal/s3shared v1.18.15 // indirect
github.com/aws/smithy-go v1.22.3 // indirect
)

Compiler and Version used

go version go1.24.3 darwin/arm64

Operating System and version

macOS 14.5 (23F79)

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions
      ⚡