python性能分析之cProfile模塊

cProfile是標准庫內建的分析工具的其中一個，另外兩個是hotshot和profile

-s cumulative

-s cumulative開關告訴cProfile對每個函數累計花費的時間進行排序,他能讓我看到代碼最慢的部分。
我們有這樣一個函數。
loopdemo.py

def foo():
    for a in range(0, 101):
        for b in range(0, 101):
            if a + b == 100:
                yield a, b
if __name__ == '__main__':
    for item in foo():
        print(item)

運行下面命令

python3 -m cProfile -s cumulative loopdemo.py

得到如下結果

         206 function calls in 0.001 seconds
         #在0.01秒內共發生了206次函數調用。包括cProfile的開銷。

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 {built-in method builtins.exec}
        1    0.000    0.000    0.001    0.001 loopdemo.py:7(<module>)
      102    0.001    0.000    0.001    0.000 loopdemo.py:7(foo)
      101    0.001    0.000    0.001    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

其中對參數的解釋:
ncalls：表示函數調用的次數；
tottime：表示指定函數的總的運行時間，除掉函數中調用子函數的運行時間；
percall：（第一個percall）等於 tottime/ncalls；
cumtime：表示該函數及其所有子函數的調用運行的時間，即函數開始調用到返回的時間；
percall：（第二個percall）即函數運行一次的平均時間，等於 cumtime/ncalls；
filename:lineno(function)：每個函數調用的具體信息；
需要注意的是cProfile很難搞清楚函數內的每一行發生了什么，是針對整個函數來說的。

-o profile.stats

我們可與你通過這個函數將結果輸出到一個文件中，當然文件的后綴名是任意的，這里為了方便后面配合python中使用所以將后綴定為stats。
首先讓我們運行下面的命令

python3 -m cProfile -o loopdemo_profile.stats loopdemo.py

然后運行下面的腳本

import pstats
p=pstats.Stats("loopdemo_profile.stats")
p.sort_stats("cumulative")
p.print_stats()
p.print_callers()  # 可以顯示函數被哪些函數調用
p.print_callees()  # 可以顯示哪個函數調用了哪些函數

可以看到輸出了和之前控制台一樣的結果

         2006 function calls in 0.005 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.005    0.005 {built-in method builtins.exec}
        1    0.000    0.000    0.005    0.005 loopdemo.py:7(<module>)
     1001    0.004    0.000    0.004    0.000 {built-in method builtins.print}
     1002    0.000    0.000    0.000    0.000 loopdemo.py:30(foo2)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

   Ordered by: cumulative time

Function                                          was called by...
                                                      ncalls  tottime  cumtime
{built-in method builtins.exec}                   <- 
loopdemo.py:7(<module>)                           <-       1    0.000    0.005  {built-in method builtins.exec}
{built-in method builtins.print}                  <-    1001    0.004    0.004  loopdemo.py:7(<module>)
loopdemo.py:30(foo2)                              <-    1002    0.000    0.000  loopdemo.py:7(<module>)
{method 'disable' of '_lsprof.Profiler' objects}  <- 


   Ordered by: cumulative time

Function                                          called...
                                                      ncalls  tottime  cumtime
{built-in method builtins.exec}                   ->       1    0.000    0.005  loopdemo.py:7(<module>)
loopdemo.py:7(<module>)                           ->    1002    0.000    0.000  loopdemo.py:30(foo2)
                                                        1001    0.004    0.004  {built-in method builtins.print}
{built-in method builtins.print}                  -> 
loopdemo.py:30(foo2)                              -> 
{method 'disable' of '_lsprof.Profiler' objects}  -> 

line_profiler

安裝

pip3 install Cpython
pip3 install Cython git+https://github.com/rkern/line_profiler.git