runtime/pprof: blockprofile test fails in VMs

[gopherbot]

by guillaume@charmes.net:

I am on ubuntu 13.10 (vagrant), 3.11.0-15, amd64/linux
The test suite fail from a fresh clone of the release (1.2.1)
I reproduce with 1.2 as well, didn't try ealier version.

```
$> hg clone https://code.google.com/p/go ~/goroot
$> hg checkout release
$> export GOROOT=~/goroot
$> cd ~/goroot/src && ./all.bash
--- 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=2284813705
                285181184 1 @ 0x404c68 0x439a0b 0x4392a9 0x43266b 0x417a40
                #       0x404c68        runtime.chanrecv1+0x38                          /home/vagrant/goroot/src/pkg/runtime/chan.c:446
                #       0x439a0b        runtime/pprof_test.blockChanClose+0x9b          /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:363
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391

                25687733 1 @ 0x404c1c 0x439960 0x4392a9 0x43266b 0x417a40
                #       0x404c1c        runtime.chansend1+0x4c                          /home/vagrant/goroot/src/pkg/runtime/chan.c:438
                #       0x439960        runtime/pprof_test.blockChanSend+0xa0           /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:354
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391

                25192867 1 @ 0x45e616 0x439ce4 0x4392a9 0x43266b 0x417a40
                #       0x45e616        sync.(*Mutex).Lock+0xd6                         /home/vagrant/goroot/src/pkg/sync/mutex.go:66
                #       0x439ce4        runtime/pprof_test.blockMutex+0x74              /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:399
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391

                23778388 1 @ 0x4052e2 0x439c6c 0x4392a9 0x43266b 0x417a40
                #       0x4052e2        runtime.selectgo+0x12                           /home/vagrant/goroot/src/pkg/runtime/chan.c:840
                #       0x439c6c        runtime/pprof_test.blockSelectSendSync+0x12c    /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:386
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391

FAIL
FAIL    runtime/pprof   7.425s

$> go version
go version go1.2.1 linux/amd64
```

[davecheney]

Comment 1:

Could you please make two changes and try again
1. do not set GOROOT
2. the second command, hg checkout release doesn't do anything because you are not
inside the checkout, I suggest `hg clone -r release https://code.google.com/go ~/goroot`

Status changed to WaitingForReply.

[gopherbot]

Comment 2 by guillaume@charmes.net:

Typo, I did `hg update release`.  Trying without GOROOT..

[gopherbot]

Comment 3 by guillaume@charmes.net:

It is less consistent without $GOROOT set, but still happen 2 out of 3 times. But at
least now I can pass the whole suite.

[gopherbot]

Comment 4 by guillaume@charmes.net:

(And I did the `hg update release` in the correct directory, cf last command: go version.

[davecheney]

Comment 5:

Can you please confirm that you are building the release
$ go version
$ hg parents
What are the specs of the vm you are building inside ?

[gopherbot]

Comment 6 by guillaume@charmes.net:

ok      regexp  0.138s
ok      regexp/syntax   0.667s
ok      runtime 17.080s
?       runtime/cgo     [no test files]
ok      runtime/debug   0.017s
--- FAIL: TestBlockProfile (0.16 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=5085427545
                47378507 1 @ 0x404c68 0x439a0b 0x4392a9 0x43266b 0x417a40
                #       0x404c68        runtime.chanrecv1+0x38                          /home/vagrant/goroot/src/pkg/runtime/chan.c:446
                #       0x439a0b        runtime/pprof_test.blockChanClose+0x9b          /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:363
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391
                23664449 1 @ 0x4052e2 0x439c6c 0x4392a9 0x43266b 0x417a40
                #       0x4052e2        runtime.selectgo+0x12                           /home/vagrant/goroot/src/pkg/runtime/chan.c:840
                #       0x439c6c        runtime/pprof_test.blockSelectSendSync+0x12c    /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:386
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391
                23451704 1 @ 0x404c1c 0x439960 0x4392a9 0x43266b 0x417a40
                #       0x404c1c        runtime.chansend1+0x4c                          /home/vagrant/goroot/src/pkg/runtime/chan.c:438
                #       0x439960        runtime/pprof_test.blockChanSend+0xa0           /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:354
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391
                23392439 1 @ 0x45e616 0x439ce4 0x4392a9 0x43266b 0x417a40
                #       0x45e616        sync.(*Mutex).Lock+0xd6                         /home/vagrant/goroot/src/pkg/sync/mutex.go:66
                #       0x439ce4        runtime/pprof_test.blockMutex+0x74              /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:399
                #       0x4392a9        runtime/pprof_test.TestBlockProfile+0x189       /home/vagrant/goroot/src/pkg/runtime/pprof/pprof_test.go:320
                #       0x43266b        testing.tRunner+0x8b                            /home/vagrant/goroot/src/pkg/testing/testing.go:391
FAIL
FAIL    runtime/pprof   7.680s
?       runtime/race    [no test files]
ok      sort    0.094s
ok      strconv 0.558s
ok      strings 0.229s
ok      sync    0.030s
ok      sync/atomic     0.033s
ok      syscall 0.052s
ok      testing 0.041s
?       testing/iotest  [no test files]
ok      testing/quick   0.087s
ok      text/scanner    0.045s
ok      text/tabwriter  0.036s
ok      text/template   0.093s
ok      text/template/parse     0.018s
ok      time    2.496s
ok      unicode 0.011s
ok      unicode/utf16   0.029s
ok      unicode/utf8    0.011s
?       unsafe  [no test files]
┌─<vagrant @ vagrant-ubuntu-raring-64 in ~/g/src>
└─<>──» go version                                                       
                                                                                        
                                                                                        
     1 < 10:15:25 PM
go version go1.2.1 linux/amd64
┌─<vagrant @ vagrant-ubuntu-raring-64 in ~/g/src>
└─<>──» hg parent                                                        
                                                                                        
                                                                                        
     0 < 10:22:43 PM
changeset:   18498:0ddbdc3c7ce2
branch:      release-branch.go1.2
tag:         go1.2.1
tag:         release
parent:      18496:66253be6d673
user:        Andrew Gerrand <adg@golang.org>
date:        Mon Mar 03 11:53:08 2014 +1100
summary:     go1.2.1
┌─<vagrant @ vagrant-ubuntu-raring-64 in ~/g/src>
└─<>──» pwd                                                              
                                                                                        
                                                                                        
     0 < 10:22:45 PM
/home/vagrant/goroot/src

[davecheney]

Comment 7:

Thank you for confirming that you are running Go version 1.2.1, 
What are the specs of the vm you are building inside of ?

[gopherbot]

Comment 8 by guillaume@charmes.net:

VirtualBox, 4core, 4Gb ram, 2 network interfaces. Host: macbook pro i7 2.4GHx 8Gb ram

[rsc]

Comment 9:

We've seen this in a few other contexts too. Not blocking 1.3 because it's only a test
but should be fixed for 1.4.

Labels changed: added release-go1.4.

Status changed to Accepted.

[rsc]

Comment 10:

Is this still happening at tip? The traceback makes no sense: it shows chanrecv1 called
from blockChanClose, not blockChanRecv.

Status changed to WaitingForReply.

[griesemer]

Comment 11:

Labels changed: added repo-main.

[rsc]

Comment 12:

Status changed to TimedOut.