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

testing: performance regression in TB.Helper in Go 1.12 relative to Go 1.11 #32093

Closed
g7r opened this issue May 17, 2019 · 8 comments
Closed

testing: performance regression in TB.Helper in Go 1.12 relative to Go 1.11 #32093

g7r opened this issue May 17, 2019 · 8 comments
Milestone

Comments

@g7r
Copy link
Contributor

@g7r g7r commented May 17, 2019

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

$ go version
go version go1.11.10 linux/amd64

and

$ go version
go version go1.12.5 linux/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
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/sz/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/sz/go"
GOPROXY=""
GORACE=""
GOROOT="/snap/go/3739"
GOTMPDIR=""
GOTOOLDIR="/snap/go/3739/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build471260994=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Here's the benchmark: https://play.golang.org/p/4PufWKn1Epv

benchstat output:

# benchstat v1.11.10_bench.txt v1.12.5_bench.txt
name       old time/op  new time/op  delta
Helper-12   647ns ± 2%   780ns ± 1%  +20.45%  (p=0.008 n=5+5)

What did you expect to see?

No performance regression.

What did you see instead?

Go 1.12.5 is 20% slower than Go 1.11.10.

@ianlancetaylor ianlancetaylor changed the title performance regression in runtime.pcvalue in Go 1.12 relative to Go 1.11 runtime: performance regression in pcvalue in Go 1.12 relative to Go 1.11 May 17, 2019
@ianlancetaylor ianlancetaylor added this to the Go1.13 milestone May 17, 2019
@g7r

This comment has been minimized.

Copy link
Contributor Author

@g7r g7r commented May 17, 2019

git bisect gave me the likely culprit: 69c2c56

@randall77

This comment has been minimized.

Copy link
Contributor

@randall77 randall77 commented May 17, 2019

It's another ~10% slower at tip :(

I found a simple fix though that actually makes it a bit faster than 1.11. I'll mail it out.
TL;DR we're symbolizing two PCs when we really only need to be symbolizing one.

@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented May 17, 2019

Change https://golang.org/cl/177858 mentions this issue: testing: callerName only needs one PC in the traceback

@cespare

This comment has been minimized.

Copy link
Contributor

@cespare cespare commented May 17, 2019

@g7r is the problem for you specifically with testing.TB.Helper, or was that just the way you chose to demonstrate the regression?

(@randall77's fix in CL 177858 is specifically for Helper.)

@g7r

This comment has been minimized.

Copy link
Contributor Author

@g7r g7r commented May 17, 2019

@cespare yes, mine problem is specifically with testing.TB.Helper. Its performance heavily affects our test set run duration.

@cespare cespare changed the title runtime: performance regression in pcvalue in Go 1.12 relative to Go 1.11 testing: performance regression in TB.Helper in Go 1.12 relative to Go 1.11 May 17, 2019
@cespare

This comment has been minimized.

Copy link
Contributor

@cespare cespare commented May 17, 2019

@g7r thanks -- I went ahead and retitled the issue accordingly.

I do wonder whether the underlying regression in runtime.Callers/CallersFrames will show up in other contexts.

@gopherbot gopherbot closed this in 1ab063c May 17, 2019
@randall77

This comment has been minimized.

Copy link
Contributor

@randall77 randall77 commented May 17, 2019

There is more we could do here, but it's getting late for big things for 1.13.

@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented May 19, 2019

Change https://golang.org/cl/178077 mentions this issue: runtime: In Frames.Next, delay file/line lookup until just before return

gopherbot pushed a commit that referenced this issue May 20, 2019
That way we will never have to look up the file/line for the frame
that's next to be returned when the user stops calling Next.

For the benchmark from #32093:

name      old time/op  new time/op  delta
Helper-4   948ns ± 1%   836ns ± 3%  -11.89%  (p=0.000 n=9+9)

(#32093 was fixed with a more specific, and better, fix, but this
fix is much more general.)

Change-Id: I89e796f80c9706706d8d8b30eb14be3a8a442846
Reviewed-on: https://go-review.googlesource.com/c/go/+/178077
Run-TryBot: Keith Randall <khr@golang.org>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants
You can’t perform that action at this time.