[Numpy-discussion] profiling line by line

Robert Kern robert.kern@gmail....
Wed Sep 17 18:29:09 CDT 2008


On Wed, Sep 17, 2008 at 18:09, Ondrej Certik <ondrej@certik.cz> wrote:
> 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.

No, I meant pystone.py. My script-finding code may have (incorrectly)
found a different, uninstrumented pystone.py file somewhere else,
though. Try with "./pystone.py".

> This is an excellent piece of software! Nice job. Just today I needed
> such a thing!
>
>
> How do you easily install it?

"python setup.py install" should have installed the module. I haven't
done anything with the scripts, yet.

> 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?

For things I am developing on, I build them in-place, using the
setuptools "develop" command to add the appropriate path to the
easy-install.pth file. To remove, I would just edit that file.

For thing I'm not developing on, I usually build and install an egg if
at all possible.

But then, I'm typically on a single-user box where I'm root, so I
sometimes do nasty and unsanitary things like chown -R rkern:rkern
/usr/local/.

> 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.

It should only be slow the first time. If it's not, then there's a
problem somewhere (and I wouldn't put it past being in the profiler;
it might screw up something in the import mechanism). Can you do the
import both outside the function *and* inside to see if that changes
the result?

-- 
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 Numpy-discussion mailing list