Skip to content

runtime: go 1.10beta2 Benchmarks slower on Mac (possibly related to time) #23419

New issue
New issue
Closed
Closed
runtime: go 1.10beta2 Benchmarks slower on Mac (possibly related to time)#23419
Labels
FrozenDueToAgeNeedsFixThe path to resolution is known, but the work has not been done.release-blocker
Milestone
 
Go1.10
@cep21

Description

@cep21
cep21
opened on Jan 11, 2018

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%

Activity

cep21

cep21 commented on Jan 11, 2018

@cep21
cep21
on Jan 11, 2018
Author

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.

bradfitz

bradfitz commented on Jan 11, 2018

@bradfitz
bradfitz
on Jan 11, 2018
Contributor

Is this an appropriate use of github issues?

Yes.

bradfitz
added
NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
release-blocker
on Jan 11, 2018
bradfitz
added this to the Go1.10 milestone on Jan 11, 2018
bradfitz

bradfitz commented on Jan 11, 2018

@bradfitz
bradfitz
on Jan 11, 2018
Contributor

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?

ianlancetaylor
changed the title [-]go 1.10beta2 Benchmarks slower on Mac (possibly related to time)[/-] [+]runtime: go 1.10beta2 Benchmarks slower on Mac (possibly related to time)[/+] on Jan 11, 2018
ianlancetaylor

ianlancetaylor commented on Jan 11, 2018

@ianlancetaylor
ianlancetaylor
on Jan 11, 2018
Contributor

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

cep21

cep21 commented on Jan 11, 2018

@cep21
cep21
on Jan 11, 2018
Author

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
bradfitz

bradfitz commented on Jan 11, 2018

@bradfitz
bradfitz
on Jan 11, 2018
Contributor

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?

ianlancetaylor

ianlancetaylor commented on Jan 11, 2018

@ianlancetaylor
ianlancetaylor
on Jan 11, 2018
Contributor

@cep21 Which version of Darwin are you using? Are you running it on a physical machine or some sort of VM?

cep21

cep21 commented on Jan 11, 2018

@cep21
cep21
on Jan 11, 2018
Author

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)

rasky

rasky commented on Jan 11, 2018

@rasky
rasky
on Jan 11, 2018 · edited by rasky
Member

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

↪ 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).

cep21

cep21 commented on Jan 11, 2018

@cep21
cep21
on Jan 11, 2018 · edited by cep21
Author

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

cep21 commented on Jan 11, 2018

@cep21
cep21
on Jan 11, 2018 · edited by cep21
Author

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

3 remaining items

rasky

rasky commented on Jan 12, 2018

@rasky
rasky
on Jan 12, 2018 · edited by rasky
Member

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.

cep21

cep21 commented on Jan 12, 2018

@cep21
cep21
on Jan 12, 2018
Author

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.

rasky

rasky commented on Jan 12, 2018

@rasky
rasky
on Jan 12, 2018
Member

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)
}
rasky

rasky commented on Jan 12, 2018

@rasky
rasky
on Jan 12, 2018
Member

It'll be 13. It looks like I made an oversight when preparing d8ff3d5: 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
added
NeedsFixThe path to resolution is known, but the work has not been done.
and removed
NeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.
on Jan 12, 2018
rasky
self-assigned this
on Jan 12, 2018
bradfitz

bradfitz commented on Jan 12, 2018

@bradfitz
bradfitz
on Jan 12, 2018
Contributor

@rasky, thanks!

gopherbot

gopherbot commented on Jan 13, 2018

@gopherbot
gopherbot
on Jan 13, 2018
Contributor

Change https://golang.org/cl/87655 mentions this issue: runtime: fix time.Now on Sierra and older

rasky

rasky commented on Jan 13, 2018

@rasky
rasky
on Jan 13, 2018
Member

@cep21 it would be great if you could test this patch, as I don't have Sierra available.

cep21

cep21 commented on Jan 13, 2018

@cep21
cep21
on Jan 13, 2018
Author

@rasky I applied the patch. Benchmark numbers are back down.

gopherbot
closed this as completedin 2d6f941on Jan 16, 2018
golang
locked and limited conversation to collaborators on Jan 16, 2019
gopherbot
added
FrozenDueToAge
on Jan 16, 2019
rsc
unassigned
rasky
on Jun 23, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    FrozenDueToAgeNeedsFixThe path to resolution is known, but the work has not been done.release-blocker

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

      Development

      No branches or pull requests

        Participants

        @bradfitz@cep21@rasky@ianlancetaylor@gopherbot

        Issue actions
          runtime: go 1.10beta2 Benchmarks slower on Mac (possibly related to time) · Issue #23419 · golang/go