classification
Title: importing of "time" module is terribly slow
Type: behavior Stage:
Components: Library (Lib) Versions: Python 2.4, Python 2.5
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: amaury.forgeotdarc, ndyankov
Priority: normal Keywords:

Created on 2009-09-25 15:52 by ndyankov, last changed 2009-09-25 19:23 by ndyankov. This issue is now closed.

Files
File name Uploaded Description Edit
dns-test.tar.gz ndyankov, 2009-09-25 15:52
Messages (4)
msg93108 - (view) Author: Nikolay Dyankov (ndyankov) Date: 2009-09-25 15:52
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
msg93110 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2009-09-25 16:02
> "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.
msg93127 - (view) Author: Nikolay Dyankov (ndyankov) Date: 2009-09-25 19:04
Stupid me :))
I must have really missed that.

Still I don't understand why the read call takes 10 seconds to complete.
msg93129 - (view) Author: Nikolay Dyankov (ndyankov) Date: 2009-09-25 19:23
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.
:)
History
Date User Action Args
2009-09-25 19:23:33ndyankovsetstatus: open -> closed

messages: + msg93129
2009-09-25 19:04:33ndyankovsetstatus: pending -> open

messages: + msg93127
2009-09-25 16:02:51amaury.forgeotdarcsetstatus: open -> pending

nosy: + amaury.forgeotdarc
messages: + msg93110

resolution: not a bug
2009-09-25 15:52:20ndyankovcreate