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

tebeka · 2018-09-19T23:17:37Z

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}

The text was updated successfully, but these errors were encountered:

agnivade · 2018-09-20T03:30:24Z

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

tebeka · 2018-09-20T05:20:57Z

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 · 2018-09-20T06:03:44Z

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 · 2022-10-18T14:39:04Z

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

Test2json is parsing the output stream from the test, which includes package testing's own framing lines intermingled with other output, in particular any output printed via fmt.Printf, println, and so on. We have had recurring problems with unexpected partial output lines causing a framing line to be missed. A recent talk at GopherCon gave an example of an integration test involving Docker that happened to print \r-terminated lines instead of \n-terminated lines in some configurations, which in turn broke test2json badly. (https://www.gophercon.com/agenda/session/944259) There are also a variety of open reported issues with similar problems, which this CL also addresses. The general approach is to add a new testing flag -test.v=json that means to print additional output to help test2json. And then test2json takes advantage of that output. Among the fixes: - Identify testing framing more reliably, using ^V (golang#23036, golang#26325, golang#43683, GopherCon talk) - Test that output with \r\n endings is handled correctly (golang#43683, golang#34286) - Use === RUN in fuzz tests (golang#52636, golang#48132) - Add === RUN lines to note benchmark starts (golang#27764, golang#49505) - Print subtest --- PASS/FAIL lines as they happen (golang#29811) - Add === NAME lines to emit more test change events, such as when a subtest stops and the parent continues running. - Fix event shown in overall test failure (golang#27568) - Avoid interleaving of writes to os.Stdout and os.Stderr (golang#33419) Fixes golang#23036. Fixes golang#26325. Fixes golang#27568. Fixes golang#27764. Fixes golang#29811. Fixes golang#33419. Fixes golang#34286. Fixes golang#43683. Fixes golang#49505. Fixes golang#52636. Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6 Reviewed-on: https://go-review.googlesource.com/c/go/+/443596 Auto-Submit: Russ Cox <rsc@golang.org> Run-TryBot: Russ Cox <rsc@golang.org> Reviewed-by: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

agnivade changed the title ~~go test --json incorrectly reports benchmark output~~ cmd/go: Test field should be properly populated when running benchmarks with -json flag Sep 20, 2018

agnivade added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 20, 2018

agnivade added this to the Unplanned milestone Sep 20, 2018

bcmills added the GoCommand cmd/go label Sep 28, 2018

bcmills changed the title ~~cmd/go: Test field should be properly populated when running benchmarks with -json flag~~ cmd/go: 'go test -json -bench' misattributes benchmark output to prior tests Jan 17, 2019

bcmills mentioned this issue Aug 1, 2019

testing: writing to os.Stderr pollutes test names in go test -json output #33419

Closed

bcmills mentioned this issue Dec 5, 2019

cmd/go: go test -json has package output incorrectly attributed to the last test when a test panics #35180

Closed

jayconrod mentioned this issue Mar 25, 2020

testing: bad output formatting when test stdout ends in an incomplete line #38063

Closed

gopherbot closed this as completed in 1c72ee7 Oct 26, 2022

dmitshur modified the milestones: Unplanned, Go1.20 Nov 18, 2022

dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Nov 18, 2022

golang locked and limited conversation to collaborators Nov 18, 2023

gopherbot added the FrozenDueToAge label Nov 18, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

tebeka commented Sep 19, 2018

agnivade commented Sep 20, 2018

tebeka commented Sep 20, 2018 •

edited

agnivade commented Sep 20, 2018

gopherbot commented Oct 18, 2022

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

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

Comments

tebeka commented Sep 19, 2018

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

agnivade commented Sep 20, 2018

tebeka commented Sep 20, 2018 • edited

agnivade commented Sep 20, 2018

gopherbot commented Oct 18, 2022

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

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

tebeka commented Sep 20, 2018 •

edited