math/rand: test times out on arm when using soft float emulation

[davecheney]

Reported by tjyang2001

What steps will reproduce the problem?

0. Obtain a Raspberry Pi
1. export GOARM=5
2. cd go/src;./all.bash

What is the expected output?

test completed

What do you see instead?

ok      log/syslog      0.353s
ok      math    0.991s
ok      math/big        5.878s
ok      math/cmplx      0.253s
panic: test timed out

goroutine 7 [running]:
testing.alarm()
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:436 +0x5c
created by time.goFunc
        /usbpub/home/gobuild/go/src/pkg/time/sleep.go:94 +0x5c

goroutine 1 [chan receive]:
testing.RunTests(0x10c00, 0x17a850, 0x6, 0x6, 0x31001, ...)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:350 +0x784
testing.Main(0x10c00, 0x17a850, 0x6, 0x6, 0x17a790, ...)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:285 +0x70
main.main()
        /tmp/go-build294647749/math/rand/_test/_testmain.go:63 +0x88

goroutine 2 [syscall]:
created by runtime.main
        /usbpub/home/gobuild/go/src/pkg/runtime/proc.c:221

goroutine 3 [timer goroutine (idle)]:
created by addtimer
        /usbpub/home/gobuild/go/src/pkg/runtime/ztime_linux_arm.c:72

goroutine 8 [runnable]:
testing.tRunner(0x10632f40, 0x17a874, 0x0)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:256
created by testing.RunTests
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:349 +0x764
FAIL    math/rand       130.702s
ok      mime    0.130s
ok      mime/multipart  1.993s

Which compiler are you using (5g, 6g, 8g, gccgo)?

gobuild@raspberrypi:~/go/bin$ gcc -v
Using built-in specs.
Target: arm-linux-gnueabi
Configured with: ../src/configure -v --with-pkgversion='Debian 4.4.5-8'
--with-bugurl=file:///usr/share/doc/gcc-4.4/README.Bugs
--enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr --program-suffix=-4.4
--enable-shared --enable-multiarch --enable-linker-build-id --with-system-zlib
--libexecdir=/usr/lib --without-included-gettext --enable-threads=posix
--with-gxx-include-dir=/usr/include/c++/4.4 --libdir=/usr/lib --enable-nls
--enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc --disable-sjlj-exceptions
--enable-checking=release --build=arm-linux-gnueabi --host=arm-linux-gnueabi
--target=arm-linux-gnueabi
Thread model: posix
gcc version 4.4.5 (Debian 4.4.5-8)
gobuild@raspberrypi:~/go/bin$

Which operating system are you using?
gobuild@raspberrypi:~/go/bin$ uname -a
Linux raspberrypi 3.1.9+ #90 Wed Apr 18 18:23:05 BST 2012 armv6l GNU/Linux
gobuild@raspberrypi:~/go/bin$


Which version are you using?  (run 'go version')
gobuild@raspberrypi:~/go/bin$ ./go version
go version weekly.2012-03-27 +7021c8a8a25a
gobuild@raspberrypi:~/go/bin$

Please provide any additional information below.

gobuild@raspberrypi:~/go/bin$ hg id
7021c8a8a25a tip
gobuild@raspberrypi:~/go/bin$

gobuild@raspberrypi:~/go/bin$ head -1  /proc/meminfo
MemTotal:         190836 kB
gobuild@raspberrypi:~/go/bin$

[davecheney]

Comment 1:

Currently ./run.bash runs all the tests with 120 second timeout, running on my netgear
stora, it just gets in under the wire at 117 seconds. This machine claims to have a 1Ghz
processor, so I can easily envisage that the math/rand tests run overtime on the Pi. 
% go test math/rand -test.short -test.v
=== RUN TestStandardNormalValues
--- PASS: TestStandardNormalValues (14.70 seconds)
=== RUN TestNonStandardNormalValues
--- PASS: TestNonStandardNormalValues (58.81 seconds)
=== RUN TestStandardExponentialValues
--- PASS: TestStandardExponentialValues (14.73 seconds)
=== RUN TestNonStandardExponentialValues
--- PASS: TestNonStandardExponentialValues (29.50 seconds)
=== RUN TestNormTables
--- PASS: TestNormTables (0.05 seconds)
=== RUN TestExpTables
--- PASS: TestExpTables (0.08 seconds)
PASS
ok      math/rand       117.952s

[davecheney]

Comment 2:

Labels changed: added os-linux.

[minux]

Comment 3:

https://gist.github.com/2874745

[tjyang]

Comment 4:

@minux, for the above successful compilation log on github, what is your "uname -a" and
"hg id" ?

[tjyang]

Comment 5:

With latest src from tip, the test error is now from encoding/gob.
gobuild@raspberrypi:~/go/src$ hg id
c868b808b7a7+ tip
gobuild@raspberrypi:~/go/src$ uname -a
Linux raspberrypi 3.1.9+ #90 Wed Apr 18 18:23:05 BST 2012 armv6l GNU/Linux
gobuild@raspberrypi:~/go/src$ time GOARM=5 ./all.bash
# Building C bootstrap tool.
cmd/dist
# Building compilers and Go bootstrap tool for host, linux/arm.
lib9
libbio
libmach
misc/pprof
cmd/addr2line
cmd/cov
cmd/nm
cmd/objdump
cmd/pack
cmd/prof
cmd/cc
cmd/gc
cmd/5l
cmd/5a
cmd/5c
cmd/5g
pkg/runtime
pkg/errors
pkg/sync/atomic
pkg/sync
pkg/io
pkg/unicode
pkg/unicode/utf8
pkg/unicode/utf16
pkg/bytes
pkg/math
pkg/strings
pkg/strconv
pkg/bufio
pkg/sort
pkg/container/heap
pkg/encoding/base64
pkg/syscall
pkg/time
pkg/os
pkg/reflect
pkg/fmt
pkg/encoding/json
pkg/flag
pkg/path/filepath
pkg/path
pkg/io/ioutil
pkg/log
pkg/regexp/syntax
pkg/regexp
pkg/go/token
pkg/go/scanner
pkg/go/ast
pkg/go/parser
pkg/os/exec
pkg/net/url
pkg/text/template/parse
pkg/text/template
pkg/go/doc
pkg/go/build
cmd/go
# Building packages and commands for linux/arm.
runtime
errors
sync/atomic
sync
io
unicode
unicode/utf8
bytes
bufio
math
syscall
time
os
strconv
reflect
fmt
sort
flag
go/token
strings
path/filepath
go/scanner
go/ast
regexp/syntax
regexp
io/ioutil
net/url
text/template/parse
text/template
go/doc
go/parser
log
path
go/build
text/tabwriter
go/printer
os/exec
cmd/api
hash
crypto
crypto/md5
encoding/binary
debug/dwarf
debug/elf
debug/macho
debug/pe
cmd/cgo
cmd/fix
container/heap
encoding/base64
unicode/utf16
encoding/json
encoding/xml
compress/flate
hash/crc32
compress/gzip
crypto/cipher
crypto/aes
crypto/des
math/rand
math/big
crypto/elliptic
crypto/hmac
crypto/rand
crypto/rc4
crypto/subtle
crypto/rsa
crypto/sha1
crypto/dsa
crypto/ecdsa
encoding/asn1
crypto/x509/pkix
encoding/pem
crypto/x509
runtime/cgo
net
crypto/tls
mime
net/textproto
mime/multipart
runtime/debug
net/http
cmd/go
archive/zip
encoding/gob
expvar
index/suffixarray
html
html/template
runtime/pprof
net/http/pprof
text/scanner
cmd/godoc
cmd/gofmt
cmd/vet
cmd/yacc
archive/tar
compress/bzip2
compress/lzw
hash/adler32
compress/zlib
container/list
container/ring
crypto/sha256
crypto/sha512
database/sql/driver
database/sql
debug/gosym
encoding/ascii85
encoding/base32
encoding/csv
encoding/hex
exp/ebnf
exp/ebnflint
exp/types
exp/gotype
exp/html/atom
exp/html
exp/inotify
exp/norm
exp/locale/collate
hash/fnv
exp/locale/collate/build
exp/proxy
exp/utf8string
hash/crc64
image/color
image
image/draw
image/gif
image/jpeg
image/png
log/syslog
math/cmplx
net/http/cgi
net/http/fcgi
net/http/httptest
net/http/httputil
net/mail
net/rpc
net/rpc/jsonrpc
net/smtp
old/netchan
os/signal
os/user
testing
testing/iotest
testing/quick
# Testing packages.
ok      cmd/api 0.259s
?       cmd/cgo [no test files]
ok      cmd/fix 32.612s
ok      cmd/go  0.314s
?       cmd/godoc       [no test files]
ok      cmd/gofmt       1.066s
?       cmd/vet [no test files]
?       cmd/yacc        [no test files]
ok      archive/tar     0.132s
ok      archive/zip     1.036s
ok      bufio   3.515s
ok      bytes   1.582s
ok      compress/bzip2  1.274s
ok      compress/flate  14.271s
ok      compress/gzip   0.320s
ok      compress/lzw    2.122s
ok      compress/zlib   27.760s
ok      container/heap  0.121s
ok      container/list  0.117s
ok      container/ring  0.363s
?       crypto  [no test files]
ok      crypto/aes      0.328s
ok      crypto/cipher   0.127s
ok      crypto/des      0.651s
ok      crypto/dsa      0.434s
ok      crypto/ecdsa    0.680s
ok      crypto/elliptic 0.294s
ok      crypto/hmac     0.144s
ok      crypto/md5      0.162s
ok      crypto/rand     0.488s
ok      crypto/rc4      0.114s
ok      crypto/rsa      6.384s
ok      crypto/sha1     0.165s
ok      crypto/sha256   0.177s
ok      crypto/sha512   0.198s
ok      crypto/subtle   0.280s
ok      crypto/tls      5.569s
ok      crypto/x509     30.142s
?       crypto/x509/pkix        [no test files]
ok      database/sql    0.325s
ok      database/sql/driver     0.115s
ok      debug/dwarf     0.284s
ok      debug/elf       0.306s
ok      debug/gosym     0.122s
ok      debug/macho     0.152s
ok      debug/pe        0.140s
ok      encoding/ascii85        0.160s
ok      encoding/asn1   0.167s
ok      encoding/base32 0.162s
ok      encoding/base64 0.163s
ok      encoding/binary 0.174s
ok      encoding/csv    0.164s
throw: runtime: out of memory
goroutine 25 [running]:
encoding/gob.(*Decoder).readMessage(0x107b1be0, 0x1000cf66, 0x1077b120)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/decoder.go:92 +0x70
encoding/gob.(*Decoder).recvMessage(0x107b1be0, 0x255a8, 0x10758000)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/decoder.go:84 +0x130
encoding/gob.(*Decoder).decodeTypeSequence(0x107b1be0, 0x1079b100, 0x160, 0x0)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/decoder.go:142 +0x68
encoding/gob.(*Decoder).DecodeValue(0x107b1be0, 0x114288, 0x1079b138, 0x160, 0x0, ...)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/decoder.go:206 +0x174
encoding/gob.(*Decoder).Decode(0x107b1be0, 0x114280, 0x1079b138, 0x107691e0, 0x10746600,
...)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/decoder.go:185 +0x27c
encoding/gob.encFuzzDec(0x1079bc78, 0x113fc0, 0x1079bc50, 0x107283e0, 0x107341b0, ...)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/codec_test.go:1429 +0x348
encoding/gob.testFuzz(0x1079f500, 0x994c53f0, 0x126fc084, 0x64, 0x40061f98, ...)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/codec_test.go:1468 +0x290
encoding/gob.TestFuzzRegressions(0x1079f500, 0xe)
        /usbpub/home/gobuild/go/src/pkg/encoding/gob/codec_test.go:1457 +0xd0
testing.tRunner(0x1079f500, 0x203bbc, 0x0)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:273 +0xac
created by testing.RunTests
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:349 +0x758
goroutine 1 [chan receive]:
testing.RunTests(0x10c00, 0x203ac0, 0x4d, 0x4d, 0x31901, ...)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:350 +0x778
testing.Main(0x10c00, 0x203ac0, 0x4d, 0x4d, 0x200670, ...)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:285 +0x70
main.main()
        /tmp/go-build224681835/encoding/gob/_test/_testmain.go:199 +0x88
goroutine 2 [syscall]:
created by runtime.main
        /usbpub/home/gobuild/go/src/pkg/runtime/proc.c:221
goroutine 3 [syscall]:
created by addtimer
        /usbpub/home/gobuild/go/src/pkg/runtime/ztime_linux_arm.c:72
FAIL    encoding/gob    0.409s
ok      encoding/hex    0.121s
ok      encoding/json   2.574s
ok      encoding/pem    0.197s
ok      encoding/xml    0.405s
ok      errors  0.117s
ok      exp/ebnf        0.121s
ok      exp/ebnflint    0.238s
ok      exp/gotype      12.177s
ok      exp/html        4.572s
ok      exp/html/atom   0.115s
ok      exp/inotify     1.156s
ok      exp/locale/collate      0.662s
ok      exp/locale/collate/build        0.191s
ok      exp/norm        26.808s
ok      exp/proxy       0.147s
ok      exp/types       4.081s
ok      exp/utf8string  0.122s
ok      expvar  0.199s
ok      flag    0.123s
ok      fmt     0.909s
ok      go/ast  0.174s
ok      go/build        5.935s
ok      go/doc  1.775s
ok      go/parser       1.107s
ok      go/printer      8.705s
ok      go/scanner      0.188s
ok      go/token        1.356s
?       hash    [no test files]
ok      hash/adler32    0.625s
ok      hash/crc32      0.112s
ok      hash/crc64      0.112s
ok      hash/fnv        0.114s
ok      html    0.126s
ok      html/template   1.148s
ok      image   1.959s
ok      image/color     0.204s
ok      image/draw      0.833s
?       image/gif       [no test files]
ok      image/jpeg      1.362s
ok      image/png       1.209s
ok      index/suffixarray       0.344s
ok      io      0.175s
ok      io/ioutil       0.120s
ok      log     0.174s
ok      log/syslog      0.355s
ok      math    0.880s
ok      math/big        5.664s
ok      math/cmplx      0.246s
panic: test timed out
goroutine 8 [running]:
testing.alarm()
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:436 +0x5c
created by time.goFunc
        /usbpub/home/gobuild/go/src/pkg/time/sleep.go:94 +0x5c
goroutine 1 [chan receive]:
testing.RunTests(0x10c00, 0x17b8a0, 0x6, 0x6, 0x31301, ...)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:350 +0x778
testing.Main(0x10c00, 0x17b8a0, 0x6, 0x6, 0x17b7e0, ...)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:285 +0x70
main.main()
        /tmp/go-build224681835/math/rand/_test/_testmain.go:63 +0x88
goroutine 2 [syscall]:
created by runtime.main
        /usbpub/home/gobuild/go/src/pkg/runtime/proc.c:221
goroutine 3 [timer goroutine (idle)]:
created by addtimer
        /usbpub/home/gobuild/go/src/pkg/runtime/ztime_linux_arm.c:72
goroutine 9 [runnable]:
testing.tRunner(0x106328c0, 0x17b8d0, 0x0)
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:256
created by testing.RunTests
        /usbpub/home/gobuild/go/src/pkg/testing/testing.go:349 +0x758
FAIL    math/rand       153.863s
ok      mime    0.131s
ok      mime/multipart  2.018s
ok      net     2.569s
ok      net/http        26.954s
ok      net/http/cgi    4.893s
ok      net/http/fcgi   0.238s
ok      net/http/httptest       0.204s
ok      net/http/httputil       0.328s
?       net/http/pprof  [no test files]
ok      net/mail        0.158s
ok      net/rpc 0.913s
ok      net/rpc/jsonrpc 0.264s
ok      net/smtp        0.172s
ok      net/textproto   0.190s
ok      net/url 0.205s
ok      old/netchan     0.447s
ok      os      0.423s
ok      os/exec 2.353s
ok      os/signal       0.113s
ok      os/user 0.123s
ok      path    0.122s
ok      path/filepath   6.152s
ok      reflect 0.201s
ok      regexp  2.895s
ok      regexp/syntax   24.873s
ok      runtime 61.629s
?       runtime/cgo     [no test files]
ok      runtime/debug   0.157s
ok      runtime/pprof   4.368s
ok      sort    1.304s
ok      strconv 19.160s
ok      strings 0.259s
ok      sync    0.763s
ok      sync/atomic     0.329s
ok      syscall 0.292s
?       testing [no test files]
?       testing/iotest  [no test files]
ok      testing/quick   0.918s
ok      text/scanner    0.195s
ok      text/tabwriter  0.189s
ok      text/template   0.528s
ok      text/template/parse     0.243s
ok      time    16.356s
ok      unicode 0.129s
ok      unicode/utf16   0.111s
ok      unicode/utf8    0.180s
?       unsafe  [no test files]
real    47m2.470s
user    42m43.350s
sys     2m44.510s
gobuild@raspberrypi:~/go/src$
gobuild@raspberrypi:~/go/src$ go test math/rand -test.short -test.v
=== RUN TestStandardNormalValues
--- PASS: TestStandardNormalValues (0.39 seconds)
=== RUN TestNonStandardNormalValues
--- PASS: TestNonStandardNormalValues (1.52 seconds)
=== RUN TestStandardExponentialValues
--- PASS: TestStandardExponentialValues (0.39 seconds)
=== RUN TestNonStandardExponentialValues
--- PASS: TestNonStandardExponentialValues (0.78 seconds)
=== RUN TestNormTables
--- PASS: TestNormTables (0.00 seconds)
=== RUN TestExpTables
--- PASS: TestExpTables (0.00 seconds)
PASS
ok      math/rand       3.207s
gobuild@raspberrypi:~/go/src$

[davecheney]

Comment 6:

Hmm, can you please make sure GOARM=5 is set when testing
GOARM=5 go test math/rand -test.short -test.v
If GOARM is not set, the linker will not insert the soft float instructions, so you get
the floating point version.
On my ~1ghz netgear stora (ARMv5) the math/rand test completes in 117s, so just gets in
under the wire. I read the Pi is 700Mhz or so so it's reasonable to assume the test just
doesn't complete in time.

[minux]

Comment 7:

@tjyang2001, log in comment #3, is for rev 4f82ce08466d on an ARM926EJ-S without VFP.
(custom qemu-system-arm v1.0)
I only patched run.bash to raise the timeout values, no other source code changes
required.

[tjyang]

Comment 8:

@dave, here is the math/rand testing with GOARM=5.
gobuild@raspberrypi:~/go/src$ GOARM=5 go test math/rand  -test.short -test.v    === RUN
TestStandardNormalValues
--- PASS: TestStandardNormalValues (19.11 seconds)
=== RUN TestNonStandardNormalValues
--- PASS: TestNonStandardNormalValues (76.50 seconds)
=== RUN TestStandardExponentialValues
--- PASS: TestStandardExponentialValues (19.25 seconds)
=== RUN TestNonStandardExponentialValues
--- PASS: TestNonStandardExponentialValues (38.64 seconds)
=== RUN TestNormTables
--- PASS: TestNormTables (0.07 seconds)
=== RUN TestExpTables
--- PASS: TestExpTables (0.12 seconds)
PASS
ok      math/rand       153.818s
gobuild@raspberrypi:~/go/src$
Here is the cpuinfo.
gobuild@raspberrypi:~/go/src$ cat /proc/cpuinfo
Processor       : ARMv6-compatible processor rev 7 (v6l)
BogoMIPS        : 697.95
Features        : swp half thumb fastmult vfp edsp java tls
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xb76
CPU revision    : 7
Hardware        : BCM2708
Revision        : 0002
Serial          : 00000000ecb55275
gobuild@raspberrypi:~/go/src$

[davecheney]

Comment 9:

Issue #3728 has been merged into this issue.

[davecheney]

Comment 10:

Could you please try this patch
http://golang.org/cl/6304087
Which increases the test timeout by 50% if you use soft float.

[minux]

Comment 11:

consider making the GOARM=5 timeout longer than that in CL 6304087?
i suggest 10m~20m, so that ARM926EJ-S could pass all.bash without any run.bash tweaks.

[rsc]

Comment 12:

We really shouldn't expect people to wait 10-20 minutes for all.bash.
Can we shorten the tests instead?

[ajstarks]

Comment 13:

test using Debian wheezy Raspberry Pi distro, timeout and GOARM=7 patches:
$ uname -a
Linux raspberrypi 3.1.9+ #125 PREEMPT Sun Jun 17 16:09:36 BST 2012 armv6l GNU/Linux
$ go version
go version weekly.2012-03-27 +645947213cac
$ cd $GOROOT/src
$ ./make.bash
$ cd $GOROOT/test
$ go run run.go
run     map.go      : incorrect output
float32 map allows NaN lookup (a)
float32 map should have 5 entries: map[+inf:NaN -0:-0 NaN:<nil> NaN:<nil>]
complex64 map allows NaN lookup (a)
complex64 map should have 5 entries: map[(5+NaNi):<nil> (+5+Infi):NaN (+0-0i):-0
(+5+NaNi):<nil>]
run     nilptr.go       :incorrect output
signal 9
run         fixedbugs/bug257.go : incorrect output
# command-line-arguments
pcIntab: write error: No such file or directory

[remyoudompheng]

Comment 14:

This issue was closed by revision 1a0a09d.

Status changed to Fixed.