cmd/test2json: go test -bench -json -count output is inconsistent

[FiloSottile]

Go version

go version go1.22.2 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/filippo/Library/Caches/go-build'
GOENV='/Users/filippo/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/filippo/pkg/mod'
GONOPROXY='github.com/FiloSottile/*,filippo.io/*'
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/filippo'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org'
GOROOT='/Users/filippo/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.2.darwin-arm64'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/filippo/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.2.darwin-arm64/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.2'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/filippo/src/filippo.io/mlkem768/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/_j/hq4ytn1n4b94fhrpvvb9tktr0000gn/T/go-build3229174055=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

$ go test -run ^$ -bench BenchmarkKeyGen -count 2 -json

What did you see happen?

{"Time":"2024-04-14T18:19:51.384784+02:00","Action":"start","Package":"filippo.io/mlkem768"}
{"Time":"2024-04-14T18:19:51.637613+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"goos: darwin\n"}
{"Time":"2024-04-14T18:19:51.637714+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"goarch: arm64\n"}
{"Time":"2024-04-14T18:19:51.637721+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"pkg: filippo.io/mlkem768\n"}
{"Time":"2024-04-14T18:19:51.637745+02:00","Action":"run","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen"}
{"Time":"2024-04-14T18:19:51.63775+02:00","Action":"output","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen","Output":"=== RUN   BenchmarkKeyGen\n"}
{"Time":"2024-04-14T18:19:51.637758+02:00","Action":"output","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen","Output":"BenchmarkKeyGen\n"}
{"Time":"2024-04-14T18:19:53.222257+02:00","Action":"output","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen","Output":"BenchmarkKeyGen-8   \t   28196\t     40652 ns/op\n"}
{"Time":"2024-04-14T18:19:54.824157+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"BenchmarkKeyGen-8   \t   28791\t     40964 ns/op\n"}
{"Time":"2024-04-14T18:19:54.824209+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"PASS\n"}
{"Time":"2024-04-14T18:19:54.824632+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"ok  \tfilippo.io/mlkem768\t3.440s\n"}
{"Time":"2024-04-14T18:19:54.824673+02:00","Action":"pass","Package":"filippo.io/mlkem768","Elapsed":3.44}

Note how the first timing output line has the Test field, and the second one doesn't.

What did you expect to see?

Either both output events having the Test field set (which is what makes more sense to me and would make it easier to extract the data I am looking for, since without Test field I have to manually filter out metadata and result option lines), or neither (which curiously is what go doc test2json claims).

When a benchmark runs, it typically produces a single line of output giving timing results. That line is reported in an event with Action == "output" and no Test field.

[cherrymui]

cc @aclements