2.4 簡單計時方法——print語句和裝飾器

前面顯示了代碼中的一些print語句生成的輸出。在作者的筆記本電腦上使用CPython 3.7運行這些代碼時，執(zhí)行時間大約為8 s。請注意，執(zhí)行時間并非固定不變的，計算代碼的執(zhí)行時間時，必須考慮正常波動，否則可能將執(zhí)行時間的隨機變化歸功于對代碼所做的改進。

運行代碼時，計算機還執(zhí)行其他任務(wù)，如訪問網(wǎng)絡(luò)、磁盤或RAM，而這些因素會導(dǎo)致代碼的執(zhí)行時間發(fā)生變化。

作者的筆記本電腦是一臺Dell 9550，它配置了Intel Core I7 6700HQ CPU（2.6 GHz、6 MB緩存、雙核、支持超線程），內(nèi)存為32 GB，安裝的操作系統(tǒng)為Linux Mint 19.1（Ubuntu 18.04）。

在函數(shù)calc_pure_python（示例2-2）中，有幾條print語句。這是測量函數(shù)中代碼執(zhí)行時間的最簡單方式。這種基本方法雖然有些粗糙，但在剛著手研究代碼時很有用。

在調(diào)試和剖析代碼時，print語句是一種常用手段。它雖然難以管理，但對簡單的調(diào)查很有用。使用完print語句后，務(wù)必將其刪除，否則輸出將亂得一塌糊涂。

一種更整潔的方法是使用裝飾器，為此只需在目標函數(shù)前面添加一行代碼。這里使用的裝飾器非常簡單，只是重現(xiàn)print語句的效果。稍后，我們可以讓代碼更高級。

示例2-5定義了新函數(shù)timefn，它將另一個函數(shù)作為參數(shù)。這個新函數(shù)定義了函數(shù)measure_time，它接收參數(shù)*args（數(shù)量可變的位置參數(shù)）和**kwargs（數(shù)量可變的鍵-值對參數(shù)），并將它們傳遞給函數(shù)fn。在調(diào)用fn之前和之后，程序都調(diào)用了time.time()來記錄時間，然后打印結(jié)果以及函數(shù)名（fn._  _name_ _）。使用這個裝飾器的開銷很小，但如果調(diào)用fn數(shù)百萬次，開銷可就不小了。為向調(diào)用者暴露被裝飾的函數(shù)的名稱和文檔字符串，我們使用了@wraps(fn)；如果不這樣做，暴露的將是裝飾器（而不是它裝飾的函數(shù)）的名稱和文檔字符串。

示例2-5　定義自動計時的裝飾器

from functools import wraps
　
def timefn(fn):
    @wraps(fn)
def measure_time(*args, **kwargs):
        t1 = time.time()
        result = fn(*args, **kwargs)
        t2 = time.time()
print(f"@timefn: {fn._ _name_ _} took {t2 - t1} seconds")
return result
return measure_time
　
@timefn
def calculate_z_serial_purepython(maxiter, zs, cs):
    ...

運行這個版本的代碼（它保留了以前的print語句）時，發(fā)現(xiàn)其執(zhí)行速度比從calc_pure_python中調(diào)用快些，這是因為函數(shù)調(diào)用存在開銷（差別微乎其微）：

    Length of x: 1000
    Total elements: 1000000
    @timefn:calculate_z_serial_purepython took 8.00485110282898 seconds
    calculate_z_serial_purepython took 8.004898071289062 seconds

注意：添加剖析信息不可避免地會降低執(zhí)行速度——有些剖析選項提供了大量信息，但會嚴重影響速度，因此必須在剖析信息的詳細程度和速度之間進行權(quán)衡。

也可以使用模塊timeit來粗略地測量CPU密集型函數(shù)的執(zhí)行速度。更典型的情況是，嘗試解決問題的不同方式時，通常使用這個模塊來測量各種簡單表達式的執(zhí)行時間。

警告：模塊timeit會暫時禁用垃圾收集器。如果受測操作會調(diào)用垃圾收集器，那么這可能影響測量結(jié)果。有關(guān)這方面的幫助信息，請參閱Python文檔。

可從命令行運行timeit，如下所示：

python -m timeit -n 5 -r 1 -s "import julia1" \
 "julia1.calc_pure_python(desired_width=1000, max_iterations=300)"

請注意，必須使用設(shè)置選項-s來導(dǎo)入calc_pure_python所在的模塊。timeit的一些默認設(shè)置適合簡短的代碼，但對于運行時間較長的函數(shù)，最好指定循環(huán)次數(shù)（-n 5）和重復(fù)次數(shù)（-r 5）。這樣，結(jié)果將為多次重復(fù)的最佳結(jié)果。要顯示每次重復(fù)中所有循環(huán)的累計時間，可添加標志-v，這有助于展示結(jié)果的波動性。

如果沒有指定-n和-r，timeit將默認循環(huán)10次并重復(fù)5次，對函數(shù)calc_pure_python來說，這需要6 min。如果想更快地獲得結(jié)果，可修改默認設(shè)置。

我們只關(guān)心最佳結(jié)果，因為其他結(jié)果可能受到了其他進程的影響：

5 loops, best of 1: 8.45 sec per loop

請嘗試運行多次，看看結(jié)果是否不同——要獲得穩(wěn)定的最佳結(jié)果，可能需要增加重復(fù)次數(shù)。不存在絕對正確的配置，如果發(fā)現(xiàn)計時結(jié)果波動很大，就增加重復(fù)次數(shù)，直到結(jié)果相當(dāng)穩(wěn)定為止。

上述輸出表明，調(diào)用calc_pure_python的開銷為8.45 s（最佳結(jié)果），而前面使用裝飾器@timefn調(diào)用calculate_z_serial_purepython的開銷為8.0 s。區(qū)別主要在于創(chuàng)建列表zs和cs所需的時間。

在IPython中，可以用同樣的方式使用魔法命令%timeit。在IPython或Jupyter Notebook中以交互方式編寫代碼時，可像下面這樣做：

In [1]: import julia1
In [2]: %timeit julia1.calc_pure_python(desired_width=1000, max_iterations=300)

警告：請注意，在Jupyter和IPython中，魔法命令%timeit計算最佳結(jié)果的方式與timeit.py方法不同。timeit.py使用的是最小值（最短時間），而IPython從2016年起轉(zhuǎn)而使用平均值和標準偏差。這兩種方法都存在缺陷，但通常都是合理的，雖然它們之間沒有可比性。因此，請堅持使用其中的一種方法，而不要混用。

必須考慮計算的負載變化。有很多在后臺運行的任務(wù)，如Dropbox、備份操作，它們可能隨機地占用CPU和磁盤資源。網(wǎng)頁中的腳本也會導(dǎo)致不可預(yù)測的資源占用。圖2-4表明，執(zhí)行前述某些計時步驟時，有個核心的占用率為100%，而其他核心的占用率都較低。

圖2-4　在我們對函數(shù)進行計時期間，Ubuntu系統(tǒng)監(jiān)視器顯示的后臺任務(wù)的CPU占用情況

系統(tǒng)監(jiān)視器的結(jié)果表明，機器中的活動會時不時地出現(xiàn)峰值，因此必須使用系統(tǒng)監(jiān)視器來核實沒有其他進程占用關(guān)鍵資源（CPU、磁盤、網(wǎng)絡(luò)）。