[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 看起來像下面這樣：
由上面這張圖，就可以觀察整個程式裡比較花時間的一些地方，
進而可以從最花時間的部分開始改善。
當改善程式之後，可以重覆上面的步驟，檢查下一個耗時的地方～
基本上這個改善速度的流程是不會有完美的時候 (總是希望執行時間越短越好)，
不過持續改善下去，就會遇到改善幅度降低+難度變高的問題，
因此也要先決定好停損點，才不會無止盡的改善下去囉～
參考資料：
Profiling in Python: Who called the function?
How can you get the call tree with python profilers?
2 thoughts on “[Python] 用 cProfile+gprof2dot 將 profiling 結果視覺化”
嘗試在 brew cask install graphviz 這一步的時候有 Error: Cask ‘graphviz’ is unavailable: No Cask with this name exists.
直接 brew install graphviz 就可以了。
這篇寫得真好，跟著做就達到預期效果了，謝謝你
謝謝您，我把 brew install 的指令修正了~^^