[Python-Dev] Startup time

[Jeff Epler]

Comparing 2.2 and 2.3, there are a lot of files opened in 2.3 that
aren't in 2.2.

The comparison is not fully valid because I'm running 2.3 from the
compilation directory, while 2.2 is being run from /usr/bin.

Results:
# Number of attempts to open a file
# Python-2.3b1 compiled with no special flags
$ strace -e open ./python -S -c pass 2>&1 | wc -l
    249
# RedHat 9's /usr/bin/python (based on 2.2.2)
$ strace -e open python -S -c pass 2>&1 | wc -l
    9

# Number of attempts to open an existing file
$ strace -e open python -S -c pass 2>&1 | grep -v ENOENT | wc -l
      8
$ strace -e open ./python -S -c pass 2>&1 | grep -v ENOENT | wc -l
     46

The modules imported in 2.3 are:
    warnings
    re
    sre
    sre_compile
    sre_constants
    sre_parse
    string
    copy_reg
    types
    linecache
    os
    posixpath
    stat
    UserDict
    codecs
    encodings.__init__
    encodings.utf_8

I'm crossing my fingers that the time to reload(m) is similar to the
time to import it in the first place, which gives these maybe-helpful
stats:
$ for i in warnings re sre sre_compile sre_constants sre_parse string copy_reg types linecache os posixpath stat UserDict  codecs encodings.__init__ encodings.utf_8; do echo -n "reload of module $i: "; ./python Lib/timeit.py -s "import $i" "reload($i)"; done
reload of module warnings: 1000 loops, best of 3: 495 usec per loop
reload of module re: 10000 loops, best of 3: 80.3 usec per loop
reload of module sre: 1000 loops, best of 3: 575 usec per loop
reload of module sre_compile: 1000 loops, best of 3: 503 usec per loop
reload of module sre_constants: 1000 loops, best of 3: 380 usec per loop
reload of module sre_parse: 1000 loops, best of 3: 701 usec per loop
reload of module string: 1000 loops, best of 3: 465 usec per loop
reload of module copy_reg: 10000 loops, best of 3: 200 usec per loop
reload of module types: 10000 loops, best of 3: 180 usec per loop
reload of module linecache: 10000 loops, best of 3: 156 usec per loop
reload of module os: 1000 loops, best of 3: 1.53e+03 usec per loop
reload of module posixpath: 1000 loops, best of 3: 403 usec per loop
reload of module stat: 10000 loops, best of 3: 157 usec per loop
reload of module UserDict: 1000 loops, best of 3: 454 usec per loop
reload of module codecs: 1000 loops, best of 3: 852 usec per loop
reload of module encodings.__init__: 1000 loops, best of 3: 244 usec per loop
reload of module encodings.utf_8: 10000 loops, best of 3: 132 usec per loop

These times seem pretty low, but maybe they're accurate.  "os" is the
worst of the lot (1530us) and the total comes to 7507us (7.5ms).  On my
system [2.4GHz Pentium4], this is a typical output of 'time' on python:
$ time ./python -S -c pass

real    0m0.249s
user    0m0.020s
sys     0m0.000s
$ time python -S -c pass

real    0m0.043s
user    0m0.010s
sys     0m0.000s

so the time to import these 17 modules does account for 3/4 of the
additional user time between 2.2.2 and 2.3. (Do you care about the 200ms
increase in "real" time, or just the user time?)

I tried compiling 2.3 with profiling, but gprof sees no samples ("Each
sample counts as 0.01 seconds.  no time accumulated").  I don't have
the capability to try oprofile right now either.

Jeff