Speed of Python vs. Perl

[Paul Jackson]

Tim wrote:
|> Unless you've got a broken installation, Python shouldn't
|> be spending *any* time parsing imported files at startup.

Perhaps I should have said "processing", not "parsing".

Whatever, it's definitely _not_ stating, opening or
reading that costing the bulk of the time.  Rather it
is mostly pure application cpu, occurring after the
stat/open/read sequence.

My installation _is_ successfully loading *.pyc files,
as I can see from the par traces.

Perhaps there is no way to be certain I've said this right,
except by actually presenting some of a par trace, taken
from running python with the command:

    echo print '"hi"' | python

The following snippet of par trace shows the handling of
the posixpath import.  This is with Python 1.5.2 on Irix.

  124mS       stat("/usr/local/lib/python1.5/posixpath", 0x7ffefdc8)
  124mS       END-stat() errno = 2 (No such file or directory)
  124mS       open("/usr/local/lib/python1.5/posixpath.so", O_RDONLY, 0666)
  124mS       END-open() errno = 2 (No such file or directory)
  124mS       open("/usr/local/lib/python1.5/posixpathmodule.so", O_RDONLY, 0666)
  124mS       END-open() errno = 2 (No such file or directory)
  124mS       open("/usr/local/lib/python1.5/posixpath.py", O_RDONLY, 0666)
  125mS       END-open() = 6
  125mS       fstat(6, 0x7ffef990)
  125mS       END-fstat() OK
  125mS       open("/usr/local/lib/python1.5/posixpath.pyc", O_RDONLY, 0666)
  125mS       END-open() = 7
  125mS       fstat(7, 0x7ffef850)
  125mS       END-fstat() OK
  125mS       brk(0x10269000)
  125mS       END-brk() OK
  125mS       ioctl(7, __OLD_TCGETA, 0x7ffef800)
  126mS       END-ioctl(7, __OLD_TCGETA, 0x7ffef800) errno = 25
  126mS       read(7, 0x10266718, 4096)
  126mS       END-read(7, ..., 4096) = 4096
  130mS       read(7, 0x10266718, 4096)
  130mS       END-read(7, "e of a file, reported by os.st", 4096) = 4096
  131mS       brk(0x1026b000)
  131mS       END-brk() OK
  157mS       read(7, 0x10266718, 4096)
  157mS       END-read(7, "er constructions.  If user or ", 4096) = 2786
  158mS       brk(0x1026d000)
  158mS       END-brk() OK
  161mS       close(7)
  161mS       END-close() OK
  161mS       stat("/usr/local/lib/python1.5/stat", 0x7ffeebc8)

Notice that:

  - It did open posixpatch.pyc (and didn't need to rewrite the *.pyc)

  - It took just 1 mSec to get through all the stats, fstats and opens
	(This was rerunning the test, so all was in the cache.)

  - It took another 35 mSec to get through the brk's and reads.

  - For example, it took 26 mSecs, from the brk at the 131 mS mark
	to the read at the 157 mS mark, purely in user cpu.  Looking
	at the captured real/user/sys times for this test case shows
	that indeed this time is spent in user cpu, not waiting,
	and not in system cpu.

  - If you're curious, the close(6) of the posixpath.py file comes
	another 24 lines later in the trace, after the stat module
	is finished processing (I'd guess this means that the stat
	import was nested in the posixpath module).

So while it may not be "parsing" in that 26 mSecs, it's sure
doing something that is _not_ due to the costs of stat'ing,
open'ing or read'ing files, but rather somehow related to the
processing of what is read.

The Intel/Linux times and traces (also Python 1.5.2) look
similar.  If you'd like similar analysis for Python 2.0, let
me know.  My apologies for not upgrading yet (Python 1.5.2 is
meeting all my current needs, so I've been lazy).

Likely the next step is to profile the code, to see where it is
executing during all this time.
-- 
                          I won't rest till it's the best ...
                          Manager, Linux System Software
                          Paul Jackson <pj at sgi.com> 1.650.933.1373