[Python] 用 cProfile+gprof2dot 將 profiling 結果視覺化

[Python] 用 cProfile+gprof2dot 將 profiling 結果視覺化

專案裡有隻 python 程式,因為它常常被呼叫到,

可是它執行所花費的時間似乎有點久,比我們預期的要長…

因此今天的任務就是找出程式執行時間的瓶頸 (profiling),來加以改善~

 

查了一下,大部分人在 python 的 profiling 都是使用 profile/cProfile 這個內建的套件,

再加上 gprof2dot 來轉成視覺化的圖,

試用了一下這方法,感覺相當不錯,

就以下面這個簡短的 python 程式來試驗一下吧:

import os
import sys
def process(filename):
print filename
for (dirpath, dirnames, filenames) in os.walk(sys.argv[1]):
for filename in filenames:
process(filename)

 

1. 使用 cProfile 套件量測程式執行的時間

最簡單的用法,就是直接執行 cProfile 套件,

-o 參數指定要輸出的量測資料檔,後面再加上要被執行的 python 程式與參數~

例如下面的範例是指定輸出量測檔為 profile.pstats,

實際要執行的程式與參數是 test.py /usr:

python -m cProfile -o profile.pstats test.py /usr

 

執行完之後,會產生一個 profile.pstats 檔案。

如果想檢視這個檔案的內容,可以用 pstats 這個模組,例如:

python -m pstats profile.pstats

 

這樣子會進入 pstats 模組的交談式畫面,鍵入 ? 可以看到可用的指令:

profile.pstats% ?
Documented commands (type help <topic>):
========================================
EOF  add  callees  callers  help  quit  read  reverse  sort  stats  strip

 

可以用 sort 設定排序欄位,不加參數的話會秀出可以用的欄位:

profile.pstats% sort
Valid sort keys (unique prefixes are accepted):
cumulative -- cumulative time
module -- file name
ncalls -- call count
pcalls -- primitive call count
file -- file name
line -- line number
name -- function name
calls -- call count
stdname -- standard name
nfl -- name/file/line
filename -- file name
cumtime -- cumulative time
time -- internal time
tottime -- internal time

 

像我想看累計的時間,就用 sort cumtime 就行了~

接著執行 stats 就可以秀出統計資料,依照剛剛設定的欄位作排序:

profile.pstats% stats
Fri Aug 19 00:02:43 2016    profile.pstats
140349 function calls (120514 primitive calls) in 0.656 seconds
Ordered by: cumulative time
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
1    0.016    0.016    0.656    0.656 test.py:1(<module>)
22277/2442    0.071    0.000    0.483    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/os.py:209(walk)
8781    0.156    0.000    0.156    0.000 test.py:5(process)
2441    0.148    0.000    0.148    0.000 {posix.listdir}
11221    0.025    0.000    0.147    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/genericpath.py:46(isdir)
11221    0.106    0.000    0.106    0.000 {posix.stat}
13661    0.045    0.000    0.071    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/posixpath.py:61(join)
2440    0.008    0.000    0.042    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/posixpath.py:132(islink)
2440    0.030    0.000    0.030    0.000 {posix.lstat}
13661    0.017    0.000    0.017    0.000 {method 'startswith' of 'str' objects}
11221    0.010    0.000    0.016    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/stat.py:40(S_ISDIR)
13661    0.009    0.000    0.009    0.000 {method 'endswith' of 'str' objects}
13661    0.007    0.000    0.007    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/stat.py:24(S_IFMT)
2440    0.003    0.000    0.005    0.000 /usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/stat.py:55(S_ISLNK)
11221    0.005    0.000    0.005    0.000 {method 'append' of 'list' objects}
1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

 

2. 將量測得到的 pstats 檔案轉成圖檔 

們可以用 gprof2dot 先將剛剛得到的 pstats 檔案,轉成 dot 格式。

dot 是一種純文字檔,裡面會描述各個節點間的關係~

先用 pip 來安裝 gprof2dot:

pip install gprof2dot

 

接著就可以執行 gprof2dot 模組,

用 -f 參數指定我們的輸入檔是 pstats 格式,最後放我們的輸入檔案:

python -m gprof2dot -f pstats profile.pstats

 

直接執行的話,就可以看到輸出為 dot 格式的文字,例如:

digraph {
graph [fontname=Arial, nodesep=0.125, ranksep=0.25];
node [fontcolor=white, fontname=Arial, height=0, shape=box, style=filled, width=0];
edge [fontname=Arial];
0 [color="#0d1074", fontcolor="#ffffff", fontsize="10.00", label="~:0:<method 'append' of 'list' objects>\n0.70%\n(0.70%)\n11221×", tooltip="~"];
1 [color="#cdd806", fontcolor="#ffffff", fontsize="10.00", label="os:209:walk\n73.71%\n(10.80%)\n22277×", tooltip="/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/os.py"];
1 -> 0 [arrowsize="0.35", color="#0d1074", fontcolor="#0d1074", fontsize="10.00", label="0.70%\n11221×", labeldistance="0.50", penwidth="0.50"];
1 -> 1 [arrowsize="0.86", color="#c7d706", fontcolor="#c7d706", fontsize="10.00", label="73.14%\n2454×", labeldistance="2.93", penwidth="2.93"];
1 -> 3 [arrowsize="0.47", color="#0c8290", fontcolor="#0c8290", fontsize="10.00", label="22.38%\n11221×", labeldistance="0.90", penwidth="0.90"];
}

 

不過我們通常不需要看到 dot 資料的內容,

只需要將這 dot 資料送給 GraphViz 內帶的 dot 程式,

就能幫我們將 dot 資料轉成真正的圖檔了 (如 PNG)~

 

先將 GraphViz 安裝起來~在 Mac 上可以用 Homebrew:

brew install graphviz

 

在 CentOS 上的話,可以用 yum 來安裝:

sudo yum install graphviz

 

安裝好之後,就可以將剛剛的 dot 輸出直接導給 dot 程式,

如下例是用 -T png 指定輸出為 PNG 圖檔,-o 指定輸出檔案為 profile.png:

python -m gprof2dot -f pstats profile.pstats | dot -T png -o profile.png

 

產生出來的 profile.png 看起來像下面這樣:

profile

 

由上面這張圖,就可以觀察整個程式裡比較花時間的一些地方,

進而可以從最花時間的部分開始改善。

當改善程式之後,可以重覆上面的步驟,檢查下一個耗時的地方~

基本上這個改善速度的流程是不會有完美的時候 (總是希望執行時間越短越好),

不過持續改善下去,就會遇到改善幅度降低+難度變高的問題,

因此也要先決定好停損點,才不會無止盡的改善下去囉~

 

參考資料:

Profiling in Python: Who called the function?

How can you get the call tree with python profilers?

 

(本頁面已被瀏覽過 1,212 次)

2 thoughts on “[Python] 用 cProfile+gprof2dot 將 profiling 結果視覺化

  1. 嘗試在 brew cask install graphviz 這一步的時候有 Error: Cask ‘graphviz’ is unavailable: No Cask with this name exists.
    直接 brew install graphviz 就可以了。
    這篇寫得真好,跟著做就達到預期效果了,謝謝你

發佈留言

發佈留言必須填寫的電子郵件地址不會公開。

這個網站採用 Akismet 服務減少垃圾留言。進一步瞭解 Akismet 如何處理網站訪客的留言資料