[Numpy-discussion] profiling line by line
Robert Kern
robert.kern at gmail.com
Tue Sep 16 21:56:24 EDT 2008
On Mon, Sep 15, 2008 at 11:13, Arnar Flatberg <arnar.flatberg at 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