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

runtime: huge performance drops in a timer application #35395

Closed
changkun opened this issue Nov 6, 2019 · 4 comments
Closed

runtime: huge performance drops in a timer application #35395

changkun opened this issue Nov 6, 2019 · 4 comments
Labels
FrozenDueToAge

Comments

@changkun
Copy link
Member

changkun commented Nov 6, 2019

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

$ go version
go version devel +6dc250f456 Wed Nov 6 13:55:04 2019 +0000 darwin/amd64

Does this issue reproduce with the latest release?

Yes, it is reproducible in the current master branch(6dc250f).

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/changkun/Library/Caches/go-build"
GOENV="/Users/changkun/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/changkun/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/changkun/dev/golang-go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/changkun/dev/golang-go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/changkun/dev/gobase/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/j_/h4j7spgj3znbfxcbbph5fp4w0000gn/T/go-build604565365=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

# changkun at ou-lmu.local in ~/dev/experiments
$ git clone https://github.com/changkun/gobase.git && cd gobase && git checkout new-timer && cd sched                                                                                                      [16:32:58]
Cloning into 'gobase'...
remote: Enumerating objects: 357, done.
remote: Counting objects: 100% (357/357), done.
remote: Compressing objects: 100% (253/253), done.
remote: Total 357 (delta 118), reused 318 (delta 87), pack-reused 0
Receiving objects: 100% (357/357), 1.68 MiB | 3.37 MiB/s, done.
Resolving deltas: 100% (118/118), done.
Branch 'new-timer' set up to track remote branch 'new-timer' from 'origin'.
Switched to a new branch 'new-timer'

# changkun at ou-lmu.local in ~/dev/experiments/gobase/sched
$ ~/goes/go1.12.13/bin/go test -bench=. -run=^$ -count=10 . | tee go1.12.txt                                                                                                                  new-timer ● [16:33:14]
size:  10
goos: darwin
goarch: amd64
pkg: github.com/changkun/gobase/sched
BenchmarkSubmit/#tasks-10-12               20000             61103 ns/op
BenchmarkSubmit/#tasks-10-12               20000             60255 ns/op
BenchmarkSubmit/#tasks-10-12               20000             60381 ns/op
BenchmarkSubmit/#tasks-10-12               20000             63703 ns/op
BenchmarkSubmit/#tasks-10-12               30000             61081 ns/op
BenchmarkSubmit/#tasks-10-12               20000             62021 ns/op
BenchmarkSubmit/#tasks-10-12               30000             61320 ns/op
BenchmarkSubmit/#tasks-10-12               20000             60020 ns/op
BenchmarkSubmit/#tasks-10-12               20000             60892 ns/op
BenchmarkSubmit/#tasks-10-12               20000             62412 ns/op
PASS
ok      github.com/changkun/gobase/sched        32.822s

# changkun at ou-lmu.local in ~/dev/experiments/gobase/sched
$  go test -bench=. -run=^$ -count=10 . | tee go1.13.txt                                                                                                                                      new-timer ✖︎ [16:34:04]
size:  10
goos: darwin
goarch: amd64
pkg: github.com/changkun/gobase/sched
BenchmarkSubmit/#tasks-10-12               15416             78142 ns/op
BenchmarkSubmit/#tasks-10-12               15368             77824 ns/op
BenchmarkSubmit/#tasks-10-12               15277             78486 ns/op
BenchmarkSubmit/#tasks-10-12               15379             74390 ns/op
BenchmarkSubmit/#tasks-10-12               16436             70893 ns/op
BenchmarkSubmit/#tasks-10-12               16768             71989 ns/op
BenchmarkSubmit/#tasks-10-12               16472             71118 ns/op
BenchmarkSubmit/#tasks-10-12               16729             73497 ns/op
BenchmarkSubmit/#tasks-10-12               16626             70976 ns/op
BenchmarkSubmit/#tasks-10-12               16338             72970 ns/op
PASS
ok      github.com/changkun/gobase/sched        30.057s

# changkun at ou-lmu.local in ~/dev/experiments/gobase/sched
$  ~/dev/golang-go/bin/go test -bench=. -run=^$ -count=10 . | tee go1.14.txt                                                                                                                  new-timer ✖︎ [16:34:59]
size:  10
goos: darwin
goarch: amd64
pkg: github.com/changkun/gobase/sched
BenchmarkSubmit/#tasks-10-12                  86          21858388 ns/op
BenchmarkSubmit/#tasks-10-12                  54          21955353 ns/op
BenchmarkSubmit/#tasks-10-12                  56          21642704 ns/op
BenchmarkSubmit/#tasks-10-12                  56          22091363 ns/op
BenchmarkSubmit/#tasks-10-12                  54          21785593 ns/op
BenchmarkSubmit/#tasks-10-12                  52          21763809 ns/op
BenchmarkSubmit/#tasks-10-12                  56          21759341 ns/op
BenchmarkSubmit/#tasks-10-12                  60          22021139 ns/op
BenchmarkSubmit/#tasks-10-12                  60          21497675 ns/op
BenchmarkSubmit/#tasks-10-12                  58          21710705 ns/op
PASS
ok      github.com/changkun/gobase/sched        13.300s

What did you expect to see?

Performance improvements or fair performance changes.

What did you see instead?

# changkun at ou-lmu.local in ~/dev/experiments/gobase/sched
$  benchstat go1.12.txt go1.13.txt go1.14.txt                                                                                                                                                 new-timer ✖︎ [16:35:40]
name \ time/op       go1.12.txt   go1.13.txt   go1.14.txt
Submit/#tasks-10-12  61.3µs ± 4%  74.0µs ± 6%  21808.6µs ± 1%

# changkun at ou-lmu.local in ~/dev/experiments/gobase/sched
$  benchstat go1.13.txt go1.14.txt                                                                                                                                                            new-timer ✖︎ [16:35:48]
name                 old time/op  new time/op     delta
Submit/#tasks-10-12  74.0µs ± 6%  21808.6µs ± 1%  +29359.74%  (p=0.000 n=10+10)
@ianlancetaylor
Copy link
Contributor

Your code has a busy wait in the sched.Wait function. Don't use busy waits in Go. They behave badly.

If I change your loop to call runtime.Gosched--still a busy wait, but at least slightly less busy--then the benchmark results are comparable to 1.13.

And actually your comment "With function call, no need for runtime.Gosched()" is incorrect. The tip compiler is better about inlining, so there may not be any function calls there at all. I didn't check that, though.

@changkun
Copy link
Member Author

changkun commented Nov 6, 2019

@ianlancetaylor Are you suggesting the performance drop caused by new changes to the inlining? Why the new async preemption didn't work out for the busy-wait?

@ianlancetaylor
Copy link
Contributor

@changkun I think that is a possibility to consider. If I'm right, then the async preemption did kick in; that would be why the test passes at all. But I might also be wrong, and it might be something else, like the new timer code.

In any case, I don't think there is any bug to fix here in the Go toolchain. We aren't going to make any promises about the performance of a busy wait loop.

@changkun
Copy link
Member Author

changkun commented Nov 6, 2019

@ianlancetaylor Reasonable, then I am closing this due to nothing needs to be fixed.

@changkun changkun closed this as completed Nov 6, 2019
@golang golang locked and limited conversation to collaborators Nov 5, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ianlancetaylor @changkun @gopherbot