Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: Go 1.14 is extremely slow under debugging on macOS #37528

Closed
Cyberax opened this issue Feb 27, 2020 · 9 comments
Closed

runtime: Go 1.14 is extremely slow under debugging on macOS #37528

Cyberax opened this issue Feb 27, 2020 · 9 comments
Labels
Debugging FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin
Milestone

Comments

@Cyberax
Copy link

Cyberax commented Feb 27, 2020

What version of Go are you using (go version)?

$ go version
go version go1.14 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/cyberax/Library/Caches/go-build"
GOENV="/Users/cyberax/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/cyberax/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.14/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.14/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/cyberax/aurora/terra/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/ph/3916sjqd66z3tl55r2d5l79h0000gn/T/go-build235180942=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

After upgrade to 1.14 our application became unusable in a debugger with asynchronous preemption turned on. It's sometimes 1000 times slower than with the asyncpreempt=off.

You can try this program: https://play.golang.org/p/k3fnAt18hcO Normally it runs in under <4ms on my computer but under a debugger it runs in 500-2000ms.

What did you expect to see?

Normal speed.

What did you see instead?

Elapsed 1433 ms

@dmitshur dmitshur added OS-Darwin Debugging NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Feb 28, 2020
@dmitshur dmitshur changed the title Go 1.14 is extremely slow under debugging on Mac OS X runtime: Go 1.14 is extremely slow under debugging on macOS Feb 28, 2020
@dmitshur dmitshur added this to the Backlog milestone Feb 28, 2020
@dmitshur
Copy link
Contributor

/cc @aclements @mknyszek

@cherrymui
Copy link
Member

What debugger are you using? LLDB?

On my mac, it is clearly slower under lldb but not that slow. I see 10X-30X slowdown.

% ./xxx
Elapsed 4 ms

% lldb ./xxx
(lldb) target create "./xxx"
Current executable set to './xxx' (x86_64).
(lldb) run
Process 42895 launched: './xxx' (x86_64)
Elapsed 135 ms

Process 42895 exited with status = 0 (0x00000000) 
(lldb) run
Process 42899 launched: './xxx' (x86_64)
Elapsed 38 ms

Process 42899 exited with status = 0 (0x00000000) 
(lldb) run
Process 42903 launched: './xxx' (x86_64)
Elapsed 36 ms

Process 42903 exited with status = 0 (0x00000000) 

GDB on Linux doesn't show any slowdown.

Maybe LLDB's signal handling on darwin is not very efficient?
It would be interesting to see what the overhead of GDB is on darwin. @dr2chase

@dr2chase
Copy link
Contributor

If anyone can provide detailed actually-working instructions (a shell script would be ideal, "frab the gnobulator"-style instructions are less helpful) on how to get gdb working on Darwin, then I could perhaps answer that question. Till then, I can report that "no slowdown was observed" (because there are no observations at all).

@Cyberax
Copy link
Author

Cyberax commented Feb 28, 2020

I'm using the Delve debugger with default options:

cyberax@CybMac:~/aurora/terra/repro$ go get -u github.com/go-delve/delve/cmd/dlv
...
cyberax@CybMac:~/aurora/terra/repro$ go run github.com/go-delve/delve/cmd/dlv debug main.go
Type 'help' for list of commands.
(dlv) continue
Elapsed 991 ms
Process 72508 has exited with status 0

@Cyberax
Copy link
Author

Cyberax commented Feb 28, 2020

Here's a reproduction script: https://gist.github.com/Cyberax/693f1d1f2c4550478615047e8ca866e0

Output:

cyberax@CybMac:~/aurora/bug$ ./repro.sh
Elapsed 4 ms
Type 'help' for list of commands.
Elapsed 936 ms
Process 3277 has exited with status 0
exit

With preempt off:

cyberax@CybMac:~/aurora/bug$ export GODEBUG=asyncpreemptoff=1
cyberax@CybMac:~/aurora/bug$ ./repro.sh
Elapsed 4 ms
Type 'help' for list of commands.
Elapsed 9 ms
Process 5574 has exited with status 0
exit

@dr2chase
Copy link
Contributor

It has something to do with asynchronous preemption, not sure what.
What @derekparker just now said.

@Cyberax
Copy link
Author

Cyberax commented Feb 28, 2020

I think this might have something to do with somewhat unusual stack arrangement. The reproduction case creates an array of slices into a large array. As far as I remember, asyncpreempt treats stack conservatively during GC pauses which would cause a lot of unnecessary work

I've tested this hypothesis by running with GOGC=off and it indeed fixes the issue:

cyberax@CybMac:~/aurora/bug$ ./repro.sh
Elapsed 4 ms
Type 'help' for list of commands.
Elapsed 7 ms
Process 7323 has exited with status 0
exit

@cherrymui
Copy link
Member

I don't think conservative stack scan causes this. It is the same amount of work, under the debugger or not.

My guess is that with GC off, there are fewer preemption happened, as a source of preemptions is the GC trying to stop the goroutine to scan the stack or stop the world.

@Cyberax
Copy link
Author

Cyberax commented Jul 2, 2021

The workaround with disabling the asyncpreemt works, closing the issue.

@Cyberax Cyberax closed this as completed Jul 2, 2021
@golang golang locked and limited conversation to collaborators Jul 2, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Debugging FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin
Projects
None yet
Development

No branches or pull requests

5 participants