runtime: extremely slow stack unwind on panic

[robpike]

Go version

go version go1.26-devel_91435be153 Mon Dec 22 16:19:29 2025 -0800 darwin/arm64

Output of go env in your module/workspace:

AR='ar'
CC='clang'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='clang++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN='/Users/r/bin'
GOCACHE='/Users/r/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/r/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS='-ldflags=-w'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/hs/fxh5g1g977x6bvfxsk5vc27w0000gn/T/go-build61226620=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/Users/r/src/robpike.io/ivy/go.mod'
GOMODCACHE='/Users/r/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/r'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/r/go'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/r/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/r/go/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.26-devel_91435be153 Mon Dec 22 16:19:29 2025 -0800'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

I'm pretty sure this is recent behavior. If you install robpike.io/ivy@latest and cause an interpreter stack overflow (not a Go stack overflow), ivy will use panic to unwind and report the error. The unwind takes a very long time, and the time depends superlinearly on the Go (and ivy) stack depth. If I set the user's stack limit, that is the depth of the interpreter stack, to 10000, the unwind takes several seconds. At 100,000, the default, I've gotten bored waiting after many minutes. More precisely, at a mere 1000, it takes 0.080s. At 2,000, 0.236s. At 10,000, 5.3s. At 20,000, I gave up waiting after many minutes. The Go stack scales linearly with the ivy stack, I promise you.

Here's a way to make it happen:

$ ivy
)maxstack 10000 # The default takes far too long.
op x b y
op a x = (x (x+1)) b x
op (x y) b z = a x+y-z
1 2 b 3

What did you see happen?

If you run the most recent checkin (not tagged as I write this) it will immediately print the state of the ivy execution stack, but hang doing the Go stack unwind before printing the overflow error and returning to the user. I used pprof (with maxstack 10000, user time about 5 seconds) and it said this:

(pprof) top 50
Showing nodes accounting for 4.09s, 98.08% of 4.17s total
Dropped 46 nodes (cum <= 0.02s)
      flat  flat%   sum%        cum   cum%
     1.01s 24.22% 24.22%      1.09s 26.14%  runtime.pcvalue
     0.82s 19.66% 43.88%         2s 47.96%  runtime.(*unwinder).resolveInternal
     0.69s 16.55% 60.43%      3.56s 85.37%  runtime.(*unwinder).next
     0.51s 12.23% 72.66%      0.81s 19.42%  runtime.findfunc
     0.24s  5.76% 78.42%      0.24s  5.76%  runtime.findmoduledatap (inline)
     0.21s  5.04% 83.45%      0.30s  7.19%  runtime.(*_panic).initOpenCodedDefers
     0.18s  4.32% 87.77%      4.02s 96.40%  runtime.(*_panic).nextFrame.func1
     0.09s  2.16% 89.93%      1.18s 28.30%  runtime.funcspdelta (inline)
     0.08s  1.92% 91.85%      0.08s  1.92%  runtime.releasem (inline)
     0.07s  1.68% 93.53%      0.07s  1.68%  runtime.funcdata (inline)
     0.06s  1.44% 94.96%      0.06s  1.44%  runtime.guintptr.ptr (inline)
     0.05s  1.20% 96.16%      0.05s  1.20%  runtime.(*moduledata).textOff (inline)
     0.03s  0.72% 96.88%      4.08s 97.84%  runtime.systemstack
     0.02s  0.48% 97.36%      4.04s 96.88%  runtime.(*_panic).nextFrame
     0.02s  0.48% 97.84%      4.06s 97.36%  runtime.(*_panic).start
     0.01s  0.24% 98.08%      4.08s 97.84%  runtime.gopanic
         0     0% 98.08%      4.08s 97.84%  robpike.io/ivy/value.EvalFunctionBody.func1
         0     0% 98.08%      0.03s  0.72%  runtime.mcall
         0     0% 98.08%      0.03s  0.72%  runtime.park_m
         0     0% 98.08%      0.03s  0.72%  runtime.schedule

My aged eyes see this as panic/recover unwinding issue, but I may be wrong.
I'm happy to help debug this as well as listen to arguments why this could be my fault somehow.

I thought this was due to new code after a major rewrite, but it still happens with older versions. I'm sure it didn't used to do this.

Ivy has a -prof flag to automate writing profiling data for pprof.

What did you expect to see?

It should finish in a fraction of a second. The stack isn't that big.

[gabyhelp]

Related Issues

• runtime/trace: segfault in runtime.fpTracebackPCs during deferred call after recovering from panic #61766 (closed)
• runtime: endless sigtramp in the stack of coredump generated by panic on arm64 #58998

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

[randall77]

I'm not entirely sure about this, but I think I see what is going on.

Ivy queues up 10000 frames, each with a defer. That defer ends up re-panicking (specifically, here).

Each time a panic happens, it walks up the stack looking for the next defer to do. Each time it finds and runs one, it gets marked as done. The defer immediately panics, and now it has to walk the stack again, and now the first unexecuted defer is one further frame away. Instant O(n^2) behavior.

The runtime does the right thing here if there are multiple defers to find during a single panic. The problem here is that each time there is a new panic, which means the runtime starts with no state and has to walk the stack all over again.

Maybe there is something we could do here, keeping track of a section of stack that has no (unexecuted) defers in it. Maybe keep track of how far up the stack we've promoted open-coded defers to a linked list, so we don't have to redo that work. Sounds kind of tricky.

[robpike]

Thanks for looking into it. That explains why the behavior is new: that defer (which was not the one I thought was the culprit) went in not too long ago. I can hack the interpreter to avoid that defer if a RetExpr is never going to happen, which is overwhelmingly likely. That will fix my problem almost always. But n^2 in the runtime should be avoided too. I'll leave it to you to decide if you want to try to fix it.

[robpike]

An easy hack (but truly a hack) and the problem is gone for the overwhelming majority of ivy programs. And probably performance improves overall as well.

But I think this issue should stay open. Up to you.

[robpike]

See e430fc2

[randall77]

I think it is worth leaving this open. The defer-recover-repanic pattern is pretty common. Together with a very deep stack, maybe not super common, but probably worth fixing. If we can find a way to do it without too much additional complexity.

[robpike]

Thank you for looking into it so fast.

[JunyangShao]

@golang/runtime