cmd/go: 'go test' output incompatible with benchstat #21341

bep · 2017-08-08T11:33:05Z

I thought I should take the new Go 1.9rc2 for a spin on Hugo and compare the performance with Go 1.8.3. But when writing the output file to use with benchstat I have to manually remove the goos etc. info that is printed before the actual benchmark results. This info is not present when running the same benchmark with Go 1.8.3.

▶ go1.9rc2 test -run="NONE" -bench="BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1$" -test.benchmem=true -count 5 ./hugolib
goos: darwin
goarch: amd64
pkg: github.com/gohugoio/hugo/hugolib
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 102094187 ns/op	68475372 B/op	  575104 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 102375423 ns/op	68446526 B/op	  574962 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 102479407 ns/op	68487863 B/op	  575091 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 108496033 ns/op	68367944 B/op	  574620 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 100340475 ns/op	68136600 B/op	  573439 allocs/op
PASS
ok  	github.com/gohugoio/hugo/hugolib	6.717s

On the positve note, when I remove those lines and run benchstat:

▶ benchstat go1.8.3.bench go1.9rc2.bench
name                                                                    old time/op    new time/op    delta
SiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4     108ms ± 3%     104ms ± 5%    ~     (p=0.222 n=5+5)

name                                                                    old alloc/op   new alloc/op   delta
SiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4    68.4MB ± 0%    68.4MB ± 0%    ~     (p=0.548 n=5+5)

name                                                                    old allocs/op  new allocs/op  delta
SiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4      599k ± 0%      575k ± 0%  -4.02%  (p=0.008 n=5+5)

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

ALTree · 2017-08-08T11:47:29Z

Can't reproduce the issue:

$ cat old.txt 
BenchmarkA-4   	1000000000	         1.96 ns/op
BenchmarkA-4   	2000000000	         1.96 ns/op
BenchmarkA-4   	2000000000	         1.96 ns/op
BenchmarkA-4   	2000000000	         1.99 ns/op
PASS
ok  	command-line-arguments	14.609s

$ cat new.txt 
goos: linux
goarch: amd64
BenchmarkA-4   	2000000000	         1.97 ns/op
BenchmarkA-4   	2000000000	         1.96 ns/op
BenchmarkA-4   	1000000000	         1.99 ns/op
BenchmarkA-4   	2000000000	         1.97 ns/op
PASS
ok  	command-line-arguments	14.593s

$ benchstat old.txt new.txt 
name  old time/op  new time/op  delta
A-4   1.97ns ± 1%  1.97ns ± 1%   ~     (p=0.486 n=4+4)

Are you using the latest benchstat binary? The one in x/perf/benchstat? The rsc version is deprecated and unmaintained.

mvdan · 2017-08-08T14:45:54Z

I've been using benchstat too (the x/ version) with no problem.

Perhaps it's time to add a run time warning/notice to - or even break - the old tool. @rsc

bep · 2017-08-08T15:08:31Z

I use the one I get from go get golang.org/x/perf/cmd/benchstat. I just deleted it and "re-getted" it to make sure, and did a retest. Same result.

That tool does not print anything on my MacBook with those lines prepended.

I assume someone can fix benchstat to handle this extra info, but I guess there are also other tools in the wild that is broken by this ...?

@ALTree your listing doesn't match mine: Different goos and no pkg, so I wouldn't call it a "reproduce".

ALTree · 2017-08-08T15:11:21Z

@bep thanks for checking. Could you please paste in this issue the two files you are running benchstat on, so that we have an auto-contained reproducer in the report?

bep · 2017-08-08T15:14:18Z

Here it is:

github.com/gohugoio/hugo  master ✔                                                                                                                             6h18m
▶ benchstat ~/go1.8.3.bench ~/go1.9rc2.bench

github.com/gohugoio/hugo  master ✔                                                                                                                             6h18m
▶ cat ~/go1.8.3.bench
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 107999797 ns/op	68518904 B/op	  599247 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 106153851 ns/op	68483199 B/op	  599106 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 108656476 ns/op	68527046 B/op	  599239 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 106619162 ns/op	68415500 B/op	  598777 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 111204176 ns/op	68175992 B/op	  597582 allocs/op
PASS
ok  	github.com/gohugoio/hugo/hugolib	6.837s

github.com/gohugoio/hugo  master ✔                                                                                                                             6h18m
▶ cat ~/go1.9rc2.bench
goos: darwin
goarch: amd64
pkg: github.com/gohugoio/hugo/hugolib
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      20	 101479924 ns/op	68373446 B/op	  574586 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      20	 104989914 ns/op	68233329 B/op	  573879 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 113746025 ns/op	68244142 B/op	  573991 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      10	 102361774 ns/op	68332316 B/op	  574337 allocs/op
BenchmarkSiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4         	      20	  99760404 ns/op	68189966 B/op	  573721 allocs/op
PASS
ok  	github.com/gohugoio/hugo/hugolib	13.247s

ALTree · 2017-08-08T15:40:14Z

Thanks for the reproducer. Also my benchstat was good because I installed it before the change that broke it.

I bisected this to benchstat, cmd/benchstat: group benchmark results . cc @quentinmit

ALTree · 2017-08-08T15:45:49Z

Passing a bogus separator to -split, like this:

benchstat -split XXX ~/go1.8.3.bench ~/go1.9rc2.bench

seems to fix the issue:

$ benchstat -split xxx ~/go1.8.3.bench ~/go1.9rc2.bench
name                                                                    old time/op    new time/op    delta
SiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4     108ms ± 3%     104ms ± 9%    ~     (p=0.151 n=5+5)

name                                                                    old alloc/op   new alloc/op   delta
SiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4    68.4MB ± 0%    68.3MB ± 0%    ~     (p=0.151 n=5+5)

name                                                                    old allocs/op  new allocs/op  delta
SiteBuilding/TOML,num_root_sections=5,num_pages=1000,tags_per_page=1-4      599k ± 0%      574k ± 0%  -4.12%  (p=0.008 n=5+5)

I'm still not sure if the go1.8 vs go1.9 comparison was broken intentionally (and it now requires the use of the -split flag), so I'm leaving this as NeedsInvestigation.

In any case this should (at least) be documented.

ianlancetaylor · 2017-08-08T16:59:17Z

CC @aclements

ianlancetaylor · 2018-03-30T00:41:42Z

As far as I can tell, this is fixed.

ALTree added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Aug 8, 2017

ALTree added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Aug 8, 2017

cespare changed the title ~~cmd/test: Output incompatible with benchstat~~ cmd/go: 'go test' output incompatible with benchstat Aug 15, 2017

ianlancetaylor closed this as completed Mar 30, 2018

golang locked and limited conversation to collaborators Mar 30, 2019

gopherbot added the FrozenDueToAge label Mar 30, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/go: 'go test' output incompatible with benchstat #21341

cmd/go: 'go test' output incompatible with benchstat #21341

bep commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

mvdan commented Aug 8, 2017

bep commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

bep commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

ianlancetaylor commented Aug 8, 2017

ianlancetaylor commented Mar 30, 2018

Navigation Menu

cmd/go: 'go test' output incompatible with benchstat #21341

cmd/go: 'go test' output incompatible with benchstat #21341

Comments

bep commented Aug 8, 2017 • edited

ALTree commented Aug 8, 2017 • edited

mvdan commented Aug 8, 2017

bep commented Aug 8, 2017 • edited

ALTree commented Aug 8, 2017 • edited

bep commented Aug 8, 2017 • edited

ALTree commented Aug 8, 2017 • edited

ALTree commented Aug 8, 2017 • edited

ianlancetaylor commented Aug 8, 2017

ianlancetaylor commented Mar 30, 2018

bep commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

bep commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

bep commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited

ALTree commented Aug 8, 2017 •

edited