[Python-Dev] Python 2.3 startup slowness, import related?

[Neil Schemenauer]

Python 2.3 seems to be really sluggish starting up.  Even on my
relatively fast development machine I am getting annoyed when running
small scripts.  I've only just starting digging into it but I think
I've found something interesting.  Here's an excerpt of strace
output for 2.2:

0.0511 rt_sigaction(SIGRT_30, NULL, {SIG_DFL}, 8) = 0
0.0511 rt_sigaction(SIGRT_31, NULL, {SIG_DFL}, 8) = 0
0.0512 rt_sigaction(SIGINT, NULL, {SIG_DFL}, 8) = 0
0.0512 rt_sigaction(SIGINT, {0x4002e610, [], SA_RESTORER, 0x4010e578}, NULL, 8)
0.0513 stat64("/home/nascheme/lib/python", {st_mode=S_IFDIR|0775, st_size=504, 
0.0514 stat64("/home/nascheme/lib/python/site", 0xbfffed08) = -1 ENOENT (No suc
0.0515 open("/home/nascheme/lib/python/site.so", O_RDONLY|O_LARGEFILE) = -1 ENO
0.0516 open("/home/nascheme/lib/python/sitemodule.so", O_RDONLY|O_LARGEFILE) = 
0.0516 open("/home/nascheme/lib/python/site.py", O_RDONLY|O_LARGEFILE) = -1 ENO
0.0517 open("/home/nascheme/lib/python/site.pyc", O_RDONLY|O_LARGEFILE) = -1 EN
0.0517 stat64("/www/plat/python/lib/python23.zip", 0xbfffe3c4) = -1 ENOENT (No 
0.0518 stat64("/www/plat/python/lib", {st_mode=S_IFDIR|0755, st_size=4096, ...}
0.0519 stat64("/www/plat/python/lib/python23.zip/site", 0xbfffed08) = -1 ENOENT
0.0519 open("/www/plat/python/lib/python23.zip/site.so", O_RDONLY|O_LARGEFILE) 
0.0523 open("/www/plat/python/lib/python23.zip/sitemodule.so", O_RDONLY|O_LARGE
0.0538 open("/www/plat/python/lib/python23.zip/site.py", O_RDONLY|O_LARGEFILE) 
0.0541 open("/www/plat/python/lib/python23.zip/site.pyc", O_RDONLY|O_LARGEFILE)
0.0556 stat64("/www/plat/python/lib/python2.3/", {st_mode=S_IFDIR|0755, st_size
0.0557 stat64("/www/plat/python/lib/python2.3/site", 0xbfffed08) = -1 ENOENT (N
0.0557 open("/www/plat/python/lib/python2.3/site.so", O_RDONLY|O_LARGEFILE) = -
0.0561 open("/www/plat/python/lib/python2.3/sitemodule.so", O_RDONLY|O_LARGEFIL
0.0575 open("/www/plat/python/lib/python2.3/site.py", O_RDONLY|O_LARGEFILE) = 4
0.0593 fstat64(4, {st_mode=S_IFREG|0644, st_size=11784, ...}) = 0
0.0594 open("/www/plat/python/lib/python2.3/site.pyc", O_RDONLY|O_LARGEFILE) = 
0.0611 fstat64(5, {st_mode=S_IFREG|0664, st_size=11417, ...}) = 0

and for 2.3:

0.0521 rt_sigaction(SIGRT_30, NULL, {SIG_DFL}, 8) = 0
0.0521 rt_sigaction(SIGRT_31, NULL, {SIG_DFL}, 8) = 0
0.0522 rt_sigaction(SIGINT, NULL, {SIG_DFL}, 8) = 0
0.0522 rt_sigaction(SIGINT, {0x4002e610, [], SA_RESTORER, 0x4010e578}, NULL
0.0524 stat64("/home/nascheme/lib/python", {st_mode=S_IFDIR|0775, st_size=5
0.0551 stat64("/home/nascheme/lib/python/site", 0xbfffed18) = -1 ENOENT (No
0.0716 open("/home/nascheme/lib/python/site.so", O_RDONLY|O_LARGEFILE) = -1
0.0811 open("/home/nascheme/lib/python/sitemodule.so", O_RDONLY|O_LARGEFILE
0.0925 open("/home/nascheme/lib/python/site.py", O_RDONLY|O_LARGEFILE) = -1
0.1079 open("/home/nascheme/lib/python/site.pyc", O_RDONLY|O_LARGEFILE) = -
0.1145 stat64("/www/python/lib/python23.zip", 0xbfffe3d4) = -1 ENOENT (No s
0.1258 stat64("/www/python/lib", {st_mode=S_IFDIR|0755, st_size=4096, ...})
0.1260 stat64("/www/python/lib/python23.zip/site", 0xbfffed18) = -1 ENOENT 
0.1261 open("/www/python/lib/python23.zip/site.so", O_RDONLY|O_LARGEFILE) =
0.1284 open("/www/python/lib/python23.zip/sitemodule.so", O_RDONLY|O_LARGEF
0.1384 open("/www/python/lib/python23.zip/site.py", O_RDONLY|O_LARGEFILE) =
0.1443 open("/www/python/lib/python23.zip/site.pyc", O_RDONLY|O_LARGEFILE) 
0.1492 stat64("/www/python/lib/python2.3/", {st_mode=S_IFDIR|0755, st_size=
0.1512 stat64("/www/python/lib/python2.3/site", 0xbfffed18) = -1 ENOENT (No
0.1623 open("/www/python/lib/python2.3/site.so", O_RDONLY|O_LARGEFILE) = -1
0.1756 open("/www/python/lib/python2.3/sitemodule.so", O_RDONLY|O_LARGEFILE
0.1994 open("/www/python/lib/python2.3/site.py", O_RDONLY|O_LARGEFILE) = 4
0.2081 fstat64(4, {st_mode=S_IFREG|0644, st_size=11784, ...}) = 0
0.2083 open("/www/python/lib/python2.3/site.pyc", O_RDONLY|O_LARGEFILE) = 5
0.2222 fstat64(5, {st_mode=S_IFREG|0664, st_size=11417, ...}) = 0

I cut off the long lines since the first column showing time in
seconds since startup is the interesting bit.  Notice that 2.3 is
making a few more system calls due to the zip import feature but it
is taking a lot more time to find the 'site' module.

I'm going to keep digging but perhaps someone has a theory as to
what's going on.

  Neil