[Python-Dev] inspect.py very slow under 2.5

Fernando Perez fperez.net at gmail.com
Wed Sep 6 06:56:04 CEST 2006


Hi all,

I know that the 2.5 release is extremely close, so this will probably be
2.5.1 material.  I discussed it briefly with Guido at scipy'06, and he
asked for some profile-based info, which I've only now had time to gather. 
I hope this will be of some use, as I think the problem is rather serious.

For context: I am the IPython lead developer (http://ipython.scipy.org), and
ipython is used as the base shell for several interactive environments, one
of which is the mathematics system SAGE
(http://modular.math.washington.edu/sage).  It was the SAGE lead who first
ran into this problem while testing SAGE with 2.5.

The issue is the following: ipython provides several exception reporting
modes which give a lot more information than python's default tracebacks. 
In order to generate this info, it makes extensive use of the inspect
module.  The module in ipython responsible for these fancy tracebacks is:

http://projects.scipy.org/ipython/ipython/browser/ipython/trunk/IPython/ultraTB.py

which is an enhanced port of Ka Ping-Yee's old cgitb module.

Under 2.5, the generation of one of these detailed tracebacks is /extremely/
expensive, and the cost goes up very quickly the more modules have been
imported into the current session.  While in a new ipython session the
slowdown is not crippling, under SAGE (which starts with a lot of loaded
modules) it is bad enough to make the system nearly unusable.

I'm attaching a little script which can be run to show the problem, but you
need IPython to be installed to run it.  If any of you run ubuntu, fedora,
suse or almost any other major linux distro, it's already available via the
usual channels.

In case you don't want to (or can't) run the attached code, here's a summary
of what I see on my machine (ubuntu dapper).  Using ipython under python
2.4.3, I get:

         2268 function calls (2225 primitive calls) in 0.020 CPU seconds

   Ordered by: call count
   List reduced from 127 to 32 due to restriction <0.25>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      305    0.000    0.000    0.000    0.000 :0(append)
  259/253    0.010    0.000    0.010    0.000 :0(len)
      177    0.000    0.000    0.000    0.000 :0(isinstance)
       90    0.000    0.000    0.000    0.000 :0(match)
       68    0.000    0.000    0.000    0.000 ultraTB.py:539(tokeneater)
       68    0.000    0.000    0.000    0.000 tokenize.py:16
(generate_tokens)
       61    0.000    0.000    0.000    0.000 :0(span)
       57    0.000    0.000    0.000    0.000 sre_parse.py:130(__getitem__)
       56    0.000    0.000    0.000    0.000 string.py:220(lower)

etc, while running the same script under ipython/python2.5 and no other
changes gives:

         230370 function calls (229754 primitive calls) in 3.340 CPU seconds

   Ordered by: call count
   List reduced from 83 to 21 due to restriction <0.25>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    55003    0.420    0.000    0.420    0.000 :0(startswith)
    45026    0.264    0.000    0.264    0.000 :0(endswith)
    20013    0.148    0.000    0.148    0.000 :0(append)
    12138    0.180    0.000    0.660    0.000 posixpath.py:156(islink)
    12138    0.192    0.000    0.192    0.000 :0(lstat)
    12138    0.180    0.000    0.288    0.000 stat.py:60(S_ISLNK)
    12138    0.108    0.000    0.108    0.000 stat.py:29(S_IFMT)
    11838    0.680    0.000    1.244    0.000 posixpath.py:56(join)
     4837    0.052    0.000    0.052    0.000 :0(len)
     4362    0.028    0.000    0.028    0.000 :0(split)
     4362    0.048    0.000    0.100    0.000 posixpath.py:47(isabs)
     3598    0.036    0.000    0.056    0.000 string.py:218(lower)
     3598    0.020    0.000    0.020    0.000 :0(lower)
     2815    0.032    0.000    0.032    0.000 :0(isinstance)
     2809    0.028    0.000    0.028    0.000 :0(join)
     2808    0.264    0.000    0.520    0.000 posixpath.py:374(normpath)
     2632    0.040    0.000    0.068    0.000 inspect.py:35(ismodule)
     2143    0.016    0.000    0.016    0.000 :0(hasattr)
     1884    0.028    0.000    0.444    0.000 posixpath.py:401(abspath)
     1557    0.016    0.000    0.016    0.000 :0(range)
     1078    0.008    0.000    0.044    0.000 inspect.py:342(getfile)


These enormous numbers of calls are the origin of the slowdown, and the more
modules have been imported, the worse it gets.

I haven't had time to dive deep into inspect.py to try and fix this, but I
figured it would be best to at least report it now.  As far as IPython and
its user projects is concerned, I'll probably hack things to overwrite
inspect.py from 2.4 over the 2.5 version in the exception reporter, because
the current code is simply unusable for detailed tracebacks.  It would be
great if this could be fixed in the trunk at some point.

I'll be happy to provide further feedback or put this information elsewhere. 
Guido suggested initially posting here, but if you prefer it on the SF
tracker (even as incomplete as this report is) I'll be glad to do so.

Regards,

f
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: traceback_timings.py
Url: http://mail.python.org/pipermail/python-dev/attachments/20060905/fb0ac8bf/attachment.asc 


More information about the Python-Dev mailing list