Let's see how to use a profiler in Python to time and speed up a program.
What is program optimization?
This time we will focus on shortening the processing time
Let's measure the processing time of the program.
Assuming that you have two programs that take 5 seconds, try measuring with the time command.
python
% time ./wait.py
./wait.py 0.02s user 0.02s system 0% cpu 5.057 total
% time ./busy.py
./busy.py 5.01s user 0.02s system 99% cpu 5.038 total
In both cases, it takes a total of 5 seconds from the start to the end of the program, but the situation is slightly different.
Let's take a look at the source actually used:
wait.py
#!/usr/bin/env python
import time
def main():
time.sleep(5)
if __name__ == '__main__':
main()
busy.py
#!/usr/bin/env python
import time
def main():
start = time.time()
while time.time() - start < 5:
pass
if __name__ == '__main__':
main()
How to use time is different
Programs generally spend their time doing things like:
Improve how you spend your time
Where can I improve in the program?
How to find
Log output of the time difference before and after processing
python
start = time.time()
some_func()
print "%f sec" % (time.time() - start)
python
start = time.clock()
some_func()
print "%f sec" % (time.clock() - start)
cProfile
One of the tools called "Profiler" that comes with Python.
Execute with a program to be executed like the time command as an argument
python
% python -m cProfile wait.py
4 function calls in 5.002 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.001 0.001 5.002 5.002 wait.py:3(<module>)
1 0.000 0.000 5.001 5.001 wait.py:5(main)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 5.001 5.001 5.001 5.001 {time.sleep}
| item | Value meaning |
|---|---|
| ncalls | Number of calls |
| tottime | Time spent(Does not include what was called) |
| percall | Time spent per call(tottime/ncalls) |
| cumtime | Time spent(Including what you called) |
| percall | Time spent per call(cumtime/ncalls) |
When you run cProfile.py from the command line
wait_profile.py
#!/usr/bin/env python
import cProfile
import time
def main():
time.sleep(5)
if __name__ == '__main__':
cProfile.run("main()", "wait.prof")
% python -c "import pstats; pstats.Stats('wait.prof').strip_dirs().sort_stats(-1).print_stats()"
Fri Jun 17 00:25:58 2016 wait.prof
4 function calls in 5.005 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 5.005 5.005 <string>:1(<module>)
1 0.000 0.000 5.005 5.005 wait_profile.py:6(main)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 5.005 5.005 5.005 5.005 {time.sleep}
Improve non-functional requirements while maintaining functional requirements
How to recommend
Fibonacci sequence
fib.py
#!/usr/bin/env python
def fib(n):
if n == 0:
return 0
elif n == 1:
return 1
else:
return fib(n-2) + fib(n-1)
if __name__ == '__main__':
assert fib(30) == 832040
python
% time ./fib.py
python fib.py 0.52s user 0.01s system 98% cpu 0.540 total
% python -m cProfile fib.py
2692539 function calls (3 primitive calls) in 1.084 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.084 1.084 fib.py:3(<module>)
2692537/1 1.084 0.000 1.084 1.084 fib.py:3(fib)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
In this example, fib is called too many times. (M / N of tottime means M recursive calls and N non-recursive calls)
Also note that the latter takes longer when comparing the execution time without profile (0.540s) measured with the time command and the execution time with profile (1.084s).
Improve performance while maintaining functionality
Actually try
fib_optimized.py
#!/usr/bin/env python
cache = {}
def fib(n):
if n in cache:
return cache[n]
if n == 0:
cache[n] = 0
elif n == 1:
cache[n] = 1
else:
cache[n] = fib(n-2) + fib(n-1)
return cache[n]
if __name__ == '__main__':
assert fib(30) == 832040
python
% python -m cProfile fib_optimized.py
61 function calls (3 primitive calls) in 0.000 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.000 0.000 fib_optimized.py:3(<module>)
59/1 0.000 0.000 0.000 0.000 fib_optimized.py:5(fib)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
The number of calls has been reduced, and the overall time has been shortened!
The second example. A function that takes the sum from beg to end is implemented using the standard function sum.
takesum.py
#!/usr/bin/env python
def takesum(beg, end):
"take sum of beg, beg+1, ..., end"
assert beg <= end
i = beg
xs = []
while i <= end:
xs.append(i)
i += 1
return sum(xs)
if __name__ == '__main__':
assert takesum(0, 10000000) == 50000005000000
python
% python -m cProfile takesum.py
10000005 function calls in 3.482 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.076 0.076 3.482 3.482 takesum.py:3(<module>)
1 2.418 2.418 3.405 3.405 takesum.py:3(takesum)
10000001 0.878 0.000 0.878 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.109 0.109 0.109 0.109 {sum}
Think about how you can reduce the processing time.
Recommended Posts