cmd/go: 'go test -json -bench' misattributes benchmark output to prior tests

[tebeka]

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

go version go1.11 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/miki/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/miki/Projects/go"
GOPROXY=""
GORACE=""
GOROOT="/opt/go"
GOTMPDIR=""
GOTOOLDIR="/opt/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build566604237=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Running go test -v -bench . --json on a simple test. See https://play.golang.org/p/m2rEGNYaHAL

What did you expect to see?

Benchmark output in it's own test name (e.g. BenchmarkAdd-4)

What did you see instead?

Benchmark output reported under a test function name.

Lines like

{"Time":"2018-09-19T16:16:03.409160347-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"2000000000\t         0.29 ns/op\n"}

See full output below

{"Time":"2018-09-19T16:16:02.805686252-07:00","Action":"run","Package":"_/tmp/bench","Test":"TestAdd"}
{"Time":"2018-09-19T16:16:02.805789664-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"=== RUN   TestAdd\n"}
{"Time":"2018-09-19T16:16:02.805805951-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"--- PASS: TestAdd (0.00s)\n"}
{"Time":"2018-09-19T16:16:02.806048353-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"goos: linux\n"}
{"Time":"2018-09-19T16:16:02.806059884-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"goarch: amd64\n"}
{"Time":"2018-09-19T16:16:02.806068435-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"BenchmarkAdd-4   \t"}
{"Time":"2018-09-19T16:16:03.409160347-07:00","Action":"output","Package":"_/tmp/bench","Test":"TestAdd","Output":"2000000000\t         0.29 ns/op\n"}
{"Time":"2018-09-19T16:16:03.409188589-07:00","Action":"pass","Package":"_/tmp/bench","Test":"TestAdd","Elapsed":0}
{"Time":"2018-09-19T16:16:03.409195398-07:00","Action":"output","Package":"_/tmp/bench","Output":"PASS\n"}
{"Time":"2018-09-19T16:16:03.40939684-07:00","Action":"output","Package":"_/tmp/bench","Output":"ok  \t_/tmp/bench\t0.604s\n"}
{"Time":"2018-09-19T16:16:03.409405317-07:00","Action":"pass","Package":"_/tmp/bench","Elapsed":0.604}

[agnivade]

It is because you are mixing the tests and benchmarks. Try adding -run=xxx.

[tebeka]

Since go test allows running both tests and benchmark at the same time, I expect the output to be accurate :)

When I run go test -v . -bench . --json -run XXX I get results with no associated benchmark name. IMO there should be a Benchmark field with the benchmark name.

{"Time":"2018-09-19T22:18:26.575775799-07:00","Action":"output","Package":"_/tmp/bench","Output":"goos: linux\n"}
{"Time":"2018-09-19T22:18:26.57589252-07:00","Action":"output","Package":"_/tmp/bench","Output":"goarch: amd64\n"}
{"Time":"2018-09-19T22:18:26.575901836-07:00","Action":"output","Package":"_/tmp/bench","Output":"BenchmarkAdd-4   \t"}
{"Time":"2018-09-19T22:18:27.182466332-07:00","Action":"output","Package":"_/tmp/bench","Output":"2000000000\t         0.29 ns/op\n"}
{"Time":"2018-09-19T22:18:27.182503397-07:00","Action":"output","Package":"_/tmp/bench","Output":"PASS\n"}
{"Time":"2018-09-19T22:18:27.182767912-07:00","Action":"output","Package":"_/tmp/bench","Output":"ok  \t_/tmp/bench\t0.608s\n"}
{"Time":"2018-09-19T22:18:27.182779766-07:00","Action":"pass","Package":"_/tmp/bench","Elapsed":0.608}

[agnivade]

I got you now. Then this is a different issue. You want the benchmark name to be there while running benchmarks.

According to go doc test2json, this is working as intended.

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. If a benchmark logs output or reports a failure (for
example, by using b.Log or b.Error), that extra output is reported as a
sequence of events with Test set to the benchmark name, terminated by a
final event with Action == "bench" or "fail". Benchmarks have no events with
Action == "run", "pause", or "cont".

So it seems, if we just run the benchmarks with no logging, the benchmark name is not set. And if both tests and benchmarks are run together, the test name gets set to the last test that was run. Looks like something that should be fixed.

@ianlancetaylor @rsc @bcmills

[gopherbot]

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies