昨天剛學到用 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 都不會顯示出來:

profile  

 

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

因為有時候就是想知道為什麼這根 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 檔的量測結果視覺化如下:

profile  

 

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

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

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

profile  

 

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

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

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

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

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

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

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

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

 

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

 

文章標籤
創作者介紹

亂打一通的心情日記

ephrain 發表在 痞客邦 PIXNET 留言(0) 人氣()