這裡介紹如何使用 cProfile 測量 Python 程式效能、找出效能瓶頸,並以 gprof2dot 產生視覺化分析圖表。

較為大型的計算程式在開發完成後,通常都會接續著進行程式的執行效能測量與分析(profiling),找出程式的瓶頸所在,針對少數關鍵的程式碼進一步做最佳化,改善整體程式的執行速度。


在 Python 中若要進行程式效能分析,有好幾種方式可以使用(請參考 Python 官方手冊),而對於一般的使用者而言,最適合的方式就是使用 cProfile 模組,以下是使用方式與實際範例。

Python 範例程式

以下是一個簡單的 Python 程式 pi.py,此程式的目的是以蒙地卡羅方法計算 Pi 的近似值:

from __future__ import division
import random

# 模擬次數 
NB_POINTS = 10**7

# 判斷點是否落於單位圓內
def in_circle(x, y):
  return x**2 + y**2 < 1

# 計算 Pi 近似值
def compute_pi(nb_it):
  inside_count = sum(1 for _ in range(nb_it) if in_circle(random.random(),random.random()))
  return (inside_count / nb_it) * 4

if __name__ == "__main__":
  print(compute_pi(NB_POINTS))

接下來我們將示範如何以 cProfile 來測量這個程式的執行狀況。

cProfile 分析程式執行狀況

若要測量一個獨立的程式,最直接又簡單的方式就是在執行時引入 cProfile 模組:

python3 -m cProfile -s cumtime pi.py

在使用 -m 引入 cProfile 模組之後,再加上 -s 參數指定排序欄位,這裡我們以累計執行時間來排序(cumtime),執行後就會輸出類似這樣的量測報表:

         37857794 function calls (37857773 primitive calls) in 12.203 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      4/1    0.000    0.000   12.203   12.203 {built-in method exec}
        1    0.000    0.000   12.203   12.203 pi.py:1(<module>)
        1    0.000    0.000   12.193   12.193 pi.py:12(compute_pi)
        1    0.873    0.873   12.193   12.193 {built-in method sum}
  7855933    6.159    0.000   11.320    0.000 pi.py:13(<genexpr>)
 10000000    3.942    0.000    3.942    0.000 pi.py:8(in_circle)
 20000000    1.219    0.000    1.219    0.000 {method 'random' of '_random.Random' objects}
      6/2    0.000    0.000    0.010    0.005 <frozen importlib._bootstrap>:2234(_find_and_load)
[略]

這個報表的欄位意義如下:

欄位意義
ncalls呼叫次數(number of calls)。
tottime總執行時間(total time),不含子函數的執行時間。
percalltottime 除以 ncalls
cumtime累計執行時間(cumulative time),包含子函數的執行時間。
percallcumtime 除以 ncalls
filename:lineno(function)函數名稱。

測試程式碼片段

如果只是要在 Python 程式中測試幾行程式的執行效能,可以使用 cProfile.run 執行要測量的程式碼:

from __future__ import division
import random

# 引入 cProfile 模組
import cProfile

NB_POINTS = 10**7

def in_circle(x, y):
  return x**2 + y**2 < 1

def compute_pi(nb_it):
  inside_count = sum(1 for _ in range(nb_it) if in_circle(random.random(),random.random()))
  return (inside_count / nb_it) * 4

if __name__ == "__main__":
  # 測試程式碼片段
  cProfile.run('compute_pi(NB_POINTS)')

這樣就會輸出程式碼片段的測量結果:

         37853493 function calls in 12.514 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   12.514   12.514 <string>:1(<module>)
        1    0.000    0.000   12.514   12.514 pi.py:12(compute_pi)
  7853488    6.341    0.000   11.590    0.000 pi.py:13(<genexpr>)
 10000000    3.983    0.000    3.983    0.000 pi.py:9(in_circle)
        1    0.000    0.000   12.514   12.514 {built-in method exec}
        1    0.924    0.924   12.514   12.514 {built-in method sum}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
 20000000    1.265    0.000    1.265    0.000 {method 'random' of '_random.Random' objects}

cProfile 結果輸出至檔案

由於 cProfile 的報表非常長,若是較為複雜的程式,我們會把這些資料以輸出至檔案:

python3 -m cProfile -o pi.pstats pi.py

-o 參數可以指定輸出的檔案名稱,其輸出的檔案格式是二進位檔,若要觀看這個檔案,可以使用 Python 的 pstats 模組:

python3 -m pstats pi.pstats

進入 pstats 模組的互動式環境後,可用各種指令來整理與查看報表,鍵入問號 ? 可以看到可用的指令。最常用的指令就使用 sort 設定排序欄位:

sort cumtime

接著再用 stats 輸出報表:

stats

其輸出的報表就跟上面的類似。

Fri Dec 15 14:00:51 2017    pi.pstats

         37858722 function calls (37858701 primitive calls) in 12.282 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      4/1    0.000    0.000   12.282   12.282 {built-in method exec}
        1    0.000    0.000   12.282   12.282 pi.py:1(<module>)
        1    0.000    0.000   12.272   12.272 pi.py:12(compute_pi)
        1    0.886    0.886   12.272   12.272 {built-in method sum}
  7856861    6.190    0.000   11.386    0.000 pi.py:13(<genexpr>)
 10000000    3.967    0.000    3.967    0.000 pi.py:8(in_circle)
 20000000    1.229    0.000    1.229    0.000 {method 'random' of '_random.Random' objects}
 [略]

以 gprof2dot 產生視覺化圖形

若程式架構很複雜,光看簡單的文字報表可能會很難分析,這時候我們可以使用 gprof2dot 這個小工具,把 pstats 的資料轉為 dot 的格式,再將 dot 資料畫成圖形,以視覺化的方式呈現程式中各個函數之間的執行關係。

首先安裝 gprof2dot 這個 Python 模組:

sudo pip3 install gprof2dot

若要畫圖的話,也要安裝 graphviz

# Ubuntu Linux
sudo apt-get install graphviz
# CentOS Linux
sudo yum install graphviz

安裝好必要的工具之後,就可以將剛剛產生的 pi.pstats 轉為 dot 資料,直接畫出圖形來:

python3 -m gprof2dot -f pstats pi.pstats | dot -T png -o pi_profile.png

畫出來的圖會像這樣:

cProfile 測量結果

上面這個計算 Pi 的範例因為比較單純,所以程式的流程圖畫出來比較陽春,感覺不出他有多好用,但若是換成實際的範例就會差很多。

下面這張圖是我實際正在處理的 AI 分析程式,中間牽涉到影像的處理、還有使用到 Keras 以 GPU 來計算,靠這種圖來抓出程式的瓶頸會比文字報表方便很多。

cProfile 測量結果

參考資料:EPHRAIN子風的知識庫PyMOTW