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

gopherbot · 2013-12-21T20:59:54Z

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 · 2013-12-21T21:04:23Z

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 · 2014-02-19T23:52:44Z

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 · 2014-03-03T23:52:15Z

Comment 5:

Labels changed: added release-go1.3.

Status changed to Accepted.

rsc · 2014-05-11T14:46:27Z

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 · 2014-06-20T15:37:48Z

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 · 2014-06-20T16:51:25Z

Comment 8:

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

gopherbot · 2014-09-07T14:22:09Z

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 · 2014-10-01T21:02:08Z

Comment 10:

Labels changed: added repo-main.

gopherbot · 2014-10-10T14:40:34Z

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 · 2014-10-10T14:41:00Z

Comment 12 by viriketo:

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

mikioh · 2016-05-13T08:53:04Z

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

rsc · 2019-06-28T04:53:36Z

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

x448 · 2020-01-16T05:53:55Z

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 · 2020-03-13T15:20:45Z

@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 · 2020-03-13T15:24:00Z

Filed Bad mutex entry as #37844.

bcmills · 2020-03-13T15:36:14Z

@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 · 2020-11-05T15:43:20Z

Bad chan recv entry, in a TryBot:
https://storage.googleapis.com/go-build-log/66b9dbde/android-amd64-emu_3f5b06b6.log

bcmills · 2021-01-21T15:54:23Z

Bad chan close entry, in a TryBot:
https://storage.googleapis.com/go-build-log/0b96ad42/android-amd64-emu_975eb008.log

gopherbot added accepted Suggested labels Oct 10, 2014

rsc added this to the Unplanned milestone Apr 10, 2015

rsc removed release-none labels Apr 10, 2015

mikioh changed the title ~~runtime/pprof: test failure during ./all.bash~~ runtime/pprof: flaky TestBlockProfile May 13, 2016

bcmills closed this Mar 13, 2020

bcmills reopened this Mar 13, 2020

bcmills added NeedsInvestigation and removed Suggested labels Mar 13, 2020

bcmills modified the milestones: Unplanned, Backlog Mar 13, 2020

bcmills changed the title ~~runtime/pprof: flaky TestBlockProfile~~ runtime/pprof: TestBlockProfile failures with "Bad chan … entry" or "Bad select … entry" Mar 13, 2020

bcmills mentioned this issue Mar 13, 2020

runtime/pprof: TestBlockProfile failures with "Bad mutex entry" #37844

Open

golang / go

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

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

gopherbot commented Dec 21, 2013

gopherbot commented Dec 21, 2013

gopherbot commented Feb 19, 2014

rsc commented Mar 3, 2014

rsc commented May 11, 2014

gopherbot commented Jun 20, 2014

dvyukov commented Jun 20, 2014

gopherbot commented Sep 7, 2014

griesemer commented Oct 1, 2014

gopherbot commented Oct 10, 2014

gopherbot commented Oct 10, 2014

mikioh commented May 13, 2016

rsc commented Jun 28, 2019

x448 commented Jan 16, 2020

bcmills commented Mar 13, 2020 •

edited

bcmills commented Mar 13, 2020

bcmills commented Mar 13, 2020

bcmills commented Nov 5, 2020

bcmills commented Jan 21, 2021

golang / go

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

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

Comments

gopherbot commented Dec 21, 2013

gopherbot commented Dec 21, 2013

gopherbot commented Feb 19, 2014

rsc commented Mar 3, 2014

rsc commented May 11, 2014

gopherbot commented Jun 20, 2014

dvyukov commented Jun 20, 2014

gopherbot commented Sep 7, 2014

griesemer commented Oct 1, 2014

gopherbot commented Oct 10, 2014

gopherbot commented Oct 10, 2014

mikioh commented May 13, 2016

rsc commented Jun 28, 2019

x448 commented Jan 16, 2020

bcmills commented Mar 13, 2020 • edited

bcmills commented Mar 13, 2020

bcmills commented Mar 13, 2020

bcmills commented Nov 5, 2020

bcmills commented Jan 21, 2021

bcmills commented Mar 13, 2020 •

edited