How does time reported by go test relate to the wall clock time?

[Prateek Rungta]

I've noticed weird discrepancies in the time reported by `go test <packages>`, and the elapsed wall clock time. 

For example: 

❯ time go test ./client

ok   github.com/m3db/m3db/client 11.717s

/Users/prungta/code/go1.9.2/bin/go test ./client  10.54s user 1.58s system 74% cpu 16.233 total

❯ time go test ./storage

ok   github.com/m3db/m3db/storage 4.830s

/Users/prungta/code/go1.9.2/bin/go test ./storage  10.19s user 1.49s system 107% cpu 10.860 total

How does `go test` calculate the time it reports?

[Jan Mercl]

time reports build+test time, but go test reports only test time.

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

-j

[Prateek Rungta]

Thanks, that makes sense I guess. Would people be opposed to changing that behavior?

I’ve always thought of the time returned as the time to execute the command. Doesn’t matter to me if it’s having to compile or not. 

[Jan Mercl]

On Fri, Apr 27, 2018 at 8:17 AM Prateek Rungta <prun...@gmail.com> wrote:


> Would people be opposed to changing that behavior?

I guess so.

> I’ve always thought of the time returned as the time to execute the command. Doesn’t matter to me if it’s having to compile or not. 

The use the time command.

I do not understand, what's the problem. Two different methods report two different values because they measure two different things. What's the point of somehow forcing the values to be the same?

Possibly illustrative experiment:

jnml@4670:~/src/github.com/cznic/ql> go clean -cache

jnml@4670:~/src/github.com/cznic/ql> time go test

PASS

ok  github.com/cznic/ql 9.607s

real 0m11.708s

user 0m8.006s

sys 0m0.489s

jnml@4670:~/src/github.com/cznic/ql> go test -c && time ./ql.test

PASS

real 0m9.671s

user 0m3.551s

sys 0m0.171s

jnml@4670:~/src/github.com/cznic/ql>

Above we can see the reported 6.7 seconds are in both cases the time to execute the test binary per se. Additional 2.1 seconds were spent in producing the binary.

--

-j

[Jan Mercl]

On Fri, Apr 27, 2018 at 8:36 AM Jan Mercl <0xj...@gmail.com> wrote:

> Above we can see the reported 6.7 seconds are in both cases the time to execute the test binary per se. Additional 2.1 seconds were spent in producing the binary.

s/6.7/9.6/

--

-j

[Dave Cheney]

Try upgrading to go 1.10. You’ll get build and test caching for free and you’ll see a small variance between the timings you reported.