[Cython] Speed up cython for enum declarations
Robert Kern
robert.kern at gmail.com
Fri Dec 5 02:06:09 CET 2008
David Cournapeau wrote:
> On Fri, Dec 5, 2008 at 8:35 AM, Greg Ewing <greg.ewing at canterbury.ac.nz> wrote:
>> Robert Bradshaw wrote:
>>> Perhaps a 1000 line
>>> enum is a bit faster, but it seems like it should be a lot faster
>> It might be informative to find out what proportion of
>> the time is spent on scanning, parsing, building the
>> parse tree, traversing the parse tree, etc.
>
> What kind of profiling would be most useful for cython/pyrex
> developers ? I did not see any option for profiling cython itself in
> cython code, but is hotshot kind of information preferred over
> cProfile ?
May I suggest my kernprof.py script to invoke cProfile? It has a nice feature
such that it will locate scripts like cython on your $PATH. You don't have to
write any particular profiling support.
http://www.enthought.com/~rkern/cgi-bin/hgwebdir.cgi/line_profiler/raw-file/582df342463a/kernprof.py
E.g.
$ kernprof.py cython e_2_2000.pyx
Wrote profile results to cython.prof
$ python -m pstats cython.prof
Welcome to the profile statistics browser.
% strip
% reverse
% sort time
% stats 20
Thu Dec 4 18:51:19 2008 cython.prof
1092804 function calls (830642 primitive calls) in 2.267 CPU seconds
Ordered by: internal time
List reduced from 963 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
8219 0.412 0.000 0.500 0.000 Scanning.py:401(next)
52164/15 0.347 0.000 1.286 0.086 Visitor.py:18(visit)
212836 0.242 0.000 0.242 0.000 {getattr}
52164/15 0.159 0.000 1.204 0.080 Visitor.py:138(visitchildren)
52149/23 0.136 0.000 1.204 0.052 Visitor.py:86(visitchild)
52164/15 0.135 0.000 1.204 0.080 Visitor.py:92(visitchildren)
1 0.047 0.047 0.073 0.073 Scanning.py:6(<module>)
52160 0.041 0.000 0.059 0.000 inspect.py:291(getmro)
4083 0.038 0.000 0.057 0.000 Symtab.py:273(declare)
36057/14 0.038 0.000 0.929 0.066 Visitor.py:179(visit_Node)
4000 0.029 0.000 0.160 0.000 Parsing.py:2066(p_c_enum_item)
4 0.029 0.007 0.029 0.007
hashlib.py:55(__get_builtin_constructor)
52573 0.021 0.000 0.021 0.000 {isinstance}
4037 0.020 0.000 0.033 0.000 Scanning.py:359(indentation_action)
117371 0.018 0.000 0.018 0.000 {method 'append' of 'list' objects}
52163 0.018 0.000 0.018 0.000 {hasattr}
8096 0.015 0.000 0.085 0.000 Actions.py:46(perform)
1 0.015 0.015 0.015 0.015 Regexps.py:9(<module>)
1 0.015 0.015 0.044 0.044 hashlib.py:52(<module>)
1 0.015 0.015 0.015 0.015 Annotate.py:3(<module>)
It looks like a fair chunk of time is getting spent by the getattr() on line 26
of Visitor.py:BasicVisitor.visit() because of missing entries in the
dispatch_table. Per the comment there, that's possibly optimizable.
While we're at it, here are the line-base profiles for the top two functions
("kernprof.py -l cython e_2_2000.pyx" if you install the whole line_profiler
package):
$ python -m line_profiler cython.lprof
Timer unit: 1e-06 s
File:
/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/site-packages/Cython-0.10-py2.5-macosx-10.3-fat.egg/Cython/Compiler/Scanning.py
Function: next at line 401
Total time: 0.697081 s
Line # Hits Time Per Hit % Time Line Contents
==============================================================
401 @profile
402 def next(self):
403 8219 17393 2.1 2.5 try:
404 8219 576929 70.2 82.8 sy, systring =
self.read()
405 except UnrecognizedInput:
406
self.error("Unrecognized character")
407 8219 20516 2.5 2.9 if sy == 'IDENT':
408 4077 9589 2.4 1.4 if systring in
self.resword_dict:
409 23 42 1.8 0.0 sy = systring
410 else:
411 4054 12283 3.0 1.8 systring =
EncodedString(systring)
412 4054 9845 2.4 1.4
systring.encoding = self.source_encoding
413 8219 16423 2.0 2.4 self.sy = sy
414 8219 16570 2.0 2.4 self.systring = systring
415 8219 17491 2.1 2.5 if debug_scanner:
416 _, line, col =
self.position()
417 if not
self.systring or self.sy == self.systring:
418 t = self.sy
419 else:
420 t = "%s %s" %
(self.sy, self.systring)
421 print("--- %3d %2d
%s" % (line, col, t))
File:
/Library/Frameworks/Python.framework/Versions/2.5/lib/python2.5/site-packages/Cython-0.10-py2.5-macosx-10.3-fat.egg/Cython/Compiler/Visitor.py
Function: visit at line 18
Total time: 3.09749 s
Line # Hits Time Per Hit % Time Line Contents
==============================================================
18 @profile
19 def visit(self, obj):
20 52164 117647 2.3 3.8 cls = obj.__class__
21 52164 140536 2.7 4.5 m =
self.dispatch_table.get(cls.__name__)
22 52164 89747 1.7 2.9 if m is None:
23 # Must resolve,
try entire hierarchy
24 52160 85652 1.6 2.8 pattern = "visit_%s"
25 52160 238251 4.6 7.7 mro =
inspect.getmro(cls)
26 152410 258036 1.7 8.3 for cls in mro:
27 152410 623635 4.1 20.1 m =
getattr(self, pattern % cls.__name__, None)
28 152410 277683 1.8 9.0 if m is not None:
29 52160 92241 1.8 3.0 break
30 else:
31 print
type(self), type(obj)
32 print
self.access_path
33 print
self.access_path[-1][0].pos
34 print
self.access_path[-1][0].__dict__
35 raise
RuntimeError("Visitor does not accept object: %s" % obj)
36 52160 128948 2.5 4.2
self.dispatch_table[cls.__name__] = m
37 52164 1045118 20.0 33.7 return m(obj)
--
Robert Kern
"I have come to believe that the whole world is an enigma, a harmless enigma
that is made terrible by our own mad attempt to interpret it as though it had
an underlying truth."
-- Umberto Eco
More information about the Cython-dev
mailing list