Go: runtime: go 1.10beta2 Benchmarks slower on Mac (possibly related to time)
What version of Go are you using (go version)?
go version go1.10beta2 darwin/amd64
Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (go env)?
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/jlindamo/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/jlindamo/go"
GORACE=""
GOROOT="/Users/jlindamo/sdk/go1.10beta2"
GOTMPDIR=""
GOTOOLDIR="/Users/jlindamo/sdk/go1.10beta2/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
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/hz/fdkmg98n3wx1xth0ypjq1s4c3xsp_j/T/go-build325901435=/tmp/go-build -gno-record-gcc-switches -fno-common"
What did you do?
Ran my benchmarks on go 1.9 and go 1.10
What did you expect to see?
Little or no change in timings
What did you see instead?
Differences by up to 600%
To reproduce:
go get github.com/cep21/circuit
cd $GOPATH/src/github.com/cep21/circuit
make bench
I ran benchmarks for go 1.9 and go 1.10. There is the result of benchcmp
> benchcmp /tmp/go1.9.2 /tmp/go1.10.b2
benchmark old ns/op new ns/op delta
BenchmarkCiruits/cep21-circuit/Hystrix/passing/1-8 767 1698 +121.38%
BenchmarkCiruits/cep21-circuit/Hystrix/passing/75-8 436 666 +52.75%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/1-8 103 333 +223.30%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/75-8 79.1 159 +101.01%
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-8 159 800 +403.14%
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-8 84.4 496 +487.68%
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-8 58.4 282 +382.88%
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-8 20.3 159 +683.25%
BenchmarkCiruits/cep21-circuit/UseGo/passing/1-8 1361 1932 +41.95%
BenchmarkCiruits/cep21-circuit/UseGo/passing/75-8 363 622 +71.35%
BenchmarkCiruits/cep21-circuit/UseGo/failing/1-8 1454 1994 +37.14%
BenchmarkCiruits/cep21-circuit/UseGo/failing/75-8 385 674 +75.06%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/1-8 10198 10182 -0.16%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/75-8 2897 3091 +6.70%
BenchmarkCiruits/GoHystrix/DefaultConfig/failing/1-8 6376 7215 +13.16%
BenchmarkCiruits/GoHystrix/DefaultConfig/failing/75-8 1589 1912 +20.33%
BenchmarkCiruits/rubyist/Threshold-10/passing/1-8 1671 2021 +20.95%
BenchmarkCiruits/rubyist/Threshold-10/passing/75-8 878 1662 +89.29%
BenchmarkCiruits/rubyist/Threshold-10/failing/1-8 132 325 +146.21%
BenchmarkCiruits/rubyist/Threshold-10/failing/75-8 1450 2750 +89.66%
BenchmarkCiruits/gobreaker/Default/passing/1-8 207 588 +184.06%
BenchmarkCiruits/gobreaker/Default/passing/75-8 757 734 -3.04%
BenchmarkCiruits/gobreaker/Default/failing/1-8 94.5 282 +198.41%
BenchmarkCiruits/gobreaker/Default/failing/75-8 376 358 -4.79%
BenchmarkCiruits/handy/Default/passing/1-8 1105 1377 +24.62%
BenchmarkCiruits/handy/Default/passing/75-8 1377 1860 +35.08%
BenchmarkCiruits/handy/Default/failing/1-8 1383 1293 -6.51%
BenchmarkCiruits/handy/Default/failing/75-8 1699 1701 +0.12%
BenchmarkCiruits/iand_circuit/Default/passing/1-8 122 113 -7.38%
BenchmarkCiruits/iand_circuit/Default/passing/75-8 312 299 -4.17%
BenchmarkCiruits/iand_circuit/Default/failing/1-8 21.4 23.2 +8.41%
BenchmarkCiruits/iand_circuit/Default/failing/75-8 5.71 8.51 +49.04%
BenchmarkRollingCounter/super-small-buckets/1-8 98.6 90.9 -7.81%
BenchmarkRollingCounter/super-small-buckets/50-8 191 185 -3.14%
BenchmarkRollingCounter/normal-rate/1-8 63.7 61.1 -4.08%
BenchmarkRollingCounter/normal-rate/50-8 84.1 85.5 +1.66%
BenchmarkRollingCounter/default/1-8 60.6 57.2 -5.61%
BenchmarkRollingCounter/default/50-8 71.2 84.1 +18.12%
benchmark old allocs new allocs delta
BenchmarkCiruits/cep21-circuit/Hystrix/passing/1-8 4 4 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/passing/75-8 4 4 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/1-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/75-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/1-8 5 5 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/75-8 5 4 -20.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/1-8 5 5 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/75-8 5 4 -20.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/1-8 18 18 +0.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/75-8 20 20 +0.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/failing/1-8 19 19 +0.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/failing/75-8 20 20 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/passing/1-8 5 5 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/passing/75-8 4 4 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/failing/1-8 0 0 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/failing/75-8 5 5 +0.00%
BenchmarkCiruits/gobreaker/Default/passing/1-8 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/passing/75-8 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/1-8 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/75-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/1-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/75-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/1-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/75-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/1-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/75-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/1-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/75-8 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/1-8 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/50-8 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/1-8 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/50-8 0 0 +0.00%
BenchmarkRollingCounter/default/1-8 0 0 +0.00%
BenchmarkRollingCounter/default/50-8 0 0 +0.00%
benchmark old bytes new bytes delta
BenchmarkCiruits/cep21-circuit/Hystrix/passing/1-8 192 208 +8.33%
BenchmarkCiruits/cep21-circuit/Hystrix/passing/75-8 192 208 +8.33%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/1-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/75-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-8 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/1-8 256 256 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/75-8 256 256 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/1-8 256 256 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/75-8 256 255 -0.39%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/1-8 1005 1015 +1.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/75-8 1000 1022 +2.20%
BenchmarkCiruits/GoHystrix/DefaultConfig/failing/1-8 1013 1037 +2.37%
BenchmarkCiruits/GoHystrix/DefaultConfig/failing/75-8 1005 1013 +0.80%
BenchmarkCiruits/rubyist/Threshold-10/passing/1-8 332 348 +4.82%
BenchmarkCiruits/rubyist/Threshold-10/passing/75-8 309 324 +4.85%
BenchmarkCiruits/rubyist/Threshold-10/failing/1-8 0 0 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/failing/75-8 304 320 +5.26%
BenchmarkCiruits/gobreaker/Default/passing/1-8 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/passing/75-8 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/1-8 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/75-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/1-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/75-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/1-8 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/75-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/1-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/75-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/1-8 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/75-8 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/1-8 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/50-8 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/1-8 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/50-8 0 0 +0.00%
BenchmarkRollingCounter/default/1-8 0 0 +0.00%
BenchmarkRollingCounter/default/50-8 0 0 +0.00%
cep21
All 22 comments
Is this an appropriate use of github issues?
Not at all a minimal reproducible test case, sorry :( But is very reproducible. My own investigation saw a lot of pprof time inside the time package.
cep21
on 11 Jan 2018
Is this an appropriate use of github issues?
Yes.
bradfitz
on 11 Jan 2018
We should at least understand the difference before shipping Go 1.10, but no promises on fixing it this late in the cycle.
Have you run the CPU profiler on the worst cases there (like BenchmarkCiruits/cep21-circuit/Minimal/failing/75-8) to see what the CPU was doing before vs after?
bradfitz
on 11 Jan 2018
We did change the Darwin time code in 1.10, for High Sierra (#22037). That may have made it slower, though I would expect that it would only matter for benchmarks that are dominated by timing calls. Please do attach some profiling data. Thanks.
CC @aclements
ianlancetaylor
on 11 Jan 2018
Please do attach some profiling data
How do I do that? I don't see a way to attach files to github issues.
Here is some top30 output
< make PROFILE_RUN='BenchmarkCiruits/cep21-circuit/Minimal/failing/75' profile_cpu
go test -run=^$ -bench=BenchmarkCiruits/cep21-circuit/Minimal/failing/75 -benchtime=15s -cpuprofile=cpu.out ./benchmarking
(pprof) top30
Showing nodes accounting for 248.55s, 99.59% of 249.57s total
Dropped 34 nodes (cum <= 1.25s)
flat flat% sum% cum cum%
36.15s 14.48% 14.48% 36.15s 14.48% runtime.getitab /usr/local/Cellar/go/1.9.2/libexec/src/runtime/iface.go
31.72s 12.71% 27.19% 229.10s 91.80% github.com/cep21/circuit/benchmarking.genericBenchmarkTesting.func1 /Users/jlindamo/go/src/github.com/cep21/circuit/benchmarking/helpers_test.go
23.46s 9.40% 36.59% 23.46s 9.40% time.now /usr/local/Cellar/go/1.9.2/libexec/src/runtime/sys_darwin_amd64.s
23.19s 9.29% 45.89% 27.19s 10.89% github.com/cep21/circuit.RunMetricsCollection.ErrShortCircuit /Users/jlindamo/go/src/github.com/cep21/circuit/metrics.go
20.32s 8.14% 54.03% 20.32s 8.14% runtime.duffcopy /usr/local/Cellar/go/1.9.2/libexec/src/runtime/duff_amd64.s
17.38s 6.96% 60.99% 112.44s 45.05% github.com/cep21/circuit.(*Circuit).run /Users/jlindamo/go/src/github.com/cep21/circuit/circuit.go
12.01s 4.81% 65.81% 185.02s 74.14% github.com/cep21/circuit.(*Circuit).Execute /Users/jlindamo/go/src/github.com/cep21/circuit/circuit.go
11.63s 4.66% 70.47% 11.88s 4.76% runtime.deferreturn /usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go
10.23s 4.10% 74.56% 14.84s 5.95% github.com/cep21/circuit.(*Circuit).allowNewRun /Users/jlindamo/go/src/github.com/cep21/circuit/circuit.go
9.77s 3.91% 78.48% 33.23s 13.31% time.Now /usr/local/Cellar/go/1.9.2/libexec/src/time/time.go
8.90s 3.57% 82.05% 45.05s 18.05% runtime.assertI2I2 /usr/local/Cellar/go/1.9.2/libexec/src/runtime/iface.go
7.13s 2.86% 84.90% 40.36s 16.17% github.com/cep21/circuit.(*Circuit).now /Users/jlindamo/go/src/github.com/cep21/circuit/circuit.go
7.04s 2.82% 87.72% 52.09s 20.87% github.com/cep21/circuit.IsBadRequest /Users/jlindamo/go/src/github.com/cep21/circuit/errors.go
6.77s 2.71% 90.44% 197.13s 78.99% github.com/cep21/circuit/benchmarking.circuitRunner.func1 /Users/jlindamo/go/src/github.com/cep21/circuit/benchmarking/benchmark_hystrix_test.go
5.39s 2.16% 92.60% 5.39s 2.16% github.com/cep21/circuit.(*Circuit).allowNewRun /Users/jlindamo/go/src/github.com/cep21/circuit/faststats/atomic.go
5.34s 2.14% 94.73% 5.34s 2.14% github.com/cep21/circuit.(*Circuit).Execute /Users/jlindamo/go/src/github.com/cep21/circuit/faststats/atomic.go
4.61s 1.85% 96.58% 4.61s 1.85% github.com/cep21/circuit.(*neverCloses).Allow <autogenerated>
4.12s 1.65% 98.23% 8.48s 3.40% github.com/cep21/circuit.(*Circuit).fallback /Users/jlindamo/go/src/github.com/cep21/circuit/circuit.go
3.36s 1.35% 99.58% 3.36s 1.35% github.com/cep21/circuit.(*neverCloses).ErrShortCircuit <autogenerated>
0.03s 0.012% 99.59% 20.35s 8.15% runtime.morestack /usr/local/Cellar/go/1.9.2/libexec/src/runtime/asm_amd64.s
0 0% 99.59% 20.32s 8.14% runtime.newstack /usr/local/Cellar/go/1.9.2/libexec/src/runtime/stack.go
And with go1.10
< env PATH=/Users/jlindamo/sdk/go1.10beta2/bin:$PATH make PROFILE_RUN='BenchmarkCiruits/cep21-circuit/Minimal/failing/75' profile_cpu
go test -run=^$ -bench=BenchmarkCiruits/cep21-circuit/Minimal/failing/75 -benchtime=15s -cpuprofile=cpu.out ./benchmarking
(pprof) top30
Showing nodes accounting for 95.19s, 100% of 95.23s total
Dropped 8 nodes (cum <= 0.48s)
flat flat% sum% cum cum%
94.99s 99.75% 99.75% 94.99s 99.75% time.now
0.16s 0.17% 99.92% 95.16s 99.93% github.com/cep21/circuit.(*Circuit).run
0.02s 0.021% 99.94% 95.20s 100% github.com/cep21/circuit.(*Circuit).Execute
0.01s 0.011% 99.95% 95.21s 100% github.com/cep21/circuit/benchmarking.circuitRunner.func1
0.01s 0.011% 100% 95.22s 100% github.com/cep21/circuit/benchmarking.genericBenchmarkTesting.func1
0 0% 100% 94.99s 99.75% github.com/cep21/circuit.(*Circuit).now
0 0% 100% 94.99s 99.75% time.Now
Sure looks like time, but that's pretty extreme. time.Now went from 13.31% cumulative to 99.75%.
The new code that you're in (specifically the assembly for time.now lowercase) is:
https://go-review.googlesource.com/c/go/+/67332/5/src/runtime/sys_darwin_amd64.s
I wonder if it can get stuck for too many iterations in this part:
// Loop trying to take a consistent snapshot
// of the time parameters.
timeloop13:
...
@rsc, do you remember if that CL was that much slower for you?
bradfitz
on 11 Jan 2018
@cep21 Which version of Darwin are you using? Are you running it on a physical machine or some sort of VM?
ianlancetaylor
on 11 Jan 2018
Which version of Darwin are you using?
Kernel Version: Darwin 16.7.0
running it on a physical machine or some sort of VM?
Running on my physical mac (MacBook Pro)
cep21
on 12 Jan 2018
@cep21 I'm trying to reproduce it. The instructions seem incomplete because I also need to download test dependencies (go get -t ./...) but besides that, I'm getting pages of this error:
2018/01/12 00:52:21 hystrix: metrics channel (gocircuit-17) is at capacity
If I just ignore it, I get results which are much better on tip:
Go 1.9.2:
↪ go test -run=^\$ -bench=BenchmarkCiruits/cep21-circuit/Minimal ./benchmarking
goos: darwin
goarch: amd64
pkg: github.com/cep21/circuit/benchmarking
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-4 500000 2310 ns/op
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-4 2000000 789 ns/op
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-4 2000000 835 ns/op
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-4 5000000 291 ns/op
PASS
Go tip c13e0e8cee
↪ gotip test -run=^\$ -bench=BenchmarkCiruits/cep21-circuit/Minimal ./benchmarking
goos: darwin
goarch: amd64
pkg: github.com/cep21/circuit/benchmarking
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-4 10000000 142 ns/op
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-4 20000000 93.8 ns/op
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-4 30000000 57.7 ns/op
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-4 50000000 26.3 ns/op
PASS
Full benchcmp:
ignoring BenchmarkCiruits/GoHystrix/DefaultConfig/failing/1-4: before has 1 instances, after has 0
ignoring BenchmarkCiruits/GoHystrix/DefaultConfig/passing/75-4: before has 1 instances, after has 0
ignoring BenchmarkCiruits/GoHystrix/DefaultConfig/failing/75-4: before has 1 instances, after has 0
benchmark old ns/op new ns/op delta
BenchmarkCiruits/cep21-circuit/Hystrix/passing/1-4 4500 1058 -76.49%
BenchmarkCiruits/cep21-circuit/Hystrix/passing/75-4 1524 434 -71.52%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/1-4 910 129 -85.82%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/75-4 369 85.5 -76.83%
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-4 2603 157 -93.97%
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-4 965 109 -88.70%
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-4 864 58.4 -93.24%
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-4 294 28.4 -90.34%
BenchmarkCiruits/cep21-circuit/UseGo/passing/1-4 4589 1397 -69.56%
BenchmarkCiruits/cep21-circuit/UseGo/passing/75-4 1321 481 -63.59%
BenchmarkCiruits/cep21-circuit/UseGo/failing/1-4 4770 1475 -69.08%
BenchmarkCiruits/cep21-circuit/UseGo/failing/75-4 1327 672 -49.36%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/1-4 21032 9712 -53.82%
BenchmarkCiruits/rubyist/Threshold-10/passing/1-4 5392 1752 -67.51%
BenchmarkCiruits/rubyist/Threshold-10/passing/75-4 2596 849 -67.30%
BenchmarkCiruits/rubyist/Threshold-10/failing/1-4 1009 100 -90.09%
BenchmarkCiruits/rubyist/Threshold-10/failing/75-4 4158 124 -97.02%
BenchmarkCiruits/gobreaker/Default/passing/1-4 1785 189 -89.41%
BenchmarkCiruits/gobreaker/Default/passing/75-4 2120 350 -83.49%
BenchmarkCiruits/gobreaker/Default/failing/1-4 923 80.6 -91.27%
BenchmarkCiruits/gobreaker/Default/failing/75-4 1066 163 -84.71%
BenchmarkCiruits/handy/Default/passing/1-4 2898 1303 -55.04%
BenchmarkCiruits/handy/Default/passing/75-4 2153 1257 -41.62%
BenchmarkCiruits/handy/Default/failing/1-4 1518 1398 -7.91%
BenchmarkCiruits/handy/Default/failing/75-4 1412 1367 -3.19%
BenchmarkCiruits/iand_circuit/Default/passing/1-4 109 108 -0.92%
BenchmarkCiruits/iand_circuit/Default/passing/75-4 136 128 -5.88%
BenchmarkCiruits/iand_circuit/Default/failing/1-4 23.3 24.6 +5.58%
BenchmarkCiruits/iand_circuit/Default/failing/75-4 10.0 10.2 +2.00%
BenchmarkRollingCounter/super-small-buckets/1-4 106 129 +21.70%
BenchmarkRollingCounter/super-small-buckets/50-4 172 207 +20.35%
BenchmarkRollingCounter/normal-rate/1-4 65.5 92.8 +41.68%
BenchmarkRollingCounter/normal-rate/50-4 82.3 83.7 +1.70%
BenchmarkRollingCounter/default/1-4 64.1 61.6 -3.90%
BenchmarkRollingCounter/default/50-4 82.6 82.4 -0.24%
benchmark old allocs new allocs delta
BenchmarkCiruits/cep21-circuit/Hystrix/passing/1-4 4 4 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/passing/75-4 4 4 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/1-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/75-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/1-4 5 5 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/75-4 5 5 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/1-4 5 5 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/75-4 4 5 +25.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/1-4 18 18 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/passing/1-4 5 5 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/passing/75-4 4 4 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/failing/1-4 0 0 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/failing/75-4 4 0 -100.00%
BenchmarkCiruits/gobreaker/Default/passing/1-4 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/passing/75-4 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/1-4 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/75-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/1-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/75-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/1-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/75-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/1-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/75-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/1-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/75-4 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/1-4 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/50-4 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/1-4 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/50-4 0 0 +0.00%
BenchmarkRollingCounter/default/1-4 0 0 +0.00%
BenchmarkRollingCounter/default/50-4 0 0 +0.00%
benchmark old bytes new bytes delta
BenchmarkCiruits/cep21-circuit/Hystrix/passing/1-4 192 208 +8.33%
BenchmarkCiruits/cep21-circuit/Hystrix/passing/75-4 192 208 +8.33%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/1-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Hystrix/failing/75-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/1-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/passing/75-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/1-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/Minimal/failing/75-4 0 0 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/1-4 256 256 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/passing/75-4 256 256 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/1-4 256 256 +0.00%
BenchmarkCiruits/cep21-circuit/UseGo/failing/75-4 256 256 +0.00%
BenchmarkCiruits/GoHystrix/DefaultConfig/passing/1-4 1007 1031 +2.38%
BenchmarkCiruits/rubyist/Threshold-10/passing/1-4 322 348 +8.07%
BenchmarkCiruits/rubyist/Threshold-10/passing/75-4 317 325 +2.52%
BenchmarkCiruits/rubyist/Threshold-10/failing/1-4 0 0 +0.00%
BenchmarkCiruits/rubyist/Threshold-10/failing/75-4 304 0 -100.00%
BenchmarkCiruits/gobreaker/Default/passing/1-4 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/passing/75-4 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/1-4 0 0 +0.00%
BenchmarkCiruits/gobreaker/Default/failing/75-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/1-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/passing/75-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/1-4 0 0 +0.00%
BenchmarkCiruits/handy/Default/failing/75-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/1-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/passing/75-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/1-4 0 0 +0.00%
BenchmarkCiruits/iand_circuit/Default/failing/75-4 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/1-4 0 0 +0.00%
BenchmarkRollingCounter/super-small-buckets/50-4 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/1-4 0 0 +0.00%
BenchmarkRollingCounter/normal-rate/50-4 0 0 +0.00%
BenchmarkRollingCounter/default/1-4 0 0 +0.00%
BenchmarkRollingCounter/default/50-4 0 0 +0.00%
This is on a MacBook Pro 2016 (Core i7).
rasky
on 12 Jan 2018
The package go-hystrix is written in a way that it logs to stdout when it is overused :/ I manually comment out that log statement in my local repository. I'll push a branch that does that for you.
cep21
on 12 Jan 2018
Ok new reproduce steps
go get github.com/cep21/circuit
cd $GOPATH/src/github.com/cep21/circuit
git fetch -av
git reset --hard origin/remove_tests
go get -t ./...
make bench
@rasky is tip the same as beta2? If not, what do you see on beta2?
cep21
on 12 Jan 2018
Thanks. As in my edited comment above, it works much better on tip for me.
My tip is just one day newer than beta2.
Go 1.9.2 profile:
↪ gotip tool pprof cpu19.out
Main binary filename not available.
Type: cpu
Time: Jan 12, 2018 at 1:16am (CET)
Duration: 18.74s, Total samples = 51.19s (273.21%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top30
Showing nodes accounting for 51.17s, 100% of 51.19s total
Dropped 3 nodes (cum <= 0.26s)
flat flat% sum% cum cum%
51.16s 99.94% 99.94% 51.16s 99.94% time.now
0.01s 0.02% 100% 51.17s 100% github.com/cep21/circuit.(*Circuit).now
0 0% 100% 51.19s 100% github.com/cep21/circuit.(*Circuit).Execute
0 0% 100% 51.18s 100% github.com/cep21/circuit.(*Circuit).run
0 0% 100% 51.19s 100% github.com/cep21/circuit/benchmarking.circuitRunner.func1
0 0% 100% 51.19s 100% github.com/cep21/circuit/benchmarking.genericBenchmarkTesting.func1
0 0% 100% 51.16s 99.94% time.Now
Go tip profile:
↪ gotip tool pprof cpu10.out
Main binary filename not available.
Type: cpu
Time: Jan 12, 2018 at 1:17am (CET)
Duration: 36.01s, Total samples = 1.57mins (262.08%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top30
Showing nodes accounting for 93.69s, 99.28% of 94.37s total
Dropped 36 nodes (cum <= 0.47s)
flat flat% sum% cum cum%
13.55s 14.36% 14.36% 94.10s 99.71% github.com/cep21/circuit/benchmarking.genericBenchmarkTesting.func1
11.32s 12.00% 26.35% 11.32s 12.00% time.now
8.71s 9.23% 35.58% 10.39s 11.01% github.com/cep21/circuit.RunMetricsCollection.ErrShortCircuit
8.18s 8.67% 44.25% 8.30s 8.80% runtime.(*itabTableType).find
8.08s 8.56% 52.81% 47.92s 50.78% github.com/cep21/circuit.(*Circuit).run
5.94s 6.29% 59.11% 14.24s 15.09% runtime.getitab
5.03s 5.33% 64.44% 77.77s 82.41% github.com/cep21/circuit.(*Circuit).Execute
4.80s 5.09% 69.52% 19.59s 20.76% github.com/cep21/circuit.(*Circuit).now
4.49s 4.76% 74.28% 4.49s 4.76% runtime.deferreturn
3.90s 4.13% 78.41% 18.14s 19.22% runtime.assertI2I2
3.55s 3.76% 82.18% 6.90s 7.31% github.com/cep21/circuit.(*Circuit).allowNewRun
3.47s 3.68% 85.85% 14.79s 15.67% time.Now
3.11s 3.30% 89.15% 21.25s 22.52% github.com/cep21/circuit.IsBadRequest
2.78s 2.95% 92.09% 80.55s 85.36% github.com/cep21/circuit/benchmarking.circuitRunner.func1
2.10s 2.23% 94.32% 2.10s 2.23% github.com/cep21/circuit/faststats.(*AtomicBoolean).Get (inline)
1.65s 1.75% 96.07% 1.65s 1.75% github.com/cep21/circuit.(*neverCloses).Allow
1.42s 1.50% 97.57% 2.95s 3.13% github.com/cep21/circuit.(*Circuit).fallback
1.39s 1.47% 99.05% 1.39s 1.47% github.com/cep21/circuit.(*neverCloses).ErrShortCircuit
0.22s 0.23% 99.28% 1.70s 1.80% github.com/cep21/circuit.(*Circuit).IsOpen (inline)
(no difference with Go 1.10beta2, just double checked)
rasky
on 12 Jan 2018
So, results seem to make sense.
I run High Sierra. High Sierra broke Go's time.Now() fast implementation so all versions of Go (up to and including 1.9.2) fallback to a slower codepath that is syscall-based. This might have an effect on benchmarks where time.Now() dominates. We fixed this during the Go 1.10 cycle, so time.Now() on 1.10 is fast again like previous Go versions on previous macOS versions.
You're running Sierra (I assume so given your Darwin version), so Go 1.9.2 is fast for you just like Go 1.10 is fast on my High Sierra. The question is: why Go 1.10 is slow for you... it shouldn't be.
I don't have Sierra handy right now, I'll need some help. Let's see if the version detection works: can you please try compiling Go from source, after modifying this line to an absolute jump (JMP instead of JB)? This should force the 1.9 codepath for all calls to time.Now(). Let's see what happens.
rasky
on 12 Jan 2018
after modifying this line to an absolute jump
Magic! Working much better. Changing to a JMP makes the benchmarks between tip and go 1.9 comparable, with tip slightly better.
cep21
on 12 Jan 2018
Nice. What is the output of this program on your Mac?
package main
import (
"fmt"
"unsafe"
)
func main() {
var commpage uintptr = 0x7fffffe0001e
version := *(*uint16)(unsafe.Pointer(commpage))
fmt.Printf("Commpage version: %d\n", version)
}
It'll be 13. It looks like I made an oversight when preparing d8ff3d592: Apple did not increment the commpage version in High Sierra. I had assumed so because they added more fields and changed the way the real time is computed, but that's probably a backward compatible change for whatever API/ABI is enforced for commpage. I should have known better and double-checked with a git blame over XNU sources.
I'll prepare a fix tomorrow.
rasky
on 12 Jan 2018
👍2
@rasky, thanks!
bradfitz
on 12 Jan 2018
Change https://golang.org/cl/87655 mentions this issue: runtime: fix time.Now on Sierra and older
gopherbot
on 13 Jan 2018
@cep21 it would be great if you could test this patch, as I don't have Sierra available.
rasky
on 13 Jan 2018
👍2
@rasky I applied the patch. Benchmark numbers are back down.
cep21
on 13 Jan 2018
Was this page helpful?
0 / 5 - 0 ratings
Related issues
rakyll
·
3Comments
rsc
·
3Comments
jayhuang75
·
3Comments
OneOfOne
·
3Comments
Miserlou
·
3Comments
Most helpful comment
@cep21 it would be great if you could test this patch, as I don't have Sierra available.