昨天剛學到用 cProfile+gprof2dot 將 profiling 結果視覺化，

不過 cProfile 有個問題：它預設只能處理單一執行緒 (thread)，

因此如果程式會產生新的 thread 的話，

新的 thread 做的事情通常不會顯示在 profiling 結果裡面…

找了一下，有個叫做 yappi 的 python 模組可以支援 multi-thread 的 profiling，

真的是很方便，來看一下用法吧～

1. 觀察 cProfile 對 multi-thread 程式的輸出

我將 用 cProfile+gprof2dot 將 profiling 結果視覺化 那篇裡的 python 程式改了一下，

讓它產生 multi-thread 來跑：

import os
import sys
import threading
import time
def _thread_func1(filename):
time.sleep(1)
print filename
def _thread_func2(filename):
time.sleep(2)
print filename
def _thread_func3(filename):
time.sleep(3)
print filename
def process(filename):
t = threading.Thread(target=eval("_thread_func%d" % (ord(filename[0])%3+1)), args=(filename,))
t.start()
return t
thread_list = []
for (dirpath, dirnames, filenames) in os.walk(sys.argv[1]):
for filename in filenames:
thread_list.append(process(filename))
for t in thread_list:
t.join()

執行時間的視覺化是像下面這樣，

可以看到 process() 呼叫 threading.start() 之後，

被新的執行緒執行的 _thread_func1,2,3 都不會顯示出來：

執行緒所執行的函式沒有被顯示出來，會導致分析上的困難，

因為有時候就是想知道為什麼這根 thread 要跑這麼久…

2. 引入 yappi 來測量 multi-thread 程式的執行時間

首先用 pip 安裝 yappi：

pip install yappi

跟 cProfile 有一點不同，

cProfile 允許我們用像 python -m cProfile 的方式，直接執行要測量的 python 程式，

但用 python -m yappi 的話，沒辦法輸出 pstats 檔案，

只會直接在 stdout 上顯示統計資料 (yappi 0.94 版的測試結果)…

因此想要畫出視覺化的圖的話，得在程式裡直接呼叫 yappi 的 API，才能產生 pstats 檔案～

我們在剛剛的程式裡，加上了 import yappi，

接著在主程式執行前呼叫 yappi.start()，

在主程式結束前呼叫 yappi.get_func_stats() 產生一個 stats 物件，

接著可以用 stats.save() 將量測資料輸出成一個 pstats 檔案：

import os
import sys
import threading
import time
import yappi
def _thread_func1(filename):
time.sleep(1)
print filename
def _thread_func2(filename):
time.sleep(2)
print filename
def _thread_func3(filename):
time.sleep(3)
print filename
def process(filename):
t = threading.Thread(target=eval("_thread_func%d" % (ord(filename[0])%3+1)), args=(filename,))
t.start()
return t
yappi.start(builtins=False)
thread_list = []
for (dirpath, dirnames, filenames) in os.walk(sys.argv[1]):
for filename in filenames:
thread_list.append(process(filename))
for t in thread_list:
t.join()
stats = yappi.get_func_stats()
stats.save("profile.pstats", type="pstat")

接著直接執行修改後的程式，就會產生 profile.pstats 檔案，

照著 用 cProfile+gprof2dot 將 profiling 結果視覺化 裡的步驟，

我們可以將 pstats 檔的量測結果視覺化如下：

很明顯的結果和 cProfile 的不一樣，不過因為項目很多，圖在網誌上縮太小了，

我這邊截取出跟執行緒相關的部分，可以看到 _thread_func1,2,3 等等函式有被記錄到，

因此就可以量測到執行緒的執行時間，自然就有最佳化的起始點了：

不過用 yappi 量測執行緒有一點要注意的是，

量測出來的時間並不代表最終程式執行的時間，因為這和執行緒怎麼使用有關係～

舉例來說，像我們的範例程式是啟動多個 thread，但每個 thread 可以算是幾乎同時跑，

因此最終程式執行的時間，差不多是執行最慢的那根 thread 所花費的時間，

而不是所有 thread 執行時間的總和～

但這件事情在 yappi 的圖上是分不出來的，

你還是得自己根據程式的原始碼，搭配 yappi 的輸出圖來做判讀，

決定哪些地方是真正應該需要最佳化的點囉～

參考資料：Python Performance Profiling: The Guts And The Glory