如何對你的Python代碼進行基准測試

啥叫做基准測試(benchmark)代碼?其實主要就是測試(benchmarking)和分析(profiling)你的代碼執行多快，並且找到代碼瓶頸(bottlenecks)在哪里。 執行該動作的主要的目的就是優化(optimization)。也許因為業務需要你並且讓你的代碼執行更快一些。 當面臨這種情況時，你就需要找出你的代碼是在哪些部分慢的。

本文覆蓋如何使用不同工具進行代碼測試。

timeit

Python再帶一個模塊timeit。你可以使用它來對小代碼進行計時。timeit模塊使用針對平台的時間函數，你可以得到非常准確的一個時間結果。

timeit模塊有個命令行接口，也可以通過導入的方式。我們將從命令行中使用開始。打開終端執行如下命令：

$ python3 -m timeit -s "[ord(x) for x in 'abcdfghi']" 100000000 loops, best of 3: 0.00907 usec per loop $ python3 -m timeit -s "[chr(int(x)) for x in '123456789']" 100000000 loops, best of 3: 0.00897 usec per loop 

發生啥啦？好吧，當你執行Python命令並且傳遞-m參數時，你是在告訴解釋器去找該模塊並且作為主要程序執行。 -s告知timeit模塊執行一次代碼。然后timeit就行執行代碼三次，並且返回該三次的平均結果。該例子太過減少，它們 之間的區別可能不太明顯。

你的機器上運行的結果可能跟我的會有一些偏差。

我們再寫個簡單函數，看看是否可以從命令行測試

# simple_func.py def my_function(): try: 1 / 0 except ZeroDivisionError: pass 

整個函數的功能就是拋出一個異常然后直接忽略。很爛的例子。要通過命令使用timeit來測試，我們需要在命令空間中導入它，確保工作目錄在當前文件目錄下，然后執行：

$ python3 -m timeit "import simple_func; simple_func.my_function()" 1000000 loops, best of 3: 0.753 usec per loop 

這里我們就導入該模塊並且直接my_function()函數。注意我們使用了;來分來導入和執行代碼。現在可以開始學習如何在Python腳本代碼內部使用timeit了。

導入timeit測試

在代碼中使用timeit模塊也是相當容易的。我們還是使用之前很爛的例子：

def my_function(): try: 1 / 0 except ZeroDivisionError: pass if __name__ == "__main__": import timeit setup = "from __main__ import my_function" print(timeit.timeit("my_function()", setup=setup)) 

我們執行通過執行該腳本來驗證。我們導入了timeit模塊，然后調用timeit函數，參數的setup字符串將導入要測試函數到timeit的作用域中。現在 我們實現自己的裝飾器測試函數。

使用裝飾器

實現自己的裝飾器計時函數是一件很有趣的事情，雖然不一定有timeit精確。

import random import time def timerfunc(func): """  A timer decorator  """ def function_timer(*args, **kwargs): """  A nested function for timing other functions  """ start = time.time() value = func(*args, **kwargs) end = time.time() runtime = end - start msg = "The runtime for {func} took {time} seconds to complete" print(msg.format(func=func.__name__, time=runtime)) return value return function_timer @timerfunc def long_runner(): for x in range(5): sleep_time = random.choice(range(1, 5)) time.sleep(sleep_time) if __name__ == "__main__": long_runner() 

該例子中，我們導入了Python標准庫的random和time模塊。然后我們創建了裝飾器函數。你將注意到它接收了一個函數以及 包含了另一函數。嵌套的函數在調用實際函數時將抓取時間，然后等待函數返回並抓取結束時間。現在我們知道函數所花費的時間，我們將它 打印出來。當然該裝飾器函數也需要將實際函數執行返回的結果返回回來。

接下來的函數就是包裝了該計時裝飾器函數。你可以看到這里使用了隨機休眠，該操作只是用來模擬耗時長程序。 也許你用來執行連接數據庫（或者較大查詢），跑線程或其他事情。

每次跑這段代碼，結果都會有些不同。自己試試！

創建計時上下文管理器

一些碼農可能更喜歡使用上下文的方式來測試小段代碼。我們來構建看看：

import random import time class MyTimer: def __init__(self): self.start = time.time() def __enter__(self): return self def __exit__(self, exc_type, exc_val, exc_tb): end = time.time() runtime = end - self.start msg = 'The function took {time} seconds to complete' print(msg.format(time=runtime)) def long_runner(): for x in range(5): sleep_time = random.choice(range(1, 5)) time.sleep(sleep_time) if __name__ == "__main__": with MyTimer(): long_runner() 

本例中，我們使用__init__方法來開始我們計時，__enter__方法不做任何事情，僅僅返回它自己。__exit__方法 中抓取了結束時間，計算了總執行時間並打印。

然后我們就使用上下文管理器來測試我們執行的代碼。

cProfile

Python內建了分析器。profile和cProfile模塊。profile模塊是純Python實現，在測試過程中可能會增加很多額外的開支。所以推薦還是使用更快的cProfile。

我們不會過細的講解該模塊，我們來看看一些例子。

>>> import cProfile >>> cProfile.run("[x for x in range(1500)]") 4 function calls in 0.000 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.000 0.000 <string>:1(<listcomp>) 1 0.000 0.000 0.000 0.000 <string>:1(<module>) 1 0.000 0.000 0.000 0.000 {built-in method exec} 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

我們來了解一下內容。第一行顯示了有4個函數調用。下一行告訴結果排序方式。根據文檔，standard name指的是最右邊的列。 這里我們有好多列數據：

• ncalls: 調用了多少次
• tottime: 函數所花費的總時間
• percall: ncalls / tottime
• cumtime: 涵蓋了該函數下的所有子函數（甚至地櫃）函數所話費的時間
• 第二個percall: cumtime / 原始釣魚那個
• filename: fileno (function) 每個函數響應信息

你也可以像timeit模塊一樣在命令行執行cProfile。主要的區別就是需要傳遞Python腳本而不是代碼作為參數。

python3 -m cProfile test.py

嘗試執行下該命令，看看執行結果。

line_profiler

有個第三方提供的項目叫line_profiler，它用來分析每行代碼執行時間。它也有一個叫做kenprof的腳本使用line_profiler來分析Python應用和腳本。只需使用pip來安裝該包。

 pip install line_profiler

在使用line_profiler之前我們需要一些代碼來分析。不過我向先告訴你命令行中如何調用line_profiler.實際上需要執行kernprof腳本來調用line_profiler。

 kernprof -l silly_functions.py 

執行完后將會打印出：Wrote profile results to silly_functions.py.lpro。該文件不能直接查看，是一個二進制文件。 當我們執行kernprof時，其實是在__builtins__命名空間中注入LineProfiler實例。該實例稱為profile，用來作為裝飾器函數。讓我們來寫實際腳本:

import time @profile def fast_function(): print("I'm fast function!") @profile def slow_function(): time.sleep(2) print("I'm slow function!") if __name__ == "__main__": fast_function() slow_function() 

現在我們擁有使用了profile裝飾的函數。如果你直接執行該腳本將會報NameError錯誤，因為並沒有定義profile。 所以記得再實際使用時移除@profile裝飾器函數。

我們來學習如果查看分析器的結果。有兩種辦法，第一使用line_profiler模塊讀結果文件：

$ python -m line_profiler silly_functions.py.lprof

還有種是在執行kernprof時帶上-v參數：

$ kernprof -l -v silly_functions.py

無論哪種辦法你都將得到如下結果：

I'm fast function! I'm slow function! Wrote profile results to silly_functions.py.lprof Timer unit: 1e-06 s Total time: 4e-05 s File: silly_functions.py Function: fast_function at line 3 Line # Hits Time Per Hit % Time Line Contents ============================================================== 3 @profile 4 def fast_function(): 5 1 40 40.0 100.0 print("I'm fast function!") Total time: 2.00227 s File: silly_functions.py Function: slow_function at line 7 Line # Hits Time Per Hit % Time Line Contents ============================================================== 7 @profile 8 def slow_function(): 9 1 2002114 2002114.0 100.0 time.sleep(2) 10 1 157 157.0 0.0 print("I'm slow function!") 

我們可以看到結果中顯示了每行代碼的執行時間相關信息。有6列內容。我們來看看每列代表的意思。

• Line#: 分析的代碼行數
• Hits: 執行次數
• Time: 該行代碼執行時間
• Per Hit: 每次執行時間
• % Time: 函數中所占時間比率
• Line Contents: 執行的代碼

如果你用IPython，你可能想知道IPython的魔術方法%lprun可以分析制定函數，甚至是具體代碼。

memory_profiler

另一個用來分析的第三方包叫做memory_profiler.它用來分析每行代碼在進程中所消耗的內存。我們也使用pip來安裝它。

pip install memory_profiler

裝好后，我們也需要代碼來評測。memory_prifiler執行方式和line_profiler非常相似，它將在__builtins__注入profiler裝飾器來測試函數。

@profile
def mem_func():
    lots_of_numbers = list(range(1500))
    x = ['letters'] * (5 ** 10)
    del lots_of_numbers
    return None

if __name__ == "__main__":
    mem_func()

本例中我們創建了1500整形list。然后我們又創建了9765625(5的10次方)字符串李彪。最后我們刪除了第一個list並返回。memory_profiler沒有提供另外一個腳本來讓你執行該程序，而是直接通過-m參數來調用模塊。

$ python -m memory_profiler memo_prof.py 
Filename: memo_prof.py

Line # Mem usage Increment Line Contents ================================================ 1 13.133 MiB 0.000 MiB @profile 2 def mem_func(): 3 13.387 MiB 0.254 MiB lots_of_numbers = list(range(1500)) 4 87.824 MiB 74.438 MiB x = ['letters'] * (5 ** 10) 5 87.938 MiB 0.113 MiB del lots_of_numbers 6 87.938 MiB 0.000 MiB return None 

結果的提供的信息就非常直觀了。包含代碼行數和改行執行完后的內存使用，接下來是內存增加量，最后是執行的代碼。

memory_profiler也提供mprof用來創建完整的內存使用報表，而不是每行結果。

$ mprof run memo_prof.py
mprof: Sampling memory every 0.1s
running as a Python program...

mprof也提供來圖示來查看應用內存消耗，需要查看圖表前我們需要先安裝matplotlib

$ pip install matplotlib

然后執行:

$ mprof plot

我們得到如下圖：

profilehooks

最后個要介紹的第三方包是profilehooks.它擁有一系列包裝器來分期函數。安裝：

pip install profilehooks

安裝完后，我們修改上次例子替換成profilehooks:

from profilehooks import profile @profile def mem_func(): lots_of_numbers = list(range(1500)) x = ['letters'] * (5 ** 10) del lots_of_numbers return None if __name__ == "__main__": mem_func() 

僅僅要做的是導入profilehooks並且包裝到要測試的函數中。執行后：

*** PROFILER RESULTS *** mem_func (profhooks.py:3) function called 1 times 2 function calls in 0.036 seconds Ordered by: cumulative time, internal time, call count ncalls tottime percall cumtime percall filename:lineno(function) 1 0.036 0.036 0.036 0.036 profhooks.py:3(mem_func) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 0 0.000 0.000 profile:0(profiler) 

輸出的結果和cProfile是一樣的，你可以看看我之前對這些列的描述。profilehooks提供了兩個裝飾器。我們來看看第一個timecall，它提供了函數執行時間。

from profilehooks import timecall @timecall def mem_func(): lots_of_numbers = list(range(1500)) x = ['letters'] * (5 ** 10) del lots_of_numbers return None if __name__ == "__main__": mem_func() 

執行后你將看到如下輸出：

  mem_func (profhooks2.py:3):
    0.056 seconds

整個包裝其輸出整個函數執行時間，和timeit是一樣的。

另一個profilehooks提供的裝飾器是coverage。它用來打印函數每行代碼涵蓋數。不過我看來用處到不是很大，你可以自己試試：

*** COVERAGE RESULTS *** mem_func (profhooks3.py:3) function called 1 times @coverage def mem_func(): 1: lots_of_numbers = list(range(1500)) 1: x = ['letters'] * (5 ** 10) 1: del lots_of_numbers 1: return None 

最后要告訴你的是，你也可以通過-m參數來從命令行中執行profilehooks.

python -m profilehooks mymodule.py

profilehooks是一個新包，不過我到覺得應該會很有前途。

總結

本文涵蓋了需要信息。分享了如何使用Python內建模塊,timeit和cProfile來測試和分期你的代碼，我還學會了如何自己包裝計時包裝 器和上下文管理器。然后我們還學習了一些第三方包：line_profiler, memory_profiler和profilehooks。就目前，你已經學會如何分析你的代碼，查找代碼瓶頸。