testing: align package duration values

[mdwhatcott]

1. What version of Go am I using?

go version go1.6.2 darwin/amd64

2. What operating system and processor architecture am I using?

GOARCH="amd64"
GOOS="darwin"

3. What did I do?

$ go get github.com/smartystreets/gunit
$ cd $GOPATH/src/github.com/smartystreets/gunit
$ go test ./...

4. What did I want to see?

ok      0.007s  github.com/smartystreets/gunit
ok      0.006s  github.com/smartystreets/gunit/advanced_examples
ok      0.009s  github.com/smartystreets/gunit/basic_examples
?               github.com/smartystreets/gunit/gunit [no test files]
ok      0.011s  github.com/smartystreets/gunit/gunit/generate
ok      0.008s  github.com/smartystreets/gunit/gunit/parse

5. What did I see instead?

ok      github.com/smartystreets/gunit  0.007s
ok      github.com/smartystreets/gunit/advanced_examples    0.006s
ok      github.com/smartystreets/gunit/basic_examples   0.009s
?       github.com/smartystreets/gunit/gunit    [no test files]
ok      github.com/smartystreets/gunit/gunit/generate   0.011s
ok      github.com/smartystreets/gunit/gunit/parse  0.008s

In the spirit of #10594 I propose that the duration of each package be aligned vertically for ease of comparison and to make sorting by duration a more obvious option:

$ go test ./... | egrep "\?|ok|FAIL" | sort -k2
?               github.com/smartystreets/gunit/gunit [no test files]
ok      0.006s  github.com/smartystreets/gunit/advanced_examples
ok      0.007s  github.com/smartystreets/gunit
ok      0.008s  github.com/smartystreets/gunit/gunit/parse
ok      0.009s  github.com/smartystreets/gunit/basic_examples
ok      0.011s  github.com/smartystreets/gunit/gunit/generate

[meirf]

Maybe I shouldn't be conflating the two but if package duration values are aligned, then people might expect the same for individual tests. One problem with aligning for individual tests is the case of subtests:

=== RUN   TestTime
=== RUN   TestTime/12:31_in_Europe/Zuri
=== RUN   TestTime/12:31_in_America/New_York
--- PASS: TestTime (2.01s)
    --- PASS: TestTime/12:31_in_Europe/Zuri (1.01s)
    --- PASS: TestTime/12:31_in_America/New_York (1.00s)
PASS
ok  	command-line-arguments	2.019s

If all the times were aligned it would be confusing to sort since the time next to a node in a subtest tree is the cumulative time of all its descendants. You would be including cumulative values with non-cumulative values.

Maybe the gain to package durations is enough of a win that people wouldn't mind the inconsistency between packages and individual tests.

@bcmills

---

For completeness, I should mention that the 1.10 release includes:

Finally, the new go test -json flag filters test output through the new command go tool test2json to produce a machine-readable JSON-formatted description of test execution. This allows the creation of rich presentations of test execution in IDEs and other tools.

I still think the use case presented by the OP is significant for a human and the new json functionality is kind of heavyweight for just looking around at test performance.

[mdwhatcott]

@meirf - I opened this issue before subtests were released with go 1.7--I probably wasn't thinking about their effect. I don't see a way to move this issue forward and I'm included to close it.

[bcmills]

It would still be possible to align the times for each level.

=== RUN   TestTime
=== RUN   TestTime/12:31_in_Europe/Zuri
=== RUN   TestTime/12:31_in_America/New_York
--- PASS (2.01s): TestTime
    --- PASS (1.01s): TestTime/12:31_in_Europe/Zuri
    --- PASS (1.00s): TestTime/12:31_in_America/New_York
PASS
ok	2.019s	command-line-arguments

Compatibility with #24929 seems to require that we move the time to the beginning instead of the end, since we won't know the maximum line length until all of the subtests have at least started.

[mdwhatcott]

@bcmills - Yes, that's true. Good point.

[rsc]

I don't believe we should change the default output. That will break existing test output processors, both programs and people's habits, for only a fairly small benefit. And not everyone will prefer the new output either (I know I don't), so it's a significant churn for what is not a clear win.

People who want alternate displays should build them by using go test -json and processing the JSON.