[Numpy-discussion] profiling line by line

Robert Kern robert.kern@gmail....
Tue Sep 16 20:56:24 CDT 2008


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

Line #      Hits         Time   % Time  Line Contents
=====================================================
    79                                  @profile
    80                                  def Proc0(loops=LOOPS):
    81                                      global IntGlob
    82                                      global BoolGlob
    83                                      global Char1Glob
    84                                      global Char2Glob
    85                                      global Array1Glob
    86                                      global Array2Glob
    87                                      global PtrGlb
    88                                      global PtrGlbNext
    89
    90         1           11      0.0      starttime = clock()
    91     50001       128471      1.5      for i in range(loops):
    92     50000       125580      1.5          pass
    93         1           28      0.0      nulltime = clock() - starttime
    94
    95         1           21      0.0      PtrGlbNext = Record()
    96         1            8      0.0      PtrGlb = Record()
    97         1            2      0.0      PtrGlb.PtrComp = PtrGlbNext
    98         1            2      0.0      PtrGlb.Discr = Ident1
    99         1            2      0.0      PtrGlb.EnumComp = Ident3
   100         1            3      0.0      PtrGlb.IntComp = 40
   101         1            3      0.0      PtrGlb.StringComp =
"DHRYSTONE PROGRAM, SOME STRING"
   102         1            2      0.0      String1Loc = "DHRYSTONE
PROGRAM, 1'ST STRING"
   103         1            5      0.0      Array2Glob[8][7] = 10
   104
   105         1            6      0.0      starttime = clock()
   106
   107     50001       123728      1.5      for i in range(loops):
   108     50000       220345      2.6          Proc5()
   109     50000       238459      2.8          Proc4()
   110     50000       119789      1.4          IntLoc1 = 2
   111     50000       123639      1.5          IntLoc2 = 3
   112     50000       116081      1.4          String2Loc =
"DHRYSTONE PROGRAM, 2'ND STRING"
   113     50000       119487      1.4          EnumLoc = Ident2
   114     50000       653711      7.7          BoolGlob = not
Func2(String1Loc, String2Loc)
   115     50000       130518      1.5          while IntLoc1 < IntLoc2:
   116     50000       132916      1.6              IntLoc3 = 5 *
IntLoc1 - IntLoc2
   117     50000       235608      2.8              IntLoc3 =
Proc7(IntLoc1, IntLoc2)
   118     50000       147952      1.7              IntLoc1 = IntLoc1 + 1
   119     50000       664949      7.9          Proc8(Array1Glob,
Array2Glob, IntLoc1, IntLoc3)
   120     50000      1710897     20.2          PtrGlb = Proc1(PtrGlb)
   121     50000       130536      1.5          CharIndex = 'A'
   122     50000       130006      1.5          while CharIndex <= Char2Glob:
   123    100000       546206      6.5              if EnumLoc ==
Func1(CharIndex, 'C'):
   124                                                  EnumLoc = Proc6(Ident1)
   125    100000       353517      4.2              CharIndex =
chr(ord(CharIndex)+1)
   126     50000       133892      1.6          IntLoc3 = IntLoc2 * IntLoc1
   127     50000       126802      1.5          IntLoc2 = IntLoc3 / IntLoc1
   128     50000       139932      1.7          IntLoc2 = 7 * (IntLoc3
- IntLoc2) - IntLoc1
   129     50000      1912016     22.6          IntLoc1 = Proc2(IntLoc1)
   130
   131         1           12      0.0      benchtime = clock() -
starttime - nulltime
   132         1           18      0.0      return benchtime, (loops /
benchtime)

File: pystone.py
Function: Proc2 at line 150
Total time: 0.612312 s

Line #      Hits         Time   % Time  Line Contents
=====================================================
   150                                  @profile
   151                                  def Proc2(IntParIO):
   152     50000        75147     12.3      IntLoc = IntParIO + 10
   153     50000        64428     10.5      while 1:
   154     50000        70023     11.4          if Char1Glob == 'A':
   155     50000        69017     11.3              IntLoc = IntLoc - 1
   156     50000        70189     11.5              IntParIO = IntLoc - IntGlob
   157     50000        65503     10.7              EnumLoc = Ident1
   158     50000        68191     11.1          if EnumLoc == Ident1:
   159     50000        66168     10.8              break
   160     50000        63646     10.4      return IntParIO


I used to call kernprof.py lsprof.py, but then I realized that's what
cProfile used to be named when it was outside of the stdlib. So I'm
just going to call it kernprof until a better name comes along.

So, I could use some comments on the workflow. Does this look sensible
to everyone? How else would you like to use it?

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