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

[Arnd Baecker]

Hi Ed,

On Thu, 4 May 2006, Ed Schofield wrote:

> Arnd Baecker wrote:
> > Hi,
> >
> > I am trying to profile some code which I am converting from
> > Numeric to numpy.
> > However, the whole profiling seems to break down on the level of hotshot,
> > depending on whether the code is run with Numeric/numpy or (old) scipy.
> >
> > For the attached test I get:
> > - old scipy: all is fine!
> > But all these fail
> > - Numeric 24.2:
> > - numpy version: 0.9.7.2256
> > - scipy version: 0.4.8
> >
> > "Failing" means that I don't get a break-down on which routine takes how
> > much time.
> >
> > First I would be interested whether someone else sees the same behaviour,
> > or if we screwed up something with our installation.
> >
>
> I've had trouble with this too.  I get more meaningful results using
> prof.run('function()') instead of prof.runcall.  I wrote myself a little
> wrapper function, which I'll include below.

Thanks for the wrapper - but it seems that is does not to help in my case:
I replaced in my script
  prof.runcall(main)
by
  prof.run("main()")
and still see the same output, i.e. no information in the
Numeric/numpy/scipy cases.

For your example (with the corresponding modifications) I get meaningful
results in all cases. Completely puzzled ...

> But I'm still mystified why hotshot's runcall doesn't work ...

Something really weird must be going on.

Thanks,

Arnd


> -----------------------
>
>
> def profilerun(function, logfilename='temp.prof'):
>     """A nice wrapper for the hotshot profiler.
>     Usage:
>         profilerun('my_statement')
>
>     Example:
>     >>> from scipy.linalg import inv
>     >>> from numpy import rand
>     >>> def timewaste(arg1=None, arg2=None):
>     >>>     print "Arguments 1 and 2 are: " + str(arg1) + " and " +
> str(arg2)
>     >>>     a = rand(1000,1000)
>     >>>     b = linalg.inv(a)
>     >>>
>     >>> profilerun('timewaste()')
>
>     Example output:
>              7 function calls in 0.917 CPU seconds
>
>        Ordered by: internal time, call count
>
>        ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>             1    0.916    0.916    0.917    0.917 basic.py:176(inv)
>             1    0.000    0.000    0.000    0.000
> function_base.py:162(asarray_chkfinite)
>             1    0.000    0.000    0.917    0.917 <ipython
> console>:1(timewaste)
>             1    0.000    0.000    0.000    0.000
> __init__.py:28(get_lapack_funcs)
>             1    0.000    0.000    0.000    0.000 _internal.py:28(__init__)
>             1    0.000    0.000    0.000    0.000 numeric.py:70(asarray)
>             1    0.000    0.000    0.000    0.000
> _internal.py:36(__getitem__)
>             0    0.000             0.000          profile:0(profiler)
>
>     """
>     prof = hotshot.Profile(logfilename)
>     output = prof.run(function)
>     print "Output of function is:"
>     print output
>     prof.close()
>     stats = hotshot.stats.load(logfilename)
>     stats.strip_dirs()
>     stats.sort_stats('time', 'calls')
>     stats.print_stats()
>
>
>