importing of "time" module is terribly slow

[ndyankov]

BPO	6993
Nosy	@amauryfa
Files	dns-test.tar.gz

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2009-09-25.19:23:33.203>
created_at = <Date 2009-09-25.15:52:19.999>
labels = ['invalid', 'type-bug', 'library']
title = 'importing of "time" module is terribly slow'
updated_at = <Date 2009-09-25.19:23:33.191>
user = 'https://bugs.python.org/ndyankov'

bugs.python.org fields:

activity = <Date 2009-09-25.19:23:33.191>
actor = 'ndyankov'
assignee = 'none'
closed = True
closed_date = <Date 2009-09-25.19:23:33.203>
closer = 'ndyankov'
components = ['Library (Lib)']
creation = <Date 2009-09-25.15:52:19.999>
creator = 'ndyankov'
dependencies = []
files = ['14972']
hgrepos = []
issue_num = 6993
keywords = []
message_count = 4.0
messages = ['93108', '93110', '93127', '93129']
nosy_count = 2.0
nosy_names = ['amaury.forgeotdarc', 'ndyankov']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = None
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue6993'
versions = ['Python 2.5', 'Python 2.4']

[ndyankov]

The behaviour described below is not always reproduced.

The attached test script simply tries to import a couple of dns-python
modules, which in turn import other ones. No code is being executed.
You expect it to exit for less than a second but it does not. Instead,
it hangs when "time" module is being imported (eventually it exits after
a long time).

Attached are stdout log and system call log produced by strace with
timestamps.

I don't know what causes it but I'm getting it on at least two machines
(the second being virtual):

$ cat /etc/fedora-release 
Fedora release 10 (Cambridge)
$ uname -a
Linux kiki 2.6.27.30-170.2.82.fc10.i686.PAE #1 SMP Mon Aug 17 08:24:23
EDT 2009 i686 i686 i386 GNU/Linux
$ python -c "import sys; print sys.version"
2.5.2 (r252:60911, Sep 30 2008, 15:41:38) 
[GCC 4.3.2 20080917 (Red Hat 4.3.2-4)]


$ cat /etc/redhat-release 
CentOS release 5.3 (Final)
$ uname -a
Linux proxy.sc.com 2.6.18-128.el5 #1 SMP Wed Jan 21 10:44:23 EST 2009
i686 i686 i386 GNU/Linux
$ python -c "import sys; print sys.version"
2.4.3 (#1, Jan 21 2009, 01:10:13) 
[GCC 4.1.2 20071124 (Red Hat 4.1.2-42)]

I don't think it's related to dns-python(that's why I am posting it
here) but for reference the version used is 1.7.1.

The timestamps in stdout.log and strace.log clearly show the slowdown:

# strace.log
18:18:53 ioctl(6, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfac06b0) = -1 EINVAL
(Invalid argument)
18:18:53 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e4f000
18:18:53 read(6, "F\t\262\276\261s\223I"..., 4096) = 8
18:19:01 read(6, ")v\244\36\v=U\336"..., 4096) = 8
18:19:11 close(6) = 0
18:19:11 munmap(0xb7e4f000, 4096) = 0
18:19:11 gettimeofday({1253891951, 431529}, NULL) = 0

# stdout.log
18:18:53 dns.entropy
18:18:53 time
18:19:11 hashlib
18:19:11 _hashlib

[amauryfa]

"No code is being executed"

Hmm, in dns.entropy module (I found the code there:
http://www.dnspython.com/docs/1.7.1/html/dns.entropy-pysrc.html
) line 89 says "pool = EntropyPool()", and the __init__ function opens
and reads bytes from /dev/random.
This is the cause of the slowdown, as is shown by the strace file.

The time module is innocent here.

[ndyankov]

Stupid me :))
I must have really missed that.

Still I don't understand why the read call takes 10 seconds to complete.

[ndyankov]

OK, I found the reason and it is the very fact of using /dev/random
which would block if there aren't enough random numbers in queue.
Maybe dns-python should be using /dev/urandom instead (though there
might be reasons for not doing so).

The mystery is revealed.
I am closing the bug.
:)