cmd/go: increase in compile time in 1.12beta2 compared to go1.10.7

[glycerine]

go1.12beta2 is much, much slower than go1.10.7 at compiling, on OSX darwin 10.13.6 amd64.

go1.12beta2 takes 6.7 seconds to do the same build that go1.10.7 does in 2.4 seconds.

specifics:

jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ go version
go version go1.12beta2 darwin/amd64
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/bin/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/pkg/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install

real	0m7.126s
user	0m6.659s
sys	0m1.653s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/bin/ ~/go/pkg/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ sudo su -
Password:
jatens-MacBook-Pro:~ root# cd /usr/local
jatens-MacBook-Pro:local root# rm go
jatens-MacBook-Pro:local root# ln -s go1.10.7 go
jatens-MacBook-Pro:local root# logout
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ go version
go version go1.10.7 darwin/amd64
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install
# github.com/cosmos72/gomacro
ld: warning: text-based stub file /System/Library/Frameworks//Security.framework/Security.tbd and library file /System/Library/Frameworks//Security.framework/Security are out of sync. Falling back to library file for linking.
ld: warning: text-based stub file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit.tbd and library file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit are out of sync. Falling back to library file for linking.

real	0m3.004s
user	0m2.390s
sys	0m0.843s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/bin/ ~/go/pkg/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install
# github.com/cosmos72/gomacro
ld: warning: text-based stub file /System/Library/Frameworks//Security.framework/Security.tbd and library file /System/Library/Frameworks//Security.framework/Security are out of sync. Falling back to library file for linking.
ld: warning: text-based stub file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit.tbd and library file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit are out of sync. Falling back to library file for linking.

real	0m2.494s
user	0m2.356s
sys	0m0.618s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/bin/ ~/go/pkg/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ sudo su 
root@jatens-MacBook-Pro /Users/jaten/go/src/github.com/cosmos72/gomacro (master) $ cd /usr/local
root@jatens-MacBook-Pro /usr/local $ rm go
root@jatens-MacBook-Pro /usr/local $ ln -s go1.12beta2 go
root@jatens-MacBook-Pro /usr/local $ exit
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ go version
go version go1.12beta2 darwin/amd64
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install

real	0m6.640s
user	0m6.649s
sys	0m1.440s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/bin/ ~/go/pkg/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install

real	0m6.889s
user	0m6.815s
sys	0m1.447s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $

update: for comparison, here is go1.11.1. Nowhere near the slowness of go1.12beta2.

jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ go version
go version go1.11.1 darwin/amd64
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/pkg/ ~/go/bin/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install
# github.com/cosmos72/gomacro
ld: warning: text-based stub file /System/Library/Frameworks//Security.framework/Security.tbd and library file /System/Library/Frameworks//Security.framework/Security are out of sync. Falling back to library file for linking.
ld: warning: text-based stub file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit.tbd and library file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit are out of sync. Falling back to library file for linking.

real	0m3.800s
user	0m3.003s
sys	0m1.021s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ rm -rf ~/go/pkg/ ~/go/bin/
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $ time go install
# github.com/cosmos72/gomacro
ld: warning: text-based stub file /System/Library/Frameworks//Security.framework/Security.tbd and library file /System/Library/Frameworks//Security.framework/Security are out of sync. Falling back to library file for linking.
ld: warning: text-based stub file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit.tbd and library file /System/Library/Frameworks//IOKit.framework/Versions/A/IOKit are out of sync. Falling back to library file for linking.

real	0m2.875s
user	0m2.677s
sys	0m0.720s
jaten@jatens-MacBook-Pro ~/go/src/github.com/cosmos72/gomacro (master) $

[mvdan]

Thanks for checking that the slow-down didn't happen on 1.11 - I was about to ask that.

Does this happen only on certain projects, or can you reproduce this build slow-down even on a small "hello world" package build?

What if you disable CGo entirely via CGO_ENABLED=0? What about builds on other operating systems like Linux?

[mvdan]

Could also be interesting to investigate if it's cmd/compile or cmd/link that's taking much more time in 1.12 versus 1.11. You could use go build -x to see how they're executed, but I don't think it measures times.

/cc @randall77 @ianlancetaylor @dr2chase - I believe some of the people in the Go team run OSX too, so perhaps they can investigate.

[randall77]

I don't see any major differences here. Tip might be 7% slower than 1.11 and 15% slower than 1.10.
I used -a to avoid caches. I'm not 100% sure how that compares to using your rm commands to avoid the build cache. (Isn't the build cache somewhere else at tip? That would make tip faster, not slower, so maybe I'm wrong.)

$ go get github.com/cosmos72/gomacro
$ cd ~/gopath/src/github.com/cosmos72/gomacro/
$ time ~/go1.10/bin/go install -a

real	0m19.432s
user	0m57.310s
sys	0m5.112s
$ time ~/go1.10/bin/go install -a

real	0m18.857s
user	0m56.311s
sys	0m4.694s

$ time ~/go1.11/bin/go install -a

real	0m20.942s
user	1m9.190s
sys	0m3.922s
$ time ~/go1.11/bin/go install -a

real	0m20.697s
user	1m8.773s
sys	0m3.983s
$ time ~/sandbox/readonly/bin/go install -a

real	0m22.226s
user	1m14.605s
sys	0m4.396s
$ time ~/sandbox/readonly/bin/go install -a

real	0m22.018s
user	1m14.255s
sys	0m3.899s

[randall77]

BTW, that was on Linux. I'll try again on my mac when I get home.

[bcmills]

@randall77, Linux and Mac performance seem to differ significantly even on the same hardware.

@jayconrod found significant performance differences in the underlying I/O syscalls in #28739.

[randall77]

Similar results in my Mac (Darwin 10.12).
Generally slower than my Linux box, but I don't see a big slowdown from 1.11->1.12.

$ time ~/go1.10/bin/go install -a

real	0m40.321s
user	1m15.655s
sys	0m10.152s
$ time ~/go1.10/bin/go install -a

real	0m40.184s
user	1m15.826s
sys	0m9.766s
$ time ~/go1.11/bin/go install -a

real	0m47.523s
user	1m41.854s
sys	0m11.014s
$ time ~/go1.11/bin/go install -a

real	0m43.962s
user	1m40.507s
sys	0m10.838s
$ time ~/sandbox/readonly/bin/go install -a

real	0m51.789s
user	1m49.250s
sys	0m13.513s
$ time ~/sandbox/readonly/bin/go install -a

real	0m48.613s
user	1m49.298s
sys	0m12.693s

Again, this is using -a, not sure if that's equivalent to what you're doing.

[randall77]

Could it be related to #27415? You could try reverting be10ad7 and see if that helps.

[josharian]

@glycerine would you mind re-running with flags -toolexec=time -x -a added to your build command? That should print the time required for each command. It’d be helpful to find out whether there’s a single command that regressed for you, or whether this is a general slowdown.

If you’re up for a git bisect, that’d also be really helpful.

If neither of those provide sufficient clarity, next step is probably going to be to get pprof information.

[glycerine]

@randall77 Correct me -- I could be wrong -- but I don't think it suffices to just call the top level go command from a different path; because the sub-commands don't get switched over as well...? At least I learned at some point that I couldn't just call a different top level go command to switch... That's why you saw me actually switching the whole /usr/local/go symlink between /usr/local/go1.10.7 and /usr/local/go1.12beta2. But maybe that's an old habit and it is different now...

@josharian, run below with the flags requested. There still seem to be significant differences in timings with -a. Output was too long for a comment, so posted this gist:

https://gist.github.com/glycerine/5bb156bdeea314b215fc2816500bd759

summary:

go version go1.12beta2 darwin/amd64
(env3) jaten@Jasons-MBP ~/go/src/github.com/cosmos72/gomacro (generate) $ time go install -a -toolexec=time -x
...
real    0m59.955s
user    1m47.941s
sys     0m15.453s

rm -rf ~/go/bin ~/go/pkg
vs. go version go1.10.7 darwin/amd64

real    0m50.889s
user    1m17.127s
sys     0m12.131s

update: yes, @josharian, I'm up for a git bisect, but I've never run one so you'll have to tell me exactly what to run.

[glycerine]

I don't think this is specific to osx. I can observe similar differences on linux amd64.

root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# go version
go version go1.10.7 linux/amd64
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to12
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to10
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# go version
go version go1.10.7 linux/amd64
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# time go install

real	0m2.026s
user	0m1.928s
sys	0m0.460s
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to12
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# time go install

real	0m23.377s
user	0m45.588s
sys	0m4.612s
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# go version
go version go1.12beta2 linux/amd64
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to10
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# time go install

real	0m2.187s
user	0m2.240s
sys	0m0.416s
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to12
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# go version
go version go1.12beta2 linux/amd64
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# time go install

real	0m4.003s
user	0m3.984s
sys	0m0.648s
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to10
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# time go install

real	0m2.070s
user	0m2.052s
sys	0m0.420s
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# to12
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# time go install

real	0m3.950s
user	0m3.816s
sys	0m0.664s
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro#
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# cat `which to10`
#!/bin/bash
rm /usr/local/go
rm -rf /root/go/pkg /root/go/bin
ln -s /usr/local/go1.10.7 /usr/local/go
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro# cat `which to12`
#!/bin/bash
rm /usr/local/go
rm -rf /root/go/pkg /root/go/bin
ln -s /usr/local/go1.12beta2 /usr/local/go
root@benchgo12-s-6vcpu-16gb-sfo2-01:~/go/src/github.com/cosmos72/gomacro#

update: I do notice that gomacro uses CGO/gcc.

[agnivade]

This is what I get on my linux box -
1.11.2

~/play/go/src/github.com/cosmos72/gomacro$time go install -a

real	0m42.938s
user	1m58.564s
sys	0m4.240s

cached -

~/play/go/src/github.com/cosmos72/gomacro$time go install

real	0m0.191s
user	0m0.284s
sys	0m0.044s

1.12beta1

~/play/go/src/github.com/cosmos72/gomacro$time PATH=~/sdk/go1.12beta1/bin:$PATH go install -a

real	0m45.856s
user	2m6.028s
sys	0m4.860s

cached -

~/play/go/src/github.com/cosmos72/gomacro$time PATH=~/sdk/go1.12beta1/bin:$PATH go install 

real	0m0.198s
user	0m0.312s
sys	0m0.036s

A difference of a couple of seconds.

@glycerine - git bisect is a standard technique to find faulty commits. Nothing specific to Go project. You can find lot of material online.

In short, find the commit hash range you want to check (in our case start of 1.12 to end of 1.12), then git bisect start <start_commit> <end_commit>. And then you have to run make.bash for every iteration, test the install time with the generated binary, and mark git bisect good|bad accordingly.

[glycerine]

@agnivade would you mind, on your linux box, repeating exactly the procedure I did that showed the difference. Can you reproduce it that way?

[agnivade]

That is what I have done effectively. To do it exactly would mean to nuke my /usr/local/go and have version specific installations under /usr/local/ which I don't want to do. One difference is that you haven't used -a on your linux box results. So that may be a factor.

Also, note that for the first time, the kernel buffer cache will be empty, so it will naturally take more time than consecutive ones. I would just discard the result of the first run to ignore those effects.

[mvdan]

Correct me -- I could be wrong -- but I don't think it suffices to just call the top level go command from a different path; because the sub-commands don't get switched over as well...?

If you're manually setting GOROOT=/usr/lib/go, then yes, you'll have to either change that variable, or what's in that directory.

If you're not setting GOROOT (which you likely shouldn't), recent Go versions find the internal tools like compile and link via where the go binary you're running is. For example, I have go pointing at ~/tip/bin/go, and alias go1=/usr/bin/go. Both work just fine, using their respective toolchains.

[bcmills]

We have a standard way to swap out (recent) go versions for comparison. Please use it, so that we can be more confident that the comparison is apples-to-apples.

$ go get golang.org/dl/go1.10.7
$ go1.10.7 download
$ go get golang.org/dl/go1.11.4
$ go1.11.4 download
$ go get golang.org/dl/gotip
$ gotip download

$ go1.10.7 clean -cache
$ time go1.10.7 install […]
$ time go1.10.7 install […]
$ go1.11.4 clean -cache
$ time go1.11.4 install […]
$ time go1.11.4 install […]
$ gotip clean -cache
$ time gotip install […]
$ time gotip install […]

[robpike]

@bcmills: Where is this standard documented? I haven't seen this before.

[bcmills]

We've advertised them in every (recent) release announcement.

For example, in the Go 1.12beta2 announcement:

If you have Go installed already, the easiest way to try go1.12beta2
is by using the go command:

$ go get golang.org/dl/go1.12beta2
$ go1.12beta2 download

[robpike]

Need to pay more attention I guess....

[mvdan]

@robpike that is precisely why I raised this CL last week: https://go-review.googlesource.com/c/go/+/157457

[pwaller]

I just tried to reproduce on Darwin but didn't find a significant difference.

I got quite different timings on first run vs subsequent runs, however. Here's the data I got for compiling a small-to-medium size project below. If I take the worst tip and compare with best go1.11 (pessimal), gotip is 1.5x slower in realtime. More fairly, comparing the medians gives 1.1x slower. But I can't reproduce a 2.8x slower on tip.

for i in {1..3}; do go1.11.4 clean -cache; time go1.11.4 install; done

real	0m9.445s
user	0m41.235s
sys	0m4.506s

real	0m7.318s
user	0m39.328s
sys	0m4.408s

real	0m6.963s
user	0m39.353s
sys	0m4.249s

for i in {1..3}; do gotip clean -cache; time gotip install; done

real	0m10.790s
user	0m45.427s
sys	0m5.499s

real	0m8.254s
user	0m43.752s
sys	0m5.095s

real	0m8.220s
user	0m45.220s
sys	0m5.111s

edit: Numbers for 1.10.7, since the above comparison was 1.11 vs tip, rather than 1.10 vs tip. It is again slightly faster but not significantly so (1.23x realtime gotip vs 1.10).

real	0m8.514s
user	0m36.115s
sys	0m4.612s

real	0m6.713s
user	0m33.987s
sys	0m4.310s

real	0m6.656s
user	0m34.019s
sys	0m4.296s

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)