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

Jump to bottom

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
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Go1.13

Comments

@g7r
Copy link
Contributor

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 the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 17, 2019
@ianlancetaylor ianlancetaylor added this to the Go1.13 milestone May 17, 2019
@g7r
Copy link
Contributor Author

g7r commented May 17, 2019

git bisect gave me the likely culprit: 69c2c56

@randall77
Copy link
Contributor

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
Copy link

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

@cespare
Copy link
Contributor

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
Copy link
Contributor Author

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
Copy link
Contributor

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.

@randall77
Copy link
Contributor

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

@gopherbot
Copy link

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
@randall77
runtime: In Frames.Next, delay file/line lookup until just before return
c77a9e0 
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>
@golang golang locked and limited conversation to collaborators May 18, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Go1.13
Development

No branches or pull requests
5 participants
@cespare @g7r @ianlancetaylor @randall77 @gopherbot