Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cmd/go: slow builds on ARM (go build doesn't install deps?) #20372

Closed
dertarr opened this issue May 16, 2017 · 8 comments
Closed

cmd/go: slow builds on ARM (go build doesn't install deps?) #20372

dertarr opened this issue May 16, 2017 · 8 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@dertarr
Copy link

dertarr commented May 16, 2017

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

1.8.1 (and 1.7.5 to compare with)

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

RaspberryPi model 3B with raspbian OS
GOARCH="arm"
GOBIN=""
GOEXE=""
GOHOSTARCH="arm"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/mkk/gopath"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_arm"
CC="gcc"
GOGCCFLAGS="-fPIC -marm -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build329748828=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"

What did you do?

My code is using sqlx library and SQLite3 driver. I'm using go test command with --cover argument.
Here is a repo to clone: https://dertarr@bitbucket.org/dertarr/wfrp3-data-fork.git
To reproduce the issue, clone the repository at commit a40a933, CD to cd almacen, go get all external libraries and make test.

$ git clone https://dertarr@bitbucket.org/dertarr/wfrp3-data-fork.git
$ git reset --hard a40a933
$ cd wfrp3-data/almacen
$ go get github.com/op/go-logging github.com/gorilla/mux github.com/jmoiron/sqlx github.com/mattn/go-sqlite3 github.com/stretchr/testify/assert
$ make test

There will be several errors in the output - this is expected:

# _/mkk/wfrp3-data/almacen/whdbobj
/tmp/go-build545648482/_/mkk/wfrp3-data/almacen/whdbobj/_test/_obj_test/cardaction.go:258: undefined: err
/tmp/go-build545648482/_/mkk/wfrp3-data/almacen/whdbobj/_test/_obj_test/cardaction.go:291: multiple-value json.Marshal() in single-value context
/tmp/go-build545648482/_/mkk/wfrp3-data/almacen/whdbobj/_test/_obj_test/cardaction.go:297: cannot use ca.cons.MainText (type string) as type []string in field value
/tmp/go-build545648482/_/mkk/wfrp3-data/almacen/whdbobj/_test/_obj_test/cardaction.go:298: cannot use ca.reck.MainText (type string) as type []string in field value
/tmp/go-build545648482/_/mkk/wfrp3-data/almacen/whdbobj/_test/_obj_test/cardaction.go:300: no new variables on left side of :=
/tmp/go-build545648482/_/mkk/wfrp3-data/almacen/whdbobj/_test/_obj_test/cardaction.go:309: missing return at end of function
?       _/mkk/wfrp3-data/almacen        [no test files]
FAIL    _/mkk/wfrp3-data/almacen/whdbobj [build failed]
Makefile:33: recipe for target 'test' failed
make: *** [test] Error 2

Another side issue is that line numbers in error messages are not correct. For example, the first error states that there is an undefined "err" at line 258 of file "cardaction.go", but line 258 returns an empty string and does not mention "err". Version 1.7.5 was displaying different line numbers for the same error messages, but not correct either: it complains about undefined "err" on line 261, which is a comment line. This happens probably due to presence of multi-line strings enclosed in backticks.

What did you expect to see?

  • The command executes is just a several seconds (as in version 1.7.5)
  • (Side issue) Error messages display correct line numbers. For example, the undefined "err" is on line 216.

What did you see instead?

  • It takes a couple of minutes to execute make test on version 1.8.1 ARMv6.
  • Incorrect line numbers in the output
@josharian
Copy link
Contributor

Some more information would be helpful.

Why concretely do you think it should only take seconds? Is the slow thing compiling the tests or executing the tests? Is 1.7.5 (or tip) faster?

Also, would you mind filing a separate issue about the line numbers, so that it doesn't get lost? Thanks.

@dertarr
Copy link
Author

dertarr commented May 16, 2017

I was using 1.7.5 and was used to the performance I had. When I downloaded 1.8.1 to replace 1.7.5, I notices vast performance drop: from some 12 seconds to about 3 minutes.

The slow thing is compiling. This is the command that executes slow:
$ go build --ldflags '-extldflags "-static"' -v .
Here is the output:

github.com/jmoiron/sqlx/reflectx
github.com/gorilla/mux
golang.org/x/net/context
github.com/op/go-logging
github.com/mattn/go-sqlite3
github.com/jmoiron/sqlx
_/mkk/wfrp3-data/almacen

The execution "halts" for almost 3 minutes after github.com/jmoiron/sqlx is printed and before _/mkk/wfrp3-data/almacen is printed. The presence of flags does not impact the performance, so the following command takes just the same time (~3 minutes) to execute.
go build -v .

PS. I'll file a separate issue about line numbers a bit later.

@ALTree
Copy link
Member

ALTree commented May 16, 2017

Please do a go install (instead of go build) and test again. Are the tests still slow?

@bradfitz
Copy link
Contributor

Yeah, this is almost certainly because go build doesn't do any caching, which we have existing bugs open for. If you run go install or go test -i then subsequent builds will not have to rebuild all the dependencies. (This is not ARM-specific)

@bradfitz bradfitz added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 16, 2017
@bradfitz bradfitz changed the title Performance is very low on ARM cmd/go: slow builds on ARM (go build doesn't install deps?) May 16, 2017
@dertarr
Copy link
Author

dertarr commented May 16, 2017

Ok. I had to copy "almacen" directory to under GOPATH. My GOPATH is /mkk/gopath, so the full application path is now /mkk/gopath/src/bitbucket.org/dertarr/wfrp3-data/almacen.
Executed the following (with the output) on version 1.8.1:

pi@raspberrypi:/mkk/gopath/src/bitbucket.org/dertarr/wfrp3-data/almacen $ go install -v .
github.com/gorilla/mux
github.com/op/go-logging
github.com/jmoiron/sqlx/reflectx
golang.org/x/net/context
github.com/mattn/go-sqlite3
github.com/jmoiron/sqlx
bitbucket.org/dertarr/wfrp3-data/almacen

It took 3 minutes to complete. Executing the same command for the second time takes almost no time. Then I updated a string literal inside my code and executed the command for the third time. The output is shorter, and the command completes in about 5 seconds, as it doesn't need to rebuild all libraries:

pi@raspberrypi:/mkk/gopath/src/bitbucket.org/dertarr/wfrp3-data/almacen $ go install -v .
bitbucket.org/dertarr/wfrp3-data/almacen

Then I switched to version 1.7.5. and deleted /mkk/gopath/pkg/linux_arm/github.com/jmoiron directory. Executed the command:

pi@raspberrypi:/mkk/gopath/src/bitbucket.org/dertarr/wfrp3-data/almacen $ go install -v .
github.com/gorilla/mux
golang.org/x/net/context
github.com/jmoiron/sqlx/reflectx
github.com/op/go-logging
github.com/mattn/go-sqlite3
github.com/jmoiron/sqlx
bitbucket.org/dertarr/wfrp3-data/almacen

It took the same 3 minutes to complete (it was rebuilding all libraries, not just the sqlx). I reverted the changes in the string literal and repeated go install -v . - the command completed in some 5 seconds.

@dertarr
Copy link
Author

dertarr commented May 16, 2017

So, the issue appeared in go build with version 1.8.1?

@bradfitz
Copy link
Contributor

Sounds like this is just the build caching issue, which is known. The meta bug of sorts is #4719 which is partially about removing the need to "install" built deps and just always cache them. We've been making progress towards this over the past few releases, making the buildid in object files more inclusive. But more remains.

I'm going to close this issue. For now, keep in mind that you need to run go install or go test -i to install deps when switching versions if you want go build or go test to be fast.

@gopherbot
Copy link

Change https://golang.org/cl/75473 mentions this issue: cmd/go: cache built packages

gopherbot pushed a commit that referenced this issue Nov 3, 2017
This CL adds caching of built package files in $GOCACHE, so that
a second build with a particular configuration will be able to reuse
the work done in the first build of that configuration, even if the
first build was only "go build" and not "go install", or even if there
was an intervening "go install" that wiped out the installed copy of
the first build.

The benchjuju benchmark runs go build on a specific revision of jujud 10 times.

Before this CL:

	102.72u 15.29s 21.98r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	105.99u 15.55s 22.71r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	106.49u 15.70s 22.82r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	107.09u 15.72s 22.94r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	108.19u 15.85s 22.78r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	108.92u 16.00s 23.02r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	109.25u 15.82s 23.05r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	109.57u 15.96s 23.11r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	109.86u 15.97s 23.17r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	110.50u 16.05s 23.37r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...

After this CL:

	113.66u 17.00s 24.17r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.85u 0.68s 3.49r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.98u 0.72s 3.63r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	4.07u 0.72s 3.57r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.98u 0.70s 3.43r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	4.58u 0.70s 3.58r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.90u 0.70s 3.46r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.85u 0.71s 3.52r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.70u 0.69s 3.64r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...
	3.79u 0.68s 3.41r 	 go build -o /tmp/jujud github.com/juju/juju/cmd/jujud ...

This CL reduces the overall all.bash time from 4m22s to 4m17s on my laptop.
Not much faster, but also not slower.

See also #4719, #20137, #20372.

Change-Id: I101d5363f8c55bf4825167a5f6954862739bf000
Reviewed-on: https://go-review.googlesource.com/75473
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: David Crawshaw <crawshaw@golang.org>
@golang golang locked and limited conversation to collaborators Nov 2, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

5 participants