cmd/go: add option to output timestamps along with command tracing

[pmenglund]

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

go version go1.8 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=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/englund/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/c4/81xwbyks1c55pm5dxsz2j73xhj07qj/T/go-build552947938=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

When you use the -x flag to build, it wold be useful to be able to pass in -t too, to see the start time of each command to get a rough estimate on where the time is spent. On one server I was working on, a path was NFS mounted, and timestamps would have let me track down the slowdown quicker.

What did you expect to see?

$ go build -x -t
[2017-11-01 09:09:15.653] WORK=/var/folders/c4/81xwbyks1c55pm5dxsz2j73xhj07qj/T/go-build902893394
[2017-11-01 09:09:15.853] mkdir -p $WORK/_/Users/englund/src/go/test/_obj/
[2017-11-01 09:09:16.142] mkdir -p $WORK/_/Users/englund/src/go/test/_obj/exe/
[2017-11-01 09:09:16.653] cd /Users/englund/src/go/test
[2017-11-01 09:09:17.532] /usr/local/go/pkg/tool/darwin_amd64/compile -o $WORK/_/Users/englund/src/go/test.a -trimpath $WORK -p main -complete -buildid 3e52baceee0a3c34b32debe006b809686bc2906c -D _/Users/englund/src/go/test -I $WORK -pack ./main.go
[2017-11-01 09:09:17.653] cd .
[2017-11-01 09:09:18.653] /usr/local/go/pkg/tool/darwin_amd64/link -o $WORK/_/Users/englund/src/go/test/_obj/exe/a.out -L $WORK -extld=clang -buildmode=exe -buildid=3e52baceee0a3c34b32debe006b809686bc2906c $WORK/_/Users/englund/src/go/test.a
[2017-11-01 09:09:19.653] mv $WORK/_/Users/englund/src/go/test/_obj/exe/a.out test

What did you see instead?

$ go build -x
WORK=/var/folders/c4/81xwbyks1c55pm5dxsz2j73xhj07qj/T/go-build902893394
mkdir -p $WORK/_/Users/englund/src/go/test/_obj/
mkdir -p $WORK/_/Users/englund/src/go/test/_obj/exe/
cd /Users/englund/src/go/test
/usr/local/go/pkg/tool/darwin_amd64/compile -o $WORK/_/Users/englund/src/go/test.a -trimpath $WORK -p main -complete -buildid 3e52baceee0a3c34b32debe006b809686bc2906c -D _/Users/englund/src/go/test -I $WORK -pack ./main.go
cd .
/usr/local/go/pkg/tool/darwin_amd64/link -o $WORK/_/Users/englund/src/go/test/_obj/exe/a.out -L $WORK -extld=clang -buildmode=exe -buildid=3e52baceee0a3c34b32debe006b809686bc2906c $WORK/_/Users/englund/src/go/test.a
mv $WORK/_/Users/englund/src/go/test/_obj/exe/a.out test

[rsc]

Note that you can do

go build -x 2>&1 | while read x; do echo "$(date) $x"; done

[pmenglund]

Right, but that primes the cache, which might mask some issues.

[pmenglund]

And I'm willing to take on implementing this feature, once it is deemed as worthwhile to have.

[rsc]

What do you mean "that primes the cache"? My point is that if you want to add timestamps to output you can do that by piping it through a timestamp-adding program (or script).

[pmenglund]

I meant it runs the commands and thus the files end up in the file system cache, which affects the following execution.

[bcmills]

The more work we do in parallel, the less useful timestamps will be, and as @rsc notes you can already pipe the output of go build -x through some other process that can annotate each line with (approximate) timestamps.

I don't think timestamps alone would are worth the complexity (particularly in terms of documentation). I'd be open to a general trace of the build (including both start and stop times, and produced in some standard structured form), but that's a matter for a separate proposal.

[josharian]

I built a pretty decent (if I say so myself) tracer for cmd/go, demo'd in #15736. Perhaps someone would like to revive that?

Note that at the end of that thread, Russ indicated he'd just as soon instead add timing information. So it seems like the two of you are headed in opposite directions.