[Numpy-discussion] profiling code with hotshot and Numeric/numpy/scipy/...

[Arnd Baecker]

On Thu, 4 May 2006, Fernando Perez wrote:

> On 5/4/06, Arnd Baecker <arnd.baecker at web.de> wrote:
>
> > I use hotshot in combination with hotshot2cachegrind
> > and kcachegrind to get a nice visual display and line-by-line
> > profilings
> > (http://mail.enthought.com/pipermail/enthought-dev/2006-January/001075.html
> > has all the links ;-).
> > As far as I know this is not possible with the "old profiler".
>
> I've seen that, and it really looks fantastic.  I need to start using it...
>
>  So yes

And no (at least with python <2.5):

  http://docs.python.org/dev/lib/module-hotshot.html

When searching around on c.l.p. I also found this very interesting looking
tool to analyze hotshot output:

http://www.vrplumber.com/programming/runsnakerun/

"""RunSnakeRun is a small GUI utility that allows you to view HotShot
profiler dumps in a sortable GUI view.  It loads the dumps incrementally
in the background so that you can begin viewing the profile results fairly
quickly."""
(I haven't tested it yet though ...)

> > However, the output of this is also puzzling, ranging
> > from 6 (almost useless) lines for Numeric and
> > to overwhelming 6 screens (also useless?) for numpy (see below).
> > ((Also, if you vary the order of the tests you also get
> > different results...))
> >
> > Ouch, this looks like a mess - I know benchmarking/profiling
> > is considered to be tricky - but that tricky?
>
> I'm by no means a profiling guru, but I wonder if this difference is
> due to the fact that numpy uses much more python code than C, while
> much of Numeric's work is done inside C routines.  As far as the
> profile module is concerned, C code is invisible.

I can understand that a python profiler cannot look into C-code
(well, even that might be possible with tricks), but shouldn't
one be able to get the time before and after a line is executed
and from this infer the time spent on a given line of code?
Maybe that's not how these profilers work, but that's the way
I would sprinkle my code with calls to time

A bit more googling reveals an old cookbook example
http://aspn.activestate.com/ASPN/Cookbook/Python/Recipe/81535
"""This recipe lets you take into account time spent in C modules when
profiling your Python code"""

I start to wonder, whether things like this are properly taken into
account in any of the available profilers??

> If I read the info you posted correctly, it also seems like the time
> in your particular example is spent on many different things, rather
> than there being a single obvious bottleneck.  That can make the
> optimization of this case a bit problematic.

The example

from scipy import *
# from math import sqrt

def main():
    x=arange(1,100.0)
    for i in xrange(10000):
        y=sin(x)
        y2=log(x)
        z=sqrt(i)
        z2=abs(y**3)

is pretty cooked up.
Still I had success (well, it really was constructed for this ;-)
with it in the past:
http://www.physik.tu-dresden.de/~baecker/talks/pyco/pyco_.html#benchmarking-and-profiling

Without importing sqrt from math, the output of kcachegrind
http://www.physik.tu-dresden.de/~baecker/talks/pyco/BenchExamples/test_with_old_scipy.png
suggests that 39% of the time is spent in sqrt and 61% in log.

Importing sqrt from math leads to
http://www.physik.tu-dresden.de/~baecker/talks/pyco/BenchExamples/test_with_old_scipy_and_mathsqrt.png
I.e., only the log operation is visible.

So things went fine in this particular example, but
after all this I got really sceptical about profiling in python.

A bit more googling revealed this very interesting thread
  http://thread.gmane.org/gmane.comp.python.devel/73166
which discusses short-comings of hotshot and suggests
lsprof as replacement.

cProfile (which is based on lsprof) will be in Python 2.5

And according to
  http://jcalderone.livejournal.com/21124.html
there is also the possibility to use the output of cProfile
with KCacheGrind.

So all this does not help me right now
(Presently I don't have the time to install python 2.5 alpha
+ numpy + scipy and test cProfile + the corresponding scripts),
but in the longer run it might be the solution ...

Best, Arnd