本文最初發表于戀花蝶的部落格http://blog.csdn.net/lanphaday，歡迎轉載，但請務必保留原文完整，并保留本聲明。
[python] 用profile協助程式性能優化 上帝說：“選擇了腳本，就不要考慮性能。”我是很支援這句話的，使用腳本要的就是開發速度、良好的擴充性以及可維護性。可惜到了最後，我們的程式難免會運作得太慢，我們的客戶不能忍受，這時候，我們就不得不考慮對代碼的性能進行優化了。 程式運作慢的原因有很多，比如存在太多的劣化代碼（如在程式中存在大量的“.”操作符），但真正的原因往往是比較是一兩段設計并不那麼良好的不起眼的程式，比如對一序列元素進行自定義的類型轉換等。因為程式性能影響是符合80／20法則的，即20%的代碼的運作時間占用了80%的總運作時間（實際上，比例要誇張的多，通常是幾十行代碼占用了95%以上的運作時間），靠經驗就很難找出造成性能瓶頸的代碼了。這時候，我們需要一個工具——profile！最近我手上的項目也在一些關鍵的地方遇到了性能問題，那時已經接近項目完工日期，幸好因為平時的代碼子產品化程度比較高，是以通過profile分析相關的獨立子產品，基本上解決了性能問題。通過這件事，讓我下決心寫一篇關于profile的文章，分享一下profile的使用心得。 初識profile profile是python的标準庫。可以統計程式裡每一個函數的運作時間，并且提供了多樣化的報表。使用profile來分析一個程式很簡單，舉例說如果有一個程式如下：
| def foo(): sum = 0 for i in range(100): sum += i return sum if __name__ == "__main__": foo() |
現在要用profile分析這個程式，很簡單，把if程式塊改為如下：
| if __name__ == "__main__": import profile profile.run("foo()") |
我們僅僅是import了profile這個子產品，然後以程式的入口函數名為參數調用了profile.run這個函數，程式運作的輸出如下：
| 5 function calls in 0.143 CPU seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.000 0.000 :0(range) 1 0.143 0.143 0.143 0.143 :0(setprofile) 1 0.000 0.000 0.000 0.000 <string>:1(?) 1 0.000 0.000 0.000 0.000 prof1.py:1(foo) 1 0.000 0.000 0.143 0.143 profile:0(foo()) 0 0.000 0.000 profile:0(profiler) |
上圖顯示了prof1.py裡函數調用的情況，根據圖表我們可以清楚地看到foo()函數占用了100%的運作時間，foo()函數是這個程式裡名至實歸的熱點。 除了用這種方式，profile還可以直接用python解釋器調用profile子產品來剖分py程式，如在指令行界面輸入如下指令：
|
産生的輸出跟直接修改腳本調用profile.run()函數有一樣的功效。 profile的統計結果分為ncalls, tottime, percall, cumtime, percall, filename:lineno(function)等若幹列：
| ncalls | 函數的被調用次數 |
| tottime | 函數總計運作時間，除去函數中調用的函數運作時間 |
| percall | 函數運作一次的平均時間，等于 tottime/ncalls |
| cumtime | 函數總計運作時間，含調用的函數運作時間 |
| percall | 函數運作一次的平均時間，等于 cumtime/ncalls |
| filename:lineno(function) | 函數所在的檔案名，函數的行号，函數名 |
通常情況下，profile的輸出都直接輸出到指令行，而且預設是按照檔案名排序輸出的。這就給我們造成了障礙，我們有時候希望能夠把輸出儲存到檔案，并且能夠以各種形式來檢視結果。profile簡單地支援了一些需求，我們可以在profile.run()函數裡再提供一個實參，就是儲存輸出的檔案名；同樣的，在指令行參數裡，我們也可以加多一個參數，用來儲存profile的輸出。 用pstats自定義報表 profile解決了我們的一個需求，還有一個需求：以多種形式檢視輸出，我們可以通過profile的另一個類Stats來解決。在這裡我們需要引入一個子產品pstats，它定義了一個類Stats，Stats的構造函數接受一個參數——就是profile的輸出檔案的檔案名。Stats提供了對profile輸出結果進行排序、輸出控制等功能，如我們把前文的程式改為如下：
| # … 略 if __name__ == "__main__": import profile profile.run("foo()", "prof.txt") import pstats p = pstats.Stats("prof.txt") p.sort_stats("time").print_stats() |
引入pstats之後，将profile的輸出按函數占用的時間排序，輸出如下：
| Sun Jan 14 00:03:12 2007 prof.txt 5 function calls in 0.002 CPU seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 1 0.002 0.002 0.002 0.002 :0(setprofile) 1 0.000 0.000 0.002 0.002 profile:0(foo()) 1 0.000 0.000 0.000 0.000 G:/prof1.py:1(foo) 1 0.000 0.000 0.000 0.000 <string>:1(?) 1 0.000 0.000 0.000 0.000 :0(range) 0 0.000 0.000 profile:0(profiler) |
Stats有若幹個函數，這些函數組合能給我們輸出不同的profile報表，功能非常強大。下面簡單地介紹一下這些函數：
| strip_dirs() | 用以除去檔案名前名的路徑資訊。 |
| add(filename,[…]) | 把 profile 的輸出檔案加入 Stats 執行個體中統計 |
| dump_stats(filename) | 把 Stats 的統計結果儲存到檔案 |
| sort_stats(key,[…]) | 最重要的一個函數，用以排序 profile 的輸出 |
| reverse_order() | 把 Stats 執行個體裡的資料反序重排 |
| print_stats([restriction,…]) | 把 Stats 報表輸出到 stdout |
| print_callers([restriction,…]) | 輸出調用了指定的函數的函數的相關資訊 |
| print_callees([restriction,…]) | 輸出指定的函數調用過的函數的相關資訊 |
這裡最重要的函數就是sort_stats和print_stats，通過這兩個函數我們幾乎可以用适當的形式浏覽所有的資訊了，下面來詳細介紹一下。 sort_stats()接受一個或者多個字元串參數，如”time”、”name”等，表明要根據哪一列來排序，這相當有用，例如我們可以通過用time為key來排序得知最消耗時間的函數，也可以通過cumtime來排序，獲知總消耗時間最多的函數，這樣我們優化的時候就有了針對性，也就事半功倍了。sort_stats可接受的參數如下：
| ‘ncalls’ | 被調用次數 |
| ‘cumulative’ | 函數運作的總時間 |
| ‘file’ | 檔案名 |
| ‘module’ | 檔案名 |
| ‘pcalls’ | 簡單調用統計（相容舊版，未統計遞歸調用） |
| ‘line’ | 行号 |
| ‘name’ | 函數名 |
| ‘nfl’ | Name/file/line |
| ‘stdname’ | 标準函數名 |
| ‘time’ | 函數内部運作時間（不計調用子函數的時間） |
另一個相當重要的函數就是print_stats——用以根據最後一次調用sort_stats之後得到的報表。print_stats有多個可選參數，用以篩選輸出的資料；print_stats的參數可以是數字也可以是perl風格的正規表達式，相關的内容通過其它管道了解，這裡就不詳述啦，僅舉三個例子： print_stats(“.1”, “foo:”) 這個語句表示将stats裡的内容取前面的10%，然後再将包含”foo:”這個字元串的結果輸出。 print_stats(“foo:”,”.1”) 這個語句表示将stats裡的包含”foo:”字元串的内容的前10%輸出。 print_stats(10) 這個語句表示将stats裡前10條資料輸出。 實際上，profile輸出結果的時候相當于這樣調用了Stats的函數：
p.strip_dirs().sort_stats(-1).print_stats() 其中sort_stats函數的參數是-1，這也是為了與舊版本相容而保留的。sort_stats可以接受-1,0,1,2之一，這四個數分别對應”stdname”, “calls”, “time”和”cumulative”；但如果你使用了數字為參數，那麼pstats隻按照第一個參數進行排序，其它參數将被忽略。 hotshot——更好的profile 因為profile本身的機制（如使用精确到毫秒的計時器等）導緻在相當多情況下profile子產品的“測不準”問題相當嚴重。hotshot大部分都是用C實作的，相對于profile子產品它的計時函數對性能剖分的影響就小得多，而且支援以行為機關統計運作時間。美中不足的是hotshot不支援多線程的程式，确切來說，是它的計時核心有個關于臨界段的bug；更加不幸的是，hotshot已經不再被維護，而且可能在未來的python版本中會從标準庫中移除。不過，對于沒有使用多線程的程式而言，hotshot目前仍然是非常好的剖分器。 hotshot有一個Profile類，它的構造函數原型如下： class Profile( logfile[, lineevents[, linetimings]]) logfile參數是儲存剖分統計結果的檔案名，lineevents表示是否統計每一行源碼的運作時間，預設為0，即以函數執行時間為統計粒度，linetimings為是否記錄時間資訊，預設為1。下面仍然是示例：
| # … 略 if __name__ == "__main__": import hotshot import hotshot.stats prof = hotshot.Profile("hs_prof.txt", 1) prof.runcall(foo) prof.close() p = hotshot.stats.load("hs_prof.txt") p.print_stats() |
輸出：
| 1 function calls in 0.003 CPU seconds Random listing order was used ncalls tottime percall cumtime percall filename:lineno(function) 1 0.003 0.003 0.003 0.003 i:/prof1.py:1(foo) 0 0.000 0.000 profile:0(profiler) |
我們可以看到來自hotshot的幹擾資訊比profile的少了很多，這也有利于我們分析資料找出熱點。不過正如我在前面代碼中使用 prof = hotshot.Profile("hs_prof.txt", 1)一樣，我發現使lineevents=1跟忽略linveevents參數沒有什麼不同，還請大家賜教。 使用hotshot能夠更加靈活地統計程式的運作情況，因為hotshot.Profile提供了下面一系列的函數：
| run(cmd) | 執行一段腳本，跟 profile 子產品的 run() 函數一樣功能 |
| runcall(func, *args, **keywords) | 調用一個函數，并統計相關的運作資訊 |
| runctx(cmd, globals, locals) | 指定一段腳本的執行環境，執行腳本并統計運作資訊 |
通過這幾個函數，我們可以非常友善地建立測試的樁子產品，不必再像使用profile那樣手工地編寫很多驅動子產品了。hotshot.Profile還提供其它有用的函數，具體請參考相關的manual。 Python 2.5注意事項 因為hotshot不能用于多線程，而且它的優勢僅在速度，是以python 2.5版本聲明不再維護hotshot子產品，并且可能在以後的版本中移除它。有去必有來，取而代之的就是cProfile，與cPickle等子產品類似，cProfile要比profile子產品更快些。cProfile的接口跟profile是一樣的，隻要在使用到profile的地方用cProfile替換就可以在以前的項目中使用它。 pstats在python 2.5版本中也産生了一些微妙的變化，pstats.Stats的構造函數增加了一個預設參數，變為： class Stats( filename[, stream=sys.stdout[, ...]]) 對我們而言，這是沒有壞處的，stream參數給了我們把profile統計報表儲存到檔案的機會，這正是我們需要的。 綜上所述，如果你使用的python 2.5版，我建議你使用cProfile。 小巧實用的瑞士軍刀——timeit 如果我們某天心血來潮，想要向list裡append一個元素需要多少時間或者想知道抛出一個異常要多少時間，那使用profile就好像用牛刀殺雞了。這時候我們更好的選擇是timeit子產品。 timeit除了有非常友好的程式設計接口，也同樣提供了友好的指令行接口。首先來看看程式設計接口。timeit子產品包含一個類Timer，它的構造函數是這樣的： class Timer( [stmt='pass' [, setup='pass' [, timer=<timer function>]]]) stmt參數是字元串形式的一個代碼段，這個代碼段将被評測運作時間；setup參數用以設定stmt的運作環境；timer可以由使用者使用自定義精度的計時函數。 timeit.Timer有三個成員函數，下面簡單介紹一下： timeit( [number=1000000]) timeit()執行一次Timer構造函數中的setup語句之後，就重複執行number次stmt語句，然後傳回總計運作消耗的時間。 repeat( [repeat=3 [, number=1000000]]) repeat()函數以number為參數調用timeit函數repeat次，并傳回總計運作消耗的時間 print_exc( [file=None]) print_exc()函數用以代替标準的tracback，原因在于print_exc()會輸出錯行的源代碼，如：
| >>> t = timeit.Timer("t = foo()/nprint t") ß 被 timeit 的代碼段 >>> t.timeit() Traceback (most recent call last): File "<pyshell#12>", line 1, in -toplevel- t.timeit() File "E:/Python23/lib/timeit.py", line 158, in timeit return self.inner(it, self.timer) File "<timeit-src>", line 6, in inner foo() ß 标準輸出是這樣的 NameError: global name 'foo' is not defined >>> try: t.timeit() except: t.print_exc() Traceback (most recent call last): File "<pyshell#17>", line 2, in ? File "E:/Python23/lib/timeit.py", line 158, in timeit return self.inner(it, self.timer) File "<timeit-src>", line 6, in inner t = foo() ß print_exc() 的輸出是這樣的，友善定位錯誤 NameError: global name 'foo' is not defined |
除了可以使用timeit的程式設計接口外，我們也可以在指令行裡使用timeit，非常友善： python timeit.py [-n N] [-r N] [-s S] [-t] [-c] [-h] [statement ...] 其中參數的定義如下： -n N/--number=N statement語句執行的次數 -r N/--repeat=N 重複多少次調用timeit()，預設為3 -s S/--setup=S 用以設定statement執行環境的語句，預設為”pass” -t/--time 計時函數，除了Windows平台外預設使用time.time()函數， -c/--clock 計時函數，Windows平台預設使用time.clock()函數 -v/--verbose 輸出更大精度的計時數值 -h/--help 簡單的使用幫助 小巧實用的timeit蘊藏了無限的潛能等待你去發掘，我在這裡就不提供執行個體啦～～ 後記 原本我隻打算寫寫profile的使用及自己應用的一些心得的，但仔細閱讀了相關的manual之後發現實用的東西很多很多，是以就羅羅嗦嗦地寫了這麼多，自己的應用經驗和心得隻好容後再述了。在寫這篇介紹的時候，我想起自己以前寫過的一個A*算法的python實作，沒有進行過任何優化，是以打算以它為執行個體，以後抽空寫上一篇有比較實用的例子貫穿全文的文檔吧。 本文撰寫的時候參考了python 2.3/2.4/2.5版本的manual，文中介紹的内容大部分适用于python 2.3或以上的版本，其中cProfile需要2.5版本才能支援。
![TestLink導出用例轉換工具(XML2Excel)[圖]](data:image/gif;base64,R0lGODlhAQABAIAAAP///wAAACwAAAAAAQABAAACAkQBADs=)