runtime: huge performance drops in a timer application

[changkun]

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]

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]

@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]

@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]

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