cmd/compile: GO19CONCURRENTCOMPILATION not working as expected

[nilslice]

Please answer these questions before submitting your issue. Thanks!

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

go1.9rc1

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

linux/amd64

What did you do?

time GO19CONCURRENTCOMPILATION=1 go1.9rc1 build ./*.go

vs.

time GO19CONCURRENTCOMPILATION=0 go1.9rc1 build ./*.go"

If possible, provide a recipe for reproducing the error.

This was tested with github.com/ponzu-cms/ponzu by running:

$ go get github.com/ponzu-cms/ponzu/...
$ ponzu new github.com/nilslice/go19test
$ cd $GOPATH/src/github.com/nilslice/go19test
$ time GO19CONCURRENTCOMPILATION=0 ponzu build --gocmd=go1.9rc1
# (equal to: time GO19CONCURRENTCOMPILATION=0 go1.9rc1 build cmd/ponzu/*.go)
# vs.
$ time GO19CONCURRENTCOMPILATION=1 ponzu build --gocmd=go1.9rc1
# vs.
$ time ponzu build # with go 1.8.3

A link on play.golang.org is best.

What did you expect to see?

I expected to see the build time / CPU usage change more dramatically when toggling concurrent compilation with the GO19CONCURRENTCOMPILATION var set/unset.

What did you see instead?

# go 1.9 with concurrent compilation
time GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -o ponzu-server cmd/ponzu/*.go
GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -o ponzu-server cmd/ponzu/*.go  8.62s user 0.43s system 249% cpu 3.628 total
# ---

# go 1.9 without concurrent comilation
time GO19CONCURRENTCOMPILATION=0 go1.9rc1 build -o ponzu-server cmd/ponzu/*.go
GO19CONCURRENTCOMPILATION=0 go1.9rc1 build -o ponzu-server cmd/ponzu/*.go  8.80s user 0.51s system 245% cpu 3.787 total
# ---

# go 1.8.3
time ponzu build # with go1.8.3 linux/amd64                                        
ponzu build  17.48s user 0.96s system 278% cpu 6.630 total

It appears that there is no difference with or without GO19CONCURRENTCOMPILATION feature, and after looking through go/internal/work/build.go, it seems that the -C or -c flag is not defined, which the surrounding code suggests it would influence the parallel build. In fact, running the build command with either of these flags explicitly set causes a failure: flag provided but not defined: -C or flag provided but not defined: -c (it's here... )

I may have this all wrong, and I couldn't create a more concurrent-happy build (so it may just be that parallel compilation doesn't help me much), but I thought I'd still report what I dug up!

[randall77]

@josharian

[nilslice]

I just realized the -c flag is nested in -gcflags , which my initial tests did not reflect.. here are the same ones under go1.9, still showing little or no difference among them.

time GO19CONCURRENTCOMPILATION=0 go1.9rc1 build -gcflags=-c=1 -o ponzu-server cmd/ponzu/*.go
GO19CONCURRENTCOMPILATION=0 go1.9rc1 build -gcflags=-c=1 -o ponzu-server   1.50s user 0.16s system 132% cpu 1.259 total

# ---

time GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -gcflags=-c=1 -o ponzu-server cmd/ponzu/*.go
GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -gcflags=-c=1 -o ponzu-server   1.48s user 0.19s system 132% cpu 1.255 total

# ---

time GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -gcflags=-c=2 -o ponzu-server cmd/ponzu/*.go
GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -gcflags=-c=2 -o ponzu-server   1.74s user 0.14s system 139% cpu 1.346 total

# ---

time GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -gcflags=-c=4 -o ponzu-server cmd/ponzu/*.go
GO19CONCURRENTCOMPILATION=1 go1.9rc1 build -gcflags=-c=4 -o ponzu-server   1.71s user 0.19s system 113% cpu 1.680 total

UPDATE:
Also seeing now the nBackendWorkers is set to 1 here in scenarios such as mine. I suppose this is expected behavior and there are clearly multiple cores working as reported by time. But, the initial issue stands, that concurrent compilation appears to still be active when GO19CONCURRENTCOMPILATION=0.

Though, I'm unclear if the > 100% cpu usage reported above when GO19CONCURRENTCOMPILATION=0 is taking into account time itself.. the go1.9rc1 build command is actually too fast for me to see it appear regularly in top, but on the occasion I do catch it, link exceeds 100% cpu usage, along with go around 40% - 50%.

[ianlancetaylor]

Assigning to @josharian . We can still get doc changes into 1.9 if appropriate.

[josharian]

Thanks for the report.

I took a look at package github.com/ponzu-cms/ponzu/cmd/ponzu. Concurrent compilation is working as anticipated, and seems to have an impact in the 30-35% range. However, build time for this package is dominated the by linker, you so can't really tell. Try running:

$ cd $GOPATH/src/github.com/ponzu-cms/ponzu/cmd/ponzu
$ GO19CONCURRENTCOMPILATION=0 time go build -toolexec='time' -x
$ GO19CONCURRENTCOMPILATION=1 time go build -toolexec='time' -x

This will tell you the individual toolchain commands being run and time them individually, and then print an overall total. On my machine, I see concurrent compilation taking ~0.09s and non-concurrent compilation taking ~0.14s. Linking takes about 0.65s. There's another 0.25s spend in the go command itself and related overhead, like making directories and moving files around, for a total of ~1s. So the 0.05s (35%) that concurrent compilation buys here ends up being only 5% in the context of the complete build, in this particular case.

As for the place where "nBackendWorkers is set to 1", that's addressed in change 41503, which was intentionally held for 1.10. But it's not obvious to me that that is an important factor in this case. If you want to experiment, or if that change makes your life much better now, feel free to cherry-pick that change and rebuild the toolchain.

So I think everything is working as intended here. I don't see any obvious doc changes to make, although I'm open to suggestions.

For now, I'm going to close this, but will re-open if there's new information or suggestions.

[nilslice]

-toolexec='time'

That's cool. Wasn't aware of this -- thanks for pointing it out.

As for the place where "nBackendWorkers is set to 1", that's addressed in change 41503, which was intentionally held for 1.10. But it's not obvious to me that that is an important factor in this case. If you want to experiment, or if that change makes your life much better now, feel free to cherry-pick that change and rebuild the toolchain.

I see -- thank you for pointing this out as well. I couldn't tell how much of each package could be compiled before the nBackendWorkers was reduced there, or if it was done prior to any compilation in some cases.

This was reported entirely out of experimentation, and I hope it didn't cause you many wasted cycles 😬 .. figured I would share what I was seeing before 1.9 hits master. The concurrent compilation is a great feature - thank you for your work on it!! If I have any doc suggestions pre 1.10, I will report back here.

[josharian]

I couldn't tell how much of each package could be compiled before the nBackendWorkers was reduced there

FWIW, this makes a noticeable difference in (generally autogenerated) packages that define thousands of types.

figured I would share what I was seeing before 1.9 hits master.

Appreciated! Very glad you're kicking the tires.