runtime/pprof: CPU profiling causes severe Scheduler Delays with Deep Context Chains

[JasonSongHoho]

Go version

go version go1.23.4 linux/amd64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/root/.cache/go-build'
GOENV='/root/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/root/go/pkg/mod'
GONOPROXY='git.garena.com'
GONOSUMDB='git.garena.com'
GOOS='linux'
GOPATH='/root/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.23.4'
GODEBUG=''
GOTELEMETRY='local'
GOTELEMETRYDIR='/root/.config/go/telemetry'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build892259413=/tmp/go-build -gno-record-gcc-switches'

What did you do?

We discovered that CPU profiling causes severe scheduler delays when combined with deep context chains, making profiling unusable in production environments with real network operations.

Reproduction steps:

1. Download reproduction program:

   # Save the attached go_profiling_issue_repro.go file 

go_profiling_issue_repro.go.zip

2. Run with CPU profiling + ZooKeeper (demonstrates severe issue):

   go run go_profiling_issue_repro.go -maxprocs=4 -enable-zk=true -enable-profiling=true -context-depth=10000000

3. Run without CPU profiling (normal behavior):

   go run go_profiling_issue_repro.go -maxprocs=4 -enable-zk=true -enable-profiling=false -context-depth=10000000

Environment:

• Go version: go1.21.6 darwin/arm64
• OS: macOS (also reproduced on Linux)
• Hardware: Apple M1/M2, x86_64
• GOMAXPROCS: 4

---

Test Configuration:

• Context depth: 10,000,000 layers
• GOMAXPROCS: 4
• Real ZooKeeper network operations
• Periodic CPU profiling (10s every 1min)
• Ticker-based time-sensitive operations (50ms intervals)

Reproduction program code:
https://go.dev/play/p/1sgZodXCKvW?v=goprev

What did you see happen?

Program startup and initialization:

=== Go Context Scheduler Issue Reproduction ===
Go Version: go1.21.6
GOMAXPROCS: 4 (was: 14)
Context Depth: 10000000, Ticker Interval: 50ms
ZooKeeper: 127.0.0.1:2181 (enabled: true)
CPU Profiling: true

🔧 Creating 10000000-layer context chain...
✅ Deep context chain created

🚀 Starting background operations...
📊 Starting periodic CPU profiling: 10s every 1min
🔗 Connecting to ZooKeeper at 127.0.0.1:2181...
🔄 Started 10s CPU profiling session: repro_cpu_1758700953.prof

Severe performance degradation observed:

🐌 ZK operation slow: 511.066667ms (scheduler delay: -32.968416ms, tick: 11, op: 22)
🐌 ZK operation slow: 528.069875ms (scheduler delay: 58.083375ms, tick: 10, op: 23)
⚠️  Ticker delayed by 83.60925ms (count: 20)
🐌 ZK operation slow: 639.356875ms (scheduler delay: 2.306149875s, tick: 28, op: 64)
🐌 ZK operation slow: 545.889459ms (scheduler delay: 61.617583ms, tick: 29, op: 65)
🐌 ZK operation slow: 766.755709ms (scheduler delay: -9.641959ms, tick: 37, op: 82)
📊 Baseline: 31 ticks in 5 seconds

Key observations:

1. Extreme Scheduler Delays:

   • Normal operations: Expected ~50ms intervals
   • During CPU profiling: 2.306149875s scheduler delay (46x slower)
   • ZK operations taking 500-800ms instead of expected <50ms

2. Network Operation Impact:

   • ZooKeeper operations severely affected during profiling
   • Connection timeouts and delays cascade through the system
   • Real network I/O becomes unreliable during profiling sessions

3. Ticker Performance Collapse:

   • Expected: 50ms ticker intervals
   • Observed: 83ms+ delays (67% slower)
   • Baseline shows only 31 ticks in 5 seconds (should be ~100 ticks)

4. Context Chain Amplification:

   • 10M-layer context chains amplify the profiling overhead
   • Each context.WithTimeout operation becomes extremely expensive
   • Stack expansion during profiling creates performance bottlenecks

What did you expect to see?

Expected behavior:

• CPU profiling should have minimal impact on Go Runtime Scheduler Latency

Root cause hypothesis:
Deep context chains require significant stack space during operations like context.WithTimeout. CPU profiling appears to interfere with goroutine scheduling during stack expansion, particularly when combined with network I/O operations.

Business impact:
If there's a deep context chain, user cannot use CPU profiling for performance debugging in production enviorenment.

This significantly impacts the observability of Go applications in production environments where deep context chains are standard practice for request tracing, authentication, and resource management.

[gabyhelp]

Related Issues

• runtime: cgo calls are way faster when enabling CPU profile #38325
• runtime: GoroutineProfile causes latency spikes in high-goroutine-count application #33250 (closed)
• runtime/pprof: collecting a CPU profile takes ~200ms of wall time #63043
• runtime/pprof: under-samples all work when runtime creates threads #40963 (closed)
• net: pure-Go DNS resolver occasionally delayed by GC/scheduler — kernel receives UDP but userspace processes late (short DNSLookup spikes) #75517
• runtime/pprof: under-samples work on short-lived threads #40435 (closed)
• runtime/pprof: collecting mutex or block profiles add ~100ms of wall time #63078 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[rhysh]

I've reduced it a bit further, including removing the timers. I've run it with go1.25.1 on darwin/arm64.

What remains is a call through an interface (context.Context.Deadline) where the concrete type only implements the method through embedding the same interface, for many layers. I'm not sure what the generated code (behind the indirect call) looks like for that, or if the reproducer could be simplified even more.

With enough layers of nesting, turning on CPU profiling results in a large slowdown to the benchmark. The slowdown is more pronounced with more layers of embedded-interface nesting.

• With 4,000,000 layers, it's a 600% slowdown.
• With 1,000,000 layers, it's closer to 100% overhead.
• With 300,000 layers, it's about 50% overhead.
• With 100,000 layers, enabling CPU profiling slows the benchmark by less than 10%.

package main

import (
	"context"
	"flag"
	"testing"
)

var depth = flag.Int("depth", 1_000_000, "context nesting depth")

func BenchmarkDeadline(b *testing.B) {
	ctx := context.Background()
	for i := range *depth {
		ctx = context.WithValue(ctx, i, i)
	}
	b.ResetTimer()
	for range b.N {
		done := make(chan int)
		go func() {
			ctx.Deadline()
			close(done)
		}()
		<-done
	}
}

$ GOTOOLCHAIN=go1.25.1 GOGC=off GODEBUG=asyncpreemptoff=1 go test -bench=. -benchtime=10x -count=10 -depth=4_000_000 | tee ./baseline
[...]
$ GOTOOLCHAIN=go1.25.1 GOGC=off GODEBUG=asyncpreemptoff=1 go test -bench=. -benchtime=10x -count=10 -depth=4_000_000 -cpuprofile=/dev/null | tee ./cpuprofile
[...]
$ benchstat ./baseline ./cpuprofile 
goos: darwin
goarch: arm64
pkg: issue-75583
cpu: Apple M1
           │ ./baseline  │             ./cpuprofile              │
           │   sec/op    │    sec/op     vs base                 │
Deadline-8   169.2m ± 5%   1193.7m ± 5%  +605.35% (p=0.000 n=10)

[rhysh]

Running on linux/amd64, I see via perf record -g that the context.(*valueCtx).Deadline calls exist on the stack. They're real function calls, so perf sees them ... but they aren't "real" functions, they're wrappers, so they're (intentionally) hidden from Go's tracebacks.

That is probably also stopping them from counting towards the limit on how many frames we'll inspect when collecting samples for the CPU/heap/mutex profiles (and for the execution trace). So instead of limiting our work to 128 frames (64 for the CPU profiler) frames, the SIGPROF handler is looking at all 10 million frames without reaching its limit of 64 "real" / non-wrapper functions.

The program then spends a huge amount of time in the signal handler instead of doing the app's real work. If the thread spends 10ms in the signal handler, then it's earned another signal. In the limit, this may prevent any forward progress.

@golang/runtime , there's no limit on the number of wrapper frames we'll inspect; maybe there should be.

@JasonSongHoho , 10 million levels of context wrapping seems like a lot. If you're able to reduce that (I haven't seen many apps with more than a few dozen keys on a single context value), you might see an immediate improvement in your particular app.

[JasonSongHoho]

Hi @rhysh

Thanks for your timely reply. ❤️

If you're able to reduce that

Sure, it's actually a Context leak issue; we have fixed the issue, but we didn't figure out why it impacts all the Network I/O requests, until we realized it caused the Scheduler Delay. 😄

[nsrip-dd]

@golang/runtime , there's no limit on the number of wrapper frames we'll inspect; maybe there should be.

I agree that we should factor wrapper frames into the unwinding limit. Perhaps we should go a step further and actually show them? As you say, they're real function calls. They have non-zero cost (stack growth) even without CPU profiling, especially when there are as many as in this example. I think it unnecessarily obscures a meaningful problem to hide these functions in runtime diagnostics.

edit: I guess the downside of not skipping wrapper frames in this example is that we'd have truncated tracebacks and wouldn't see where the original Deadline call is happening.

[randall77]

In triage: We could maybe do smarter things, like putting summaries every so often in the context chain.
Doesn't seem worth the engineering effort though. If this really is a bug, maybe just providing a way to notice would be enough.