[Numpy-discussion] profiling line by line

Ondrej Certik ondrej@certik...
Wed Sep 17 18:09:39 CDT 2008


On Wed, Sep 17, 2008 at 3:56 AM, Robert Kern <robert.kern@gmail.com> wrote:
> On Mon, Sep 15, 2008 at 11:13, Arnar Flatberg <arnar.flatberg@gmail.com> wrote:
>> That would make me an extremely happy user, I've been looking for this for
>> years!
>> I can't imagine I'm the only one who profiles some hundred lines of code and
>> ends up with 90% of total time in the dot-function
>
> For the time being, you can grab it here:
>
> http://www.enthought.com/~rkern/cgi-bin/hgwebdir.cgi/line_profiler/
>
> It requires Cython and a C compiler to build. I'm still debating
> myself about the desired workflow for using it, but for now, it only
> profiles functions which you have registered with it. I have made the
> profiler work as a decorator to make this easy. E.g.,
>
>  from line_profiler import LineProfiler
>
>  profile = LineProfiler()
>
>  @profile
>  def my_slow_func():
>      ...
>
>  profile.dump_stats('my_slow_func.lprof')
>
> This is kind of inconvenient, so I have a little script that handles
> everything except for the @profile itself. It started as a script to
> run cProfile nicely, so it actually does that by default.
>
> I took pystone.py from the Python source and added a couple of
> @profile decorators to demonstrate:
>
>
> [line_profiler]$ ./kernprof.py --help
> Usage: ./kernprof.py [-s setupfile] [-o output_file_path] scriptfile [arg] ...
>
> Options:
>  -h, --help            show this help message and exit
>  -l, --line-by-line    Use the line-by-line profiler from the line_profiler
>                        module instead of cProfile. Implies --builtin.
>  -b, --builtin         Put 'profile' in the builtins. Use 'profile.enable()'
>                        and 'profile.disable()' in your code to turn it on and
>                        off, or '@profile' to decorate a single function, or
>                        'with profile:' to profile a single section of code.
>  -o OUTFILE, --outfile=OUTFILE
>                        Save stats to <outfile>
>  -s SETUP, --setup=SETUP
>                        Code to execute before the code to profile
>
> [line_profiler]$ ./kernprof.py -l pystone.py
> Pystone(1.1) time for 50000 passes = 11.34
> This machine benchmarks at 4409.17 pystones/second
> Wrote profile results to pystone.py.lprof
>
> [line_profiler]$ ./view_line_prof.py pystone.py.lprof
> Timer unit: 1e-06 s
>
> File: pystone.py
> Function: Proc0 at line 79
> Total time: 8.46516 s
[...]

This is what I am getting:

$ ./kernprof.py -l pystone.py
Wrote profile results to pystone.py.lprof
$ ./view_line_prof.py pystone.py.lprof
Timer unit: 1e-06 s

$

So I think you meant:

$ ./kernprof.py -l mystone.py
20628
Wrote profile results to mystone.py.lprof
$ ./view_line_prof.py mystone.py.lprof
Timer unit: 1e-06 s

File: pystone.py
Function: Proc0 at line 79
Total time: 13.0803 s
[...]

Now it works.

This is an excellent piece of software! Nice job. Just today I needed
such a thing!


How do you easily install it? I usually do "python setup.py install
--home=~/lib" and I have the PYTHONPATH + PATH setup in my .bashrc,
but I then need to manually remove the stuff from my ~/lib if I want
to uninstall, which sucks. So this time I just did "python setup.py
build" and moved the .so file manually to the current dir. But there
must be a better way. What is your workflow?

Anyway, so I used it on my code and here is what I got:

File: hermes1d/mesh.py
Function: integrate_function at line 119
Total time: 0.647412 s

Line #      Hits         Time   % Time  Line Contents
=====================================================
   119                                      @profile
   120                                      def integrate_function(self, f):
   121                                          """
   122                                          Integrate the function
"f" on the element.
   123                                          """
   124        96         1091      0.2          from numpy import array
   125        96       461070     71.2          from scipy.integrate
import quadrature
   126        96          496      0.1          a, b =
self.nodes[0].x, self.nodes[1].x
   127        96          418      0.1          def func(x):
   128                                              #print x
   129                                              #print
array([f.f(y) for y in x])
   130                                              return
array([f.f(y) for y in x])
   131        96       183903     28.4          val, err =
quadrature(func, a, b)
   132                                          #print val, a, b
   133                                          #stop
   134        96          434      0.1          return val



This is interesting, because 70% of time is spent on "from
scipy.integrate import quadrature". So this is not good.

So I moved it out and voila! My code is 3.4x faster. I really didn't
know that importing (scipy.integrate) is *so* slow.

File: hermes1d/mesh.py
Function: integrate_function at line 121
Total time: 0.189429 s

Line #      Hits         Time   % Time  Line Contents
=====================================================
   121                                      @profile
   122                                      def integrate_function(self, f):
   123                                          """
   124                                          Integrate the function
"f" on the element.
   125                                          """
   126        96         1080      0.6          from numpy import array
   127        96          499      0.3          a, b =
self.nodes[0].x, self.nodes[1].x
   128        96          408      0.2          def func(x):
   129                                              #print x
   130                                              #print
array([f.f(y) for y in x])
   131                                              return
array([f.f(y) for y in x])
   132        96       187020     98.7          val, err =
quadrature(func, a, b)
   133                                          #print val, a, b
   134                                          #stop
   135        96          422      0.2          return val

Btw, after profiling quadrature in scipy:


   110       384         1241      0.1      err = 100.0
   111       384         1184      0.1      val = err
   112       384         1167      0.1      n = 1
   113       384         4086      0.5      vfunc = vectorize1(func,
args, vec_func=vec_func)
   114      1152         4509      0.5      while (err > tol) and (n < maxiter):
   115       768       879911     97.4          newval =
fixed_quad(vfunc, a, b, (), n)[0]
   116       768         4072      0.5          err = abs(newval-val)
   117       768         2470      0.3          val = newval
   118       768         2513      0.3          n = n + 1
   119       384         1381      0.2      if n == maxiter:
   120                                          print "maxiter (%d)
exceeded. Latest difference = %e" % (n,err)
   121       384         1225      0.1      return val, err


And fixed_quad:

    46       768       630714     74.4      [x,w] = p_roots(n)
    47       768         8757      1.0      x = real(x)
    48       768        13312      1.6      ainf, binf = map(isinf,(a,b))
    49       768         2912      0.3      if ainf or binf:
    50                                          raise ValueError,
"Gaussian quadrature is only available for " \
    51                                                "finite limits."
    52       768        22106      2.6      y = (b-a)*(x+1)/2.0 + a
    53       768       170229     20.1      return
(b-a)/2.0*sum(w*func(y,*args),0), None

it gives interesting results. For example in my case, where I need to
call this often, I should cache the p_roots results.

Anyways, this profiler is exciting, it makes things easy to profile.

Ondrej


More information about the Numpy-discussion mailing list