[Python-Dev] inspect.py very slow under 2.5 (original) (raw)

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