[ Python 文章收集 ] Timing and Profiling in IPython

Source From Here 
Preface 
Timing and profiling code is all sorts of useful, and it’s also just good ol’ fashioned fun (and sometimes surprising!). In this post, I’ll introduce how to do the following through IPython magic functions: 

* %time & %timeit: See how long a script takes to run (one time, or averaged over a bunch of runs).
* %prun: See how long it took each function in a script to run.
* %lprun: See how long it took each line in a function to run.
* %mprun & %memit: See how much memory a script uses (line-by-line, or averaged over a bunch of runs).

Installation & Setup
Please follow instructions to install ipython: 

# pip install ipython
# ipython --version
5.8.0

Most of the functionality we’ll work with is included in the standard library, but if you’re interested in line-by-line or memory profiling, go ahead and run through this setup. First, install the following: 

# pip install line-profiler
# pip install psutil
# pip install memory_profiler

Next, create an IPython profile and extensions directory where we’ll configure a couple of missing magic functions: 

# ipython profile create
[ProfileCreate] Generating default config file: u'/root/.ipython/profile_default/ipython_config.py'

Create the following IPython extention files with the contents below to define the magic functions: 

# vi ~/.ipython/extensions/line_profiler_ext.py

view plaincopy to clipboardprint?

1. import line_profiler  
2.   
3. def load_ipython_extension(ip):  
4.     line_profiler.load_ipython_extension(ip)  

# vi ~/.ipython/extensions/memory_profiler_ext.py

view plaincopy to clipboardprint?

1. import memory_profiler  
2.   
3. def load_ipython_extension(ip):  
4.     memory_profiler.load_ipython_extension(ip)  

Finally, register the extension modules you just created with the default IPython profile we made earlier: 

# vi ~/.ipython/profile_default/ipython_config.py

view plaincopy to clipboardprint?

1. c.TerminalIPythonApp.extensions = [  
2.     'line_profiler_ext',  
3.     'memory_profiler_ext',  
4. ]  
5. c.InteractiveShellApp.extensions = [  
6.     'line_profiler_ext',  
7.     'memory_profiler_ext',  
8. ]  

And that’s it! We’re ready to time and profile to our hearts content. Start ipython and test for the following (executing command ipython): 

view plaincopy to clipboardprint?

1. In [1]: %time?  
2.   
3. In [2]: %timeit?  
4.   
5. In [3]: %prun?  
6.   
7. In [4]: %lprun?  
8.   
9. In [5]: %mprun?  
10.   
11. In [6]: %memit?  

Time Profiling 
Time profiling does exactly what it sounds like - it tells you how much time it took to execute a script, which may be a simple one-liner or a whole module. 

%time 
See how long it takes a script to run. 

view plaincopy to clipboardprint?

1. In [7]: %time {1 for i in xrange(10*100000)}  
2. CPU times: user 76.6 ms, sys: 539 µs, total: 77.2 ms  
3. Wall time: 76.3 ms  
4. Out[7]: {1}  

%timeit 
See how long a script takes to run averaged over multiple runs. 

view plaincopy to clipboardprint?

1. In [8]: %timeit 10 * 100000  
2. 100000000 loops, best of 3: 10 ns per loop  

%timeit will limit the number of runs depending on how long the script takes to execute. Keep in mind that the timeit module in the standard library does not do this by default, so timing long running scripts that way may leave you waiting forever. The number of runs may be set with -n 1000, for example, which will limit %timeit to a thousand iterations, like this: 

view plaincopy to clipboardprint?

1. In [9]: %timeit -n 1000 10 * 100000  
2. 1000 loops, best of 3: 40.1 ns per loop  

Also note that the run-time reported will vary more when limited to fewer loops. 

%prun 
See how long it took each function in a script to run: 

view plaincopy to clipboardprint?

1. In [10]: from time import sleep  
2. In [11]: def foo(): sleep(1)  
3. In [12]: def bar(): sleep(2)  
4. In [13]: def baz(): foo(), bar()  
5. In [14]: %prun baz()  
6.          7 function calls in 3.003 seconds  
7.   
8.    Ordered by: internal time  
9.   
10.    ncalls  tottime  percall  cumtime  percall filename:lineno(function)  
11.         2    3.003    1.502    3.003    1.502 {time.sleep}  
12.         1    0.000    0.000    3.003    3.003 13-aeee66c4e941>:1(baz)  
13.         1    0.000    0.000    2.002    2.002 12-1428f9fb0b95>:1(bar)  
14.         1    0.000    0.000    1.001    1.001 11-a559e91038d2>:1(foo)  
15.         1    0.000    0.000    3.003    3.003 :1()  
16.         1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}  

%lprun 
See how long it took each line in a function to run. 

Create and edit a new module named foo.py in the same directory where you started IPython. Paste the following code in the file and jump back to IPython. 
- foo.py 

view plaincopy to clipboardprint?

1. def foo(n):  
2.     phrase = 'repeat me'  
3.     pmul = phrase * n  
4.     pjoi = ''.join([phrase for x in xrange(n)])  
5.     pinc = ''  
6.     for x in xrange(n):  
7.         pinc += phrase  
8.     del pmul, pjoi, pinc  

Import the function and profile it line by line with %lprun. Functions to profile this way must be passed by name with -f: 

view plaincopy to clipboardprint?

1. In [1]: from foo import foo  
2.   
3. In [2]: %lprun -f foo foo(10000)  
4. Timer unit: 1e-06 s  
5.   
6. Total time: 0.030291 s  
7. File: foo.py  
8. Function: foo at line 1  
9.   
10. Line #      Hits         Time  Per Hit   % Time  Line Contents  
11. ==============================================================  
12.      1                                           def foo(n):  
13.      2         1          4.0      4.0      0.0      phrase = 'repeat me'  
14.      3         1         48.0     48.0      0.2      pmul = phrase * n  
15.      4     10001      10566.0      1.1     34.9      pjoi = ''.join([phrase for x in xrange(n)])  
16.      5         1          1.0      1.0      0.0      pinc = ''  
17.      6     10001       8804.0      0.9     29.1      for x in xrange(n):  
18.      7     10000      10866.0      1.1     35.9          pinc += phrase  
19.      8         1          2.0      2.0      0.0      del pmul, pjoi, pinc  

Memory Profiling 

%mprun 
See how much memory a script uses line by line. Let’s take a look at the same foo() function that we profiled with %lprun - except this time we’re interested in incremental memory usage and not execution time: 

view plaincopy to clipboardprint?

1. In [5]: %mprun -f foo foo(1000)  
2. Filename: foo.py  
3.   
4. Line #    Mem usage    Increment   Line Contents  
5. ================================================  
6.      1     30.9 MiB     30.9 MiB   def foo(n):  
7.      2     30.9 MiB      0.0 MiB       phrase = 'repeat me'  
8.      3     30.9 MiB      0.0 MiB       pmul = phrase * n  
9.      4     30.9 MiB      0.0 MiB       pjoi = ''.join([phrase for x in xrange(n)])  
10.      5     30.9 MiB      0.0 MiB       pinc = ''  
11.      6     30.9 MiB      0.0 MiB       for x in xrange(n):  
12.      7     30.9 MiB      0.0 MiB           pinc += phrase  
13.      8     30.9 MiB      0.0 MiB       del pmul, pjoi, pinc  

%memit 
See how much memory a script uses overall. %memit works a lot like %timeit except that the number of iterations is set with -r instead of -n: 

view plaincopy to clipboardprint?

1. In [6]: %memit -r 3 [x for x in xrange(10000)]  
2. peak memory: 31.00 MiB, increment: 0.05 MiB  

Supplement 
* Difference between CPU time and wall time 

$ time gzip access.log
real 0m2.125s
user 0m1.920s
sys 0m0.170s

This process took 2.125 seconds of wall time ("real"), 1.920 seconds of CPU time ("user"), and 0.170 seconds were spent in kernel mode ("sys"). The remaining 0.035 seconds were time sliced to other processes. (Make note that compressing a file is an intensive process that demands a lot of CPU time from the server.)

* Profiling Python Code 
* Chapter 3 of the Python Data Analysis book 
* Python MotW: Debugging and Profiling