David Cournapeau wrote: > On Fri, Dec 5, 2008 at 8:35 AM, Greg Ewing <[EMAIL PROTECTED]> 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 _______________________________________________ Cython-dev mailing list [email protected] http://codespeak.net/mailman/listinfo/cython-dev
