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.

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

runtime/pprof: TestBlockProfile failures with "Bad chan … entry" or "Bad select … entry" #6999

Closed
gopherbot opened this issue Dec 21, 2013 · 21 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@gopherbot
Copy link

by jphilbin@google.com:

What steps will reproduce the problem?

No go version currently installed.
$ hg clone -u release https://code.google.com/p/go
$ cd go/src
$ ./all.bash

Get the following failure:
===
--- FAIL: TestBlockProfile (0.17 seconds)
        pprof_test.go:332: Bad chan recv entry, expect:

                [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
                #       0x[0-9,a-f]+    runtime\.chanrecv1\+0x[0-9,a-f]+        .*/src/pkg/runtime/chan.c:[0-9]+
                #       0x[0-9,a-f]+    runtime/pprof_test\.blockChanRecv\+0x[0-9,a-f]+ .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
                #       0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+      .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+

                got:
                --- contention:
                cycles/second=1659580313
                27164213 1 @ 0x4052e2 0x439bec 0x439229 0x4325eb 0x417a30
                #       0x4052e2        runtime.selectgo+0x12                           /home/jphilbin/go/src/pkg/runtime/chan.c:840
                #       0x439bec        runtime/pprof_test.blockSelectSendSync+0x12c    /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:386
                #       0x439229        runtime/pprof_test.TestBlockProfile+0x189       /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x4325eb        testing.tRunner+0x8b                            /home/jphilbin/go/src/pkg/testing/testing.go:391

                17075383 1 @ 0x45e596 0x439c64 0x439229 0x4325eb 0x417a30
                #       0x45e596        sync.(*Mutex).Lock+0xd6                         /home/jphilbin/go/src/pkg/sync/mutex.go:66
                #       0x439c64        runtime/pprof_test.blockMutex+0x74              /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:399
                #       0x439229        runtime/pprof_test.TestBlockProfile+0x189       /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x4325eb        testing.tRunner+0x8b                            /home/jphilbin/go/src/pkg/testing/testing.go:391

                17055513 1 @ 0x404c68 0x43998b 0x439229 0x4325eb 0x417a30
                #       0x404c68        runtime.chanrecv1+0x38                          /home/jphilbin/go/src/pkg/runtime/chan.c:446
                #       0x43998b        runtime/pprof_test.blockChanClose+0x9b          /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:363
                #       0x439229        runtime/pprof_test.TestBlockProfile+0x189       /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x4325eb        testing.tRunner+0x8b                            /home/jphilbin/go/src/pkg/testing/testing.go:391

                17000189 1 @ 0x404c1c 0x4398e0 0x439229 0x4325eb 0x417a30
                #       0x404c1c        runtime.chansend1+0x4c                          /home/jphilbin/go/src/pkg/runtime/chan.c:438
                #       0x4398e0        runtime/pprof_test.blockChanSend+0xa0           /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:354
                #       0x439229        runtime/pprof_test.TestBlockProfile+0x189       /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x4325eb        testing.tRunner+0x8b                            /home/jphilbin/go/src/pkg/testing/testing.go:391

                16926852 1 @ 0x4052e2 0x439ab1 0x439229 0x4325eb 0x417a30
                #       0x4052e2        runtime.selectgo+0x12                           /home/jphilbin/go/src/pkg/runtime/chan.c:840
                #       0x439ab1        runtime/pprof_test.blockSelectRecvAsync+0x121   /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:373
                #       0x439229        runtime/pprof_test.TestBlockProfile+0x189       /home/jphilbin/go/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x4325eb        testing.tRunner+0x8b                            /home/jphilbin/go/src/pkg/testing/testing.go:391

FAIL
FAIL    runtime/pprof   8.001s
===

Which operating system are you using?
Ubuntu 12.10 amd64


Which version are you using?  (run 'go version')
go version go1.2 linux/amd64
@gopherbot
Copy link
Author

Comment 1 by jphilbin@google.com:

I realized that the failing test is in runtime/pprof and not in runtime/debug (that was
the previous test that passed ok).
There doesn't seem to be a way to edit issue titles once they're submitted?

@gopherbot
Copy link
Author

Comment 4 by capnm9:

I've seen the same failure on the tip.
changeset:   19174:f28dc1ba53cf
tag:         tip
user:        Rob Pike <r@golang.org>
date:        Wed Feb 19 15:01:50 2014 -0800
summary:     cmd/pack: dump output of command of "go env" command in test
uname -a
Linux 3.8.0-35-generic #50-Ubuntu SMP Tue Dec 3 01:24:59 UTC 2013 x86_64 x86_64 x86_64
GNU/Linux

@rsc
Copy link
Contributor

rsc commented Mar 3, 2014

Comment 5:

Labels changed: added release-go1.3.

Status changed to Accepted.

@rsc
Copy link
Contributor

rsc commented May 11, 2014

Comment 6:

I believe this is happening but clearly not very often. It can wait I guess.

Labels changed: added release-none, suggested, removed release-go1.3.

@gopherbot
Copy link
Author

Comment 7 by jetze.van.beijma:

Also got the same error on Ubuntu 12.04 with go release 1.3.
3.5.0-49-generic #74~precise1-Ubuntu SMP Fri May 2 21:32:31 UTC 2014 x86_64 x86_64
x86_64 GNU/Linux
go version go1.3 linux/amd64

@dvyukov
Copy link
Member

dvyukov commented Jun 20, 2014

Comment 8:

is it exactly the same? or just a failure of the same test?

@gopherbot
Copy link
Author

Comment 9 by capnm9:

I currently see similar failures (ca. 1x/10 times).
3.13.0-35-generic #62-Ubuntu SMP Fri Aug 15 01:58:42 UTC 2014 x86_64 x86_64 x86_64
GNU/Linux
428dd5a62a9d tip
----
--- FAIL: TestBlockProfile (0.18s)
    pprof_test.go:370: Bad select send sync entry, expect:
        
        [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
        #   0x[0-9,a-f]+    runtime\.selectgo\+0x[0-9,a-f]+ .*/src/pkg/runtime/select.go:[0-9]+
        #   0x[0-9,a-f]+    runtime/pprof_test\.blockSelectSendSync\+0x[0-9,a-f]+   .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
        #   0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+  .*/src/pkg/runtime/pprof/pprof_test.go:[0-9]+
        
        got:
        --- contention:
        cycles/second=2505600281
        139908672 1 @ 0x4126e2 0x452c72 0x45230c 0x44b21b 0x42c3d0
        #   0x4126e2    runtime.selectgo+0x12               /tmp2/go/src/pkg/runtime/select.go:183
        #   0x452c72    runtime/pprof_test.blockSelectRecvAsync+0x152   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:411
        #   0x45230c    runtime/pprof_test.TestBlockProfile+0x1ac   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:358
        #   0x44b21b    testing.tRunner+0x8b                /tmp2/go/src/pkg/testing/testing.go:427
        
        25348446 1 @ 0x47f552 0x452e7c 0x45230c 0x44b21b 0x42c3d0
        #   0x47f552    sync.(*Mutex).Lock+0xd2             /tmp2/go/src/pkg/sync/mutex.go:66
        #   0x452e7c    runtime/pprof_test.blockMutex+0x7c      /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:437
        #   0x45230c    runtime/pprof_test.TestBlockProfile+0x1ac   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:358
        #   0x44b21b    testing.tRunner+0x8b                /tmp2/go/src/pkg/testing/testing.go:427
        
        25318732 1 @ 0x47f1cd 0x452fae 0x45230c 0x44b21b 0x42c3d0
        #   0x47f1cd    sync.(*Cond).Wait+0x9d              /tmp2/go/src/pkg/sync/cond.go:63
        #   0x452fae    runtime/pprof_test.blockCond+0x11e      /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:450
        #   0x45230c    runtime/pprof_test.TestBlockProfile+0x1ac   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:358
        #   0x44b21b    testing.tRunner+0x8b                /tmp2/go/src/pkg/testing/testing.go:427
        
        25286875 1 @ 0x402f6b 0x452992 0x45230c 0x44b21b 0x42c3d0
        #   0x402f6b    runtime.chanrecv1+0x2b              /tmp2/go/src/pkg/runtime/chan.go:308
        #   0x452992    runtime/pprof_test.blockChanRecv+0xb2       /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:383
        #   0x45230c    runtime/pprof_test.TestBlockProfile+0x1ac   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:358
        #   0x44b21b    testing.tRunner+0x8b                /tmp2/go/src/pkg/testing/testing.go:427
        
        25279242 1 @ 0x402f6b 0x452b12 0x45230c 0x44b21b 0x42c3d0
        #   0x402f6b    runtime.chanrecv1+0x2b              /tmp2/go/src/pkg/runtime/chan.go:308
        #   0x452b12    runtime/pprof_test.blockChanClose+0xb2      /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:401
        #   0x45230c    runtime/pprof_test.TestBlockProfile+0x1ac   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:358
        #   0x44b21b    testing.tRunner+0x8b                /tmp2/go/src/pkg/testing/testing.go:427
        
        25268569 1 @ 0x402483 0x452a58 0x45230c 0x44b21b 0x42c3d0
        #   0x402483    runtime.chansend1+0x43              /tmp2/go/src/pkg/runtime/chan.go:69
        #   0x452a58    runtime/pprof_test.blockChanSend+0xb8       /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:392
        #   0x45230c    runtime/pprof_test.TestBlockProfile+0x1ac   /tmp2/go/src/pkg/runtime/pprof/pprof_test.go:358
        #   0x44b21b    testing.tRunner+0x8b                /tmp2/go/src/pkg/testing/testing.go:427
        
FAIL
FAIL    runtime/pprof   8.420s

@griesemer
Copy link
Contributor

Comment 10:

Labels changed: added repo-main.

@gopherbot
Copy link
Author

Comment 11 by viriketo:

It happens to me often 3/4 times at least. x86_64-linux 3.14.17 SMP, dualcore AMD Athlon
4800+.

@gopherbot
Copy link
Author

Comment 12 by viriketo:

^ I've seen it with go 1.3.2 and 1.3.3.

@gopherbot gopherbot added accepted Suggested Issues that may be good for new contributors looking for work to do. labels Oct 10, 2014
@rsc rsc added this to the Unplanned milestone Apr 10, 2015
@mikioh
Copy link
Contributor

mikioh commented May 13, 2016

TestBlockProfile still fails w/ Bad mutex entry on tip (go1.7 devel). See https://storage.googleapis.com/go-build-log/88cc348c/freebsd-386-gce101_92f2a1f0.log

--- FAIL: TestBlockProfile (0.34s)
    pprof_test.go:498: Bad mutex entry, expect:

        [0-9]+ [0-9]+ @ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+ 0x[0-9,a-f]+
        #   0x[0-9,a-f]+    sync\.\(\*Mutex\)\.Lock\+0x[0-9,a-f]+   .*/src/sync/mutex\.go:[0-9]+
        #   0x[0-9,a-f]+    runtime/pprof_test\.blockMutex\+0x[0-9,a-f]+    .*/src/runtime/pprof/pprof_test.go:[0-9]+
        #   0x[0-9,a-f]+    runtime/pprof_test\.TestBlockProfile\+0x[0-9,a-f]+  .*/src/runtime/pprof/pprof_test.go:[0-9]+

        got:
        --- contention:
        cycles/second=2500072104
        309534400 1 @ 0x807e36f 0x80ba15d 0x80b98aa 0x80adad6 0x809ae61
        #   0x807e36e   runtime.selectgo+0xe                /tmp/workdir/go/src/runtime/select.go:238
        #   0x80ba15c   runtime/pprof_test.blockSelectSendSync+0x11c    /tmp/workdir/go/src/runtime/pprof/pprof_test.go:557
        #   0x80b98a9   runtime/pprof_test.TestBlockProfile+0x179   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:486
        #   0x80adad5   testing.tRunner+0x85                /tmp/workdir/go/src/testing/testing.go:547
        #   0x0

        81366149 3 @ 0x807e36f 0x80ba02c 0x80b98aa 0x80adad6 0x809ae61
        #   0x807e36e   runtime.selectgo+0xe                /tmp/workdir/go/src/runtime/select.go:238
        #   0x80ba02b   runtime/pprof_test.blockSelectRecvAsync+0x11b   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:543
        #   0x80b98a9   runtime/pprof_test.TestBlockProfile+0x179   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:486
        #   0x80adad5   testing.tRunner+0x85                /tmp/workdir/go/src/testing/testing.go:547
        #   0x0

        27756951 1 @ 0x804bc64 0x80b9ef8 0x80b98aa 0x80adad6 0x809ae61
        #   0x804bc63   runtime.chanrecv1+0x23              /tmp/workdir/go/src/runtime/chan.go:378
        #   0x80b9ef7   runtime/pprof_test.blockChanClose+0x67      /tmp/workdir/go/src/runtime/pprof/pprof_test.go:529
        #   0x80b98a9   runtime/pprof_test.TestBlockProfile+0x179   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:486
        #   0x80adad5   testing.tRunner+0x85                /tmp/workdir/go/src/testing/testing.go:547
        #   0x0

        27539367 1 @ 0x804bc64 0x80b9df8 0x80b98aa 0x80adad6 0x809ae61
        #   0x804bc63   runtime.chanrecv1+0x23              /tmp/workdir/go/src/runtime/chan.go:378
        #   0x80b9df7   runtime/pprof_test.blockChanRecv+0x67       /tmp/workdir/go/src/runtime/pprof/pprof_test.go:511
        #   0x80b98a9   runtime/pprof_test.TestBlockProfile+0x179   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:486
        #   0x80adad5   testing.tRunner+0x85                /tmp/workdir/go/src/testing/testing.go:547
        #   0x0

        27133934 1 @ 0x804b268 0x80b9e7d 0x80b98aa 0x80adad6 0x809ae61
        #   0x804b267   runtime.chansend1+0x37              /tmp/workdir/go/src/runtime/chan.go:107
        #   0x80b9e7c   runtime/pprof_test.blockChanSend+0x6c       /tmp/workdir/go/src/runtime/pprof/pprof_test.go:520
        #   0x80b98a9   runtime/pprof_test.TestBlockProfile+0x179   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:486
        #   0x80adad5   testing.tRunner+0x85                /tmp/workdir/go/src/testing/testing.go:547
        #   0x0

        26345191 1 @ 0x80cb287 0x80ba290 0x80b98aa 0x80adad6 0x809ae61
        #   0x80cb286   sync.(*Cond).Wait+0x86              /tmp/workdir/go/src/sync/cond.go:57
        #   0x80ba28f   runtime/pprof_test.blockCond+0xbf       /tmp/workdir/go/src/runtime/pprof/pprof_test.go:583
        #   0x80b98a9   runtime/pprof_test.TestBlockProfile+0x179   /tmp/workdir/go/src/runtime/pprof/pprof_test.go:486
        #   0x80adad5   testing.tRunner+0x85                /tmp/workdir/go/src/testing/testing.go:547
        #   0x0

FAIL

@mikioh mikioh changed the title runtime/pprof: test failure during ./all.bash runtime/pprof: flaky TestBlockProfile May 13, 2016
@rsc
Copy link
Contributor

rsc commented Jun 28, 2019

I can't find any instances of this bug on any of our builders going back 6 months. Closing as fixed.

@x448
Copy link

x448 commented Jan 16, 2020

Ran clean.bash and all.bash in kvm with 2 cpu and 4 gb ram to build go1.13.6 using go1.12.12.

--- FAIL: TestBlockProfile (0.19s)
    --- FAIL: TestBlockProfile/debug=1 (0.10s)
        pprof_test.go:625: Bad chan recv entry, expect:
            
            [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
            #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.blockChanRecv\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            
            got:
            --- contention:
            cycles/second=3491926309
            35317032 1 @ 0x469ddd 0x597afb 0x596f35 0x4f2039 0x45d971
            #	0x469ddc	sync.(*Cond).Wait+0x9c			/home/x448/go1.13/src/sync/cond.go:56
            #	0x597afa	runtime/pprof.blockCond+0xba		/home/x448/go1.13/src/runtime/pprof/pprof_test.go:767
            #	0x596f34	runtime/pprof.TestBlockProfile+0x454	/home/x448/go1.13/src/runtime/pprof/pprof_test.go:607
            #	0x4f2038	testing.tRunner+0xc8			/home/x448/go1.13/src/testing/testing.go:909
            
        pprof_test.go:625: Bad chan send entry, expect:
            
            [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
            #	0x[0-9a-f]+	runtime\.chansend1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.blockChanSend\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            
            got:
            --- contention:
            cycles/second=3491926309
            35317032 1 @ 0x469ddd 0x597afb 0x596f35 0x4f2039 0x45d971
            #	0x469ddc	sync.(*Cond).Wait+0x9c			/home/x448/go1.13/src/sync/cond.go:56
            #	0x597afa	runtime/pprof.blockCond+0xba		/home/x448/go1.13/src/runtime/pprof/pprof_test.go:767
            #	0x596f34	runtime/pprof.TestBlockProfile+0x454	/home/x448/go1.13/src/runtime/pprof/pprof_test.go:607
            #	0x4f2038	testing.tRunner+0xc8			/home/x448/go1.13/src/testing/testing.go:909
            
        pprof_test.go:625: Bad chan close entry, expect:
            
            [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
            #	0x[0-9a-f]+	runtime\.chanrecv1\+0x[0-9a-f]+	.*/src/runtime/chan.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.blockChanClose\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            
            got:
            --- contention:
            cycles/second=3491926309
            35317032 1 @ 0x469ddd 0x597afb 0x596f35 0x4f2039 0x45d971
            #	0x469ddc	sync.(*Cond).Wait+0x9c			/home/x448/go1.13/src/sync/cond.go:56
            #	0x597afa	runtime/pprof.blockCond+0xba		/home/x448/go1.13/src/runtime/pprof/pprof_test.go:767
            #	0x596f34	runtime/pprof.TestBlockProfile+0x454	/home/x448/go1.13/src/runtime/pprof/pprof_test.go:607
            #	0x4f2038	testing.tRunner+0xc8			/home/x448/go1.13/src/testing/testing.go:909
            
        pprof_test.go:625: Bad select recv async entry, expect:
            
            [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
            #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*/src/runtime/select.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.blockSelectRecvAsync\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            
            got:
            --- contention:
            cycles/second=3491926309
            35317032 1 @ 0x469ddd 0x597afb 0x596f35 0x4f2039 0x45d971
            #	0x469ddc	sync.(*Cond).Wait+0x9c			/home/x448/go1.13/src/sync/cond.go:56
            #	0x597afa	runtime/pprof.blockCond+0xba		/home/x448/go1.13/src/runtime/pprof/pprof_test.go:767
            #	0x596f34	runtime/pprof.TestBlockProfile+0x454	/home/x448/go1.13/src/runtime/pprof/pprof_test.go:607
            #	0x4f2038	testing.tRunner+0xc8			/home/x448/go1.13/src/testing/testing.go:909
            
        pprof_test.go:625: Bad select send sync entry, expect:
            
            [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
            #	0x[0-9a-f]+	runtime\.selectgo\+0x[0-9a-f]+	.*/src/runtime/select.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.blockSelectSendSync\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            
            got:
            --- contention:
            cycles/second=3491926309
            35317032 1 @ 0x469ddd 0x597afb 0x596f35 0x4f2039 0x45d971
            #	0x469ddc	sync.(*Cond).Wait+0x9c			/home/x448/go1.13/src/sync/cond.go:56
            #	0x597afa	runtime/pprof.blockCond+0xba		/home/x448/go1.13/src/runtime/pprof/pprof_test.go:767
            #	0x596f34	runtime/pprof.TestBlockProfile+0x454	/home/x448/go1.13/src/runtime/pprof/pprof_test.go:607
            #	0x4f2038	testing.tRunner+0xc8			/home/x448/go1.13/src/testing/testing.go:909
            
        pprof_test.go:625: Bad mutex entry, expect:
            
            [0-9]+ [0-9]+ @( 0x[[:xdigit:]]+)+
            #	0x[0-9a-f]+	sync\.\(\*Mutex\)\.Lock\+0x[0-9a-f]+	.*/src/sync/mutex\.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.blockMutex\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            #	0x[0-9a-f]+	runtime/pprof\.TestBlockProfile\+0x[0-9a-f]+	.*/src/runtime/pprof/pprof_test.go:[0-9]+
            
            got:
            --- contention:
            cycles/second=3491926309
            35317032 1 @ 0x469ddd 0x597afb 0x596f35 0x4f2039 0x45d971
            #	0x469ddc	sync.(*Cond).Wait+0x9c			/home/x448/go1.13/src/sync/cond.go:56
            #	0x597afa	runtime/pprof.blockCond+0xba		/home/x448/go1.13/src/runtime/pprof/pprof_test.go:767
            #	0x596f34	runtime/pprof.TestBlockProfile+0x454	/home/x448/go1.13/src/runtime/pprof/pprof_test.go:607
            #	0x4f2038	testing.tRunner+0xc8			/home/x448/go1.13/src/testing/testing.go:909
            
    --- FAIL: TestBlockProfile/proto (0.00s)
        pprof_test.go:638: parsed proto: PeriodType: contentions count
            Period: 1
            Time: 2020-01-15 23:11:58.218134259 -0600 CST
            Samples:
            contentions/count delay/nanoseconds
                      1   10113911: 1 2 3 4 
            Locations
                 1: 0x469ddc M=1 sync.(*Cond).Wait /home/x448/go1.13/src/sync/cond.go:56 s=0
                 2: 0x597afa M=1 runtime/pprof.blockCond /home/x448/go1.13/src/runtime/pprof/pprof_test.go:767 s=0
                 3: 0x596f34 M=1 runtime/pprof.TestBlockProfile /home/x448/go1.13/src/runtime/pprof/pprof_test.go:607 s=0
                 4: 0x4f2038 M=1 testing.tRunner /home/x448/go1.13/src/testing/testing.go:909 s=0
            Mappings
            1: 0x400000/0x5a5000/0x0 /tmp/go-build492500388/b942/pprof.test  [FN]
            2: 0x7ffd69925000/0x7ffd69927000/0x0 [vdso]  
            3: 0xffffffffff600000/0xffffffffff601000/0x0 [vsyscall]  
        pprof_test.go:646: No matching stack entry for chan recv, want [runtime.chanrecv1 runtime/pprof.blockChanRecv runtime/pprof.TestBlockProfile]
        pprof_test.go:646: No matching stack entry for chan send, want [runtime.chansend1 runtime/pprof.blockChanSend runtime/pprof.TestBlockProfile]
        pprof_test.go:646: No matching stack entry for chan close, want [runtime.chanrecv1 runtime/pprof.blockChanClose runtime/pprof.TestBlockProfile]
        pprof_test.go:646: No matching stack entry for select recv async, want [runtime.selectgo runtime/pprof.blockSelectRecvAsync runtime/pprof.TestBlockProfile]
        pprof_test.go:646: No matching stack entry for select send sync, want [runtime.selectgo runtime/pprof.blockSelectSendSync runtime/pprof.TestBlockProfile]
        pprof_test.go:646: No matching stack entry for mutex, want [sync.(*Mutex).Lock runtime/pprof.blockMutex runtime/pprof.TestBlockProfile]
FAIL
FAIL	runtime/pprof	4.709s

go version and go env after the build finished with above error:

x448@coding:~/go1.13/src> go version
go version go1.13.6 linux/amd64
x448@coding:~/go1.13/src> go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/x448/.cache/go-build"
GOENV="/home/x448/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/x448/gocode1.13"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/x448/go1.13"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/x448/go1.13/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/x448/go1.13/src/go.mod"
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-build089455649=/tmp/go-build -gno-record-gcc-switches"

@bcmills
Copy link
Contributor

bcmills commented Mar 13, 2020

@mikioh The original report was for a Bad chan recv entry. Current failures on the builders seem to be for Bad mutex entry, which is probably a separate root cause. Let's track that in a separate issue.

@bcmills bcmills closed this as completed Mar 13, 2020
@bcmills
Copy link
Contributor

bcmills commented Mar 13, 2020

Filed Bad mutex entry as #37844.

@bcmills bcmills reopened this Mar 13, 2020
@bcmills
Copy link
Contributor

bcmills commented Mar 13, 2020

@x448, I haven't been able to find any Bad chan failures on the builders, but I did find some Bad select ones I've been able to find are on the darwin-arm64-mn4m2zdaios builder.

2020-02-27T19:04:17-42f8199/darwin-arm64-mn4m2zdaios
2020-02-05T19:19:56-8a4d05c/darwin-arm64-mn4m2zdaios
2019-11-20T15:16:17-9c6f640/darwin-arm64-mn4m2zdaios
2019-11-19T06:10:03-8cf5293/darwin-arm64-mn4m2zdaios

@bcmills bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. and removed Suggested Issues that may be good for new contributors looking for work to do. labels Mar 13, 2020
@bcmills bcmills modified the milestones: Unplanned, Backlog Mar 13, 2020
@bcmills bcmills changed the title runtime/pprof: flaky TestBlockProfile runtime/pprof: TestBlockProfile failures with "Bad chan … entry" or "Bad select … entry" Mar 13, 2020
@bcmills
Copy link
Contributor

bcmills commented Nov 5, 2020

@bcmills
Copy link
Contributor

bcmills commented Jan 21, 2021

@bcmills
Copy link
Contributor

bcmills commented Nov 5, 2021

@bcmills
Copy link
Contributor

bcmills commented Feb 9, 2022

greplogs --dashboard -md -l -e '(?ms)FAIL: TestBlockProfile.*Bad (chan|select)[a-zA-Z ]* entry' --since=2021-11-06

2022-02-08T23:39:48-6749dd4/openbsd-arm64-jsing
2021-12-09T13:36:38-474ebb9/netbsd-amd64-9_0
2021-11-15T21:22:14-42fa03a/freebsd-arm64-dmgk

@gopherbot
Copy link
Author

Change https://go.dev/cl/384534 mentions this issue: runtime/pprof: skip TestBlockProfile

@bcmills bcmills self-assigned this Feb 10, 2022
@bcmills bcmills modified the milestones: Backlog, Go1.18 Feb 10, 2022
@rsc rsc unassigned bcmills Jun 22, 2022
@golang golang locked and limited conversation to collaborators Jun 23, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

7 participants