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.

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

x/build: race builder mixes benchmark and test failure output #9717

Open
bradfitz opened this Issue Jan 28, 2015 · 9 comments

Comments

Projects
None yet
4 participants
@bradfitz
Member

bradfitz commented Jan 28, 2015

The output of race.bash is a mess. e.g.:

http://build.golang.org/log/0a062dae109415840b118fbc4189c83e7b5c068a

It's hard to see anything.

We plan to rewrite run.bash into Go. It's probably time that race.bash is also rewritten in Go, so it can capture the output of child processes and not interleave them all.

Dmitry, can you fix?

@dvyukov

This comment has been minimized.

Member

dvyukov commented Jan 29, 2015

What exactly is a mess?
I do not see any interleaved output from different processes.
The bulk of the log is just output of 'go test -bench.* std'. So maybe there is something to fix in go test...

@minux

This comment has been minimized.

Member

minux commented Jan 29, 2015

I think Brad just complains about the fact that if the race build breaks,
it's relatively hard to figure out what's happening by looking at the log.
(the real message is buried inside a lot of unrelated benchmark results.)

@dvyukov

This comment has been minimized.

Member

dvyukov commented Jan 29, 2015

Hey, it is a punishment for anybody who introduces a data race.

Speaking seriously, ^F "data race" always worked for me.

@minux

This comment has been minimized.

Member

minux commented Jan 29, 2015

Right. It's easy if you know what you're looking for.

But looking at the output of other builders doesn't require
searching, just scrolling down from the top, and it's quite
easy to spot the problem.

@bradfitz

This comment has been minimized.

Member

bradfitz commented Feb 12, 2015

Here's an example of garble:

https://storage.googleapis.com/go-build-log/df6b9696/linux-amd64-race_b0f4624a.log

ok      net 9.493s
PASS
BenchmarkHeaderWriteSubset-4                   10000         10202 ns/op         192 B/op          2 allocs/op
BenchmarkReadRequestChrome-4                    3000         37263 ns/op      16.40 MB/s        1664 B/op         16 allocs/op
BenchmarkReadRequestCurl-4                     10000         17212 ns/op       4.53 MB/s         896 B/op         11 allocs/op
BenchmarkReadRequestApachebench-4              10000         16772 ns/op       4.89 MB/s         896 B/op         11 allocs/op
BenchmarkReadRequestSiege-4                     5000         24549 ns/op       6.15 MB/s        1008 B/op         13 allocs/op
BenchmarkReadRequestWrk-4                      10000         11401 ns/op       3.51 MB/s         848 B/op          9 allocs/op
BenchmarkClientServer-4                          500        358113 ns/op       16030 B/op         81 allocs/op
BenchmarkClientServerParallel4-4                1000        155262 ns/op       16318 B/op         81 allocs/op
BenchmarkClientServerParallel64-4                300        635056 ns/op       26025 B/op        116 allocs/op
BenchmarkClientServerParallelTLS4-4                1     108462942 ns/op      202848 B/op       2940 allocs/op
BenchmarkClientServerParallelTLS64-4               1     118529698 ns/op      328888 B/op       4027 allocs/op
BenchmarkServer-4                                300        456277 ns/op        4213 B/op         24 allocs/op
BenchmarkClient-4                           --- FAIL: BenchmarkClient-4
    serve_test.go:2960: subprocess does not respond
BenchmarkServerFakeConnNoKeepAlive-4             500        330695 ns/op       13096 B/op         34 allocs/op
BenchmarkServerFakeConnWithKeepAlive-4          2000         65067 ns/op        4421 B/op         25 allocs/op
BenchmarkServerFakeConnWithKeepAliveLite-4      3000         44822 ns/op        3203 B/op         14 allocs/op
BenchmarkServerHandlerTypeLen-4                 2000         54727 ns/op        4116 B/op         23 allocs/op
BenchmarkServerHandlerNoLen-4                   3000         51966 ns/op        4035 B/op         20 allocs/op
BenchmarkServerHandlerNoType-4                  2000         54172 ns/op        4052 B/op         21 allocs/op
BenchmarkServerHandlerNoHeader-4                3000         47455 ns/op        3203 B/op         14 allocs/op
BenchmarkServerHijack-4                          500        242131 ns/op       11892 B/op         23 allocs/op
Too many goroutines running after net/http test(s).
1 instances of:
net/http_test.func·157()
    /tmp/buildlet-scatch184350621/go/src/net/http/serve_test.go:2949 +0x9d
created by net/http_test.BenchmarkClient
    /tmp/buildlet-scatch184350621/go/src/net/http/serve_test.go:2950 +0x8bb
exit status 1
FAIL    net/http    8.601s
PASS
ok      net/http/cgi    0.011s
PASS
ok      net/http/cookiejar  0.010s
PASS
ok      net/http/fcgi   0.011s
PASS
ok      net/http/httptest   0.011s
PASS
ok      net/http/httputil   0.010s
PASS
ok      net/http/internal   0.008s
?       net/http/pprof  [no test files]
PASS
ok      net/mail    0.007s
PASS
BenchmarkEndToEnd-4             2015/02/12 22:15:25 Test RPC server listening on 127.0.0.1:53559
2015/02/12 22:15:25 Test HTTP RPC server listening on 127.0.0.1:36029
     500        227635 ns/op
BenchmarkEndToEndHTTP-4              500        226008 ns/op
BenchmarkEndToEndAsync-4             500        218588 ns/op
BenchmarkEndToEndAsyncHTTP-4         500        228622 ns/op
ok      net/rpc 0.565s
PASS
ok      net/rpc/jsonrpc 0.015s
PASS
ok      net/smtp    0.011s
PASS
BenchmarkReadMIMEHeader-4       3000         36915 ns/op        1342 B/op         14 allocs/op
BenchmarkUncommon-4            20000          7419 ns/op         464 B/op          5 allocs/op
ok      net/textproto   0.358s
PASS
BenchmarkString-4       3000         50870 ns/op        2336 B/op         42 allocs/op
ok      net/url 0.177s
PASS
ok      os  0.009s

What is happening there?

@dvyukov

This comment has been minimized.

Member

dvyukov commented Feb 13, 2015

^F "fail" is my second secret

@dvyukov dvyukov changed the title from build: the race output is a mess to cmd/gc: test output is a mess Feb 13, 2015

@rsc

This comment has been minimized.

Contributor

rsc commented Apr 10, 2015

I don't see what this has to do with cmd/gc.

@rsc rsc changed the title from cmd/gc: test output is a mess to build: race.bash output is a mess Apr 10, 2015

@rsc rsc added this to the Unplanned milestone Apr 10, 2015

@dvyukov dvyukov changed the title from build: race.bash output is a mess to cmd/go: test output is a mess Apr 10, 2015

@dvyukov

This comment has been minimized.

Member

dvyukov commented Apr 10, 2015

Sorry, the title meant to be cmd/go (or maybe testing:)
This is not race-related, as if you run the same command w/o -race output will be the same.
I don't think we need to fix anything here. Search on the page works well. And this is the only context where this came up.

@bradfitz

This comment has been minimized.

Member

bradfitz commented Apr 10, 2015

I'll fix this for free when the builders do test sharding probably.

@rsc rsc changed the title from cmd/go: test output is a mess to x/build: race builder mixes benchmark and test failure output Apr 14, 2015

@rsc rsc removed the builder label Apr 14, 2015

@rsc rsc modified the milestones: Unreleased, Unplanned Apr 14, 2015

@rsc rsc added the Builders label Jun 11, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment