Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
FiloSottile opened this issue Apr 14, 2024 · 1 comment
Open

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

FiloSottile opened this issue Apr 14, 2024 · 1 comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@FiloSottile
Copy link
Contributor

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 cherrymui added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 15, 2024
@cherrymui cherrymui added this to the Backlog milestone Apr 15, 2024
@cherrymui
Copy link
Member

cc @aclements

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
2 participants
@FiloSottile @cherrymui