《利用Python進行數(shù)據(jù)分析》 附錄 B.3.2 對代碼測時:%time和%timeit

附錄B 更多IPython系統(tǒng)相關(guān)內(nèi)容


B.3.2 對代碼測時:%time和%timeit

對于更大規(guī)?;蚋L時間運行的數(shù)據(jù)分析應用程序,你可能希望測量各個組件或單個語句或函數(shù)調(diào)用的執(zhí)行時間。你可能需要一個在復雜過程中哪些函數(shù)最耗時的報告。幸運的是,IPython允許你非常方便地在開發(fā)、測試代碼的時候獲得這些信息。

手工使用內(nèi)置time模塊及其函數(shù)time.clock和time.time通常是單調(diào)和重復的,因為你必須編寫相同的無趣樣板代碼

由于這是一個很常見的操作,而IPython有兩個魔術(shù)函數(shù),%time和%timeit,為你自動執(zhí)行此過程。

%time一次運行一條語句,并報告總執(zhí)行時間。假設(shè)我們有一大串字符串,我們想比較不同的選擇所有的字符串中以特殊前綴開始的字符串的方法。這里有一個包含600,000個字符串的列表和兩個只選出以’foo’開頭的方法(見圖B-1)

image

Wall time("wall-clock time"簡寫,壁鐘時間)是我們主要感興趣的數(shù)字。所以,看起來第一種方法需要兩倍以上的時間,但這不是一個非常精確的測量。如果你嘗試多用%time測試,你就發(fā)現(xiàn)測試結(jié)果是個變量。為了獲得更精確的測量,可以使用%timeit魔術(shù)函數(shù)。給定任意的語句,%timeit有多次運行語句以產(chǎn)生更準確的平均運行時間的功能(見圖B-2)

image

這個看似普通的例子表明,理解本書中使用的Python標準庫、NumPy、pandas以及其他的類庫的性能特征是很有必要的。在更大型的數(shù)據(jù)分析應用中,相差的毫秒就開始累加了!

%timeit對于執(zhí)行時間很短的分析語句和函數(shù)特別有用,甚至在微秒(百萬分之一秒)或納秒(十億分之一秒)的級別依然有效。

這些時間可能看起來微不足道,但是,調(diào)用100萬次的20微秒函數(shù)比5毫秒的函數(shù)要多用15秒。在之前的例子中,我們可以非常直接地對比兩個字符串操作來理解它們的性能差異(見圖B-3)

image

B.3.3 基礎(chǔ)分析:%prun和%run -p

代碼分析與代碼測試相關(guān)性很高,但代碼分析更多關(guān)注于時間開銷的位置。主要的Python分析工具是cProfile模塊,該模塊不是專用于IPython。cProfile執(zhí)行程序或任意代碼塊,同時記錄每個函數(shù)花費多少時間。

使用cProfile的常用方法是在命令行上運行整個程序,并輸出每個函數(shù)的聚合時間。假設(shè)我們有一個簡單的腳本,它在循環(huán)中執(zhí)行一些線性代數(shù)(計算一系列100×100矩陣的最大絕對特征值):

import numpy as np
from numpy.linalg import eigvals
def run_experiment(niter=100):
    K = 100
    results = []
    for _ in xrange(niter):
        mat = np.random.randn(K, K)
        max_eigenvalue = np.abs(eigvals(mat)).max()
        results.append(max_eigenvalue)
    return results
some_results = run_experiment()
print 'Largest one we saw: %s' % np.max(some_results)

你可以使用下面的代碼在命令行中通過cProfile運行腳本:

python -m cProfile cprof_example.py

如果你按照上面的代碼嘗試,你會發(fā)現(xiàn)輸出是按照函數(shù)名排序的。這讓我們很難了解大部分時間花在哪里,所以通常需要使用-s標志指定一個排序順序

$ python -m cProfile -s cumulative cprof_example.py
Largest one we saw: 11.923204422
    15116 function calls (14927 primitive calls) in 0.720 seconds
Ordered by: cumulative time
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.001    0.001    0.721    0.721 cprof_example.py:1(<module>)
  100    0.003    0.000    0.586    0.006 linalg.py:702(eigvals)
  200    0.572    0.003    0.572    0.003 {numpy.linalg.lapack_lite.dgeev}
    1    0.002    0.002    0.075    0.075 __init__.py:106(<module>)
  100    0.059    0.001    0.059    0.001 {method 'randn')
    1    0.000    0.000    0.044    0.044 add_newdocs.py:9(<module>)
    2    0.001    0.001    0.037    0.019 __init__.py:1(<module>)
    2    0.003    0.002    0.030    0.015 __init__.py:2(<module>)
    1    0.000    0.000    0.030    0.030 type_check.py:3(<module>)
    1    0.001    0.001    0.021    0.021 __init__.py:15(<module>)
    1    0.013    0.013    0.013    0.013 numeric.py:1(<module>)
    1    0.000    0.000    0.009    0.009 __init__.py:6(<module>)
    1    0.001    0.001    0.008    0.008 __init__.py:45(<module>)
  262    0.005    0.000    0.007    0.000 function_base.py:3178(add_newdoc)
100 0.003 0.000 0.005 0.000 linalg.py:162(_assertFinite)
...

輸出只顯示最前面的15行。通過掃描cumtime列來查看每個函數(shù)內(nèi)花費的總時間是最容易的。

請注意,如果一函數(shù)調(diào)用了其他一些函數(shù),時鐘并不會停止運行。cProfile記錄了每個函數(shù)調(diào)用的起始和結(jié)束時間,并以此來生成耗時。
除了命令行的使用,還可以通過編程方式使用cProfile來分析任意代碼塊,而無須運行新進程。IPython使用%prun命令和%run的-p選項為此功能提供了方便的接口。%prun與cProfile采用相同的“命令行選項”,但會分析任意Python語句而不是整個.py文件:

In [4]: %prun -l 7 -s cumulative run_experiment()
          4203 function calls in 0.643 seconds
Ordered by: cumulative time
List reduced from 32 to 7 due to restriction <7>
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.643    0.643 <string>:1(<module>)
    1    0.001    0.001    0.643    0.643 cprof_example.py:4(run_experiment)
    100    0.003    0.000    0.583    0.006 linalg.py:702(eigvals)
    200    0.569    0.003    0.569    0.003 {numpy.linalg.lapack_lite.dgeev}
    100    0.058    0.001    0.058    0.001 {method 'randn'}
    100    0.003    0.000    0.005    0.000 linalg.py:162(_assertFinite)
    200    0.002    0.000    0.002    0.000 {method 'all' of 'numpy.ndarray'}

同樣,調(diào)用%run -p -s cumulative cprof_example.py與命令行方法具有相同的效果,并且你不必離開IPython。

在Jupyter notebook中,你可以使用%%prun魔術(shù)方法(兩個百分號%)來分析整個代碼塊。這會彈出一個包含配置文件輸出的獨立窗口。獨立窗口對于快速回答如下問題很有用:“為什么代碼塊需要很長時間才能運行?”

還有其他工具可以幫助你在使用IPython或Jupyter時更容易理解配置文件。其中一個是SnakeViz(https://github.com/jiffyclub/snakeviz),它使用d3.js生成配置文件結(jié)果的交互式可視化。

B.3.4 逐行分析函數(shù)

某些情況下,你從%prun(或者及其他基于cProfile的分析方法)獲得的信息可能無法完整闡述函數(shù)的執(zhí)行時間,或者特別復雜而使得根據(jù)函數(shù)名聚合得到的結(jié)果太難而無法解釋。對于這種情況,有一個小的庫,叫作line_profiler(從PyPI或者其他的包管理工具中獲得)。
這個庫包含了一個IPython拓展,增加了一個新的魔術(shù)函數(shù)%lprun, %lprun可以對一或多個函數(shù)進行逐行分析。你可以通過修改你的IPython配置類開啟這個拓展(參考IPython官方文檔或本章之后介紹配置的小節(jié)),修改配置時增加下面一行:

# IPython拓展需要載入的模塊名稱列表
c.TerminalIPythonApp.extensions = ['line_profiler']

你也可以運行以下命令:

%load_ext line_profiler

line_profiler可以按編程的方式使用(參考line_profiler完整文檔),但是可能最有效的使用方式還是在IPython中交互式使用。假設(shè)你有一個prod_mod模塊,該模塊含有以下進行NumPy數(shù)組操作的代碼:

from numpy.random import randn
def add_and_sum(x, y):
    added = x + y
    summed = added.sum(axis=1)
    return summed
def call_function():
    x = randn(1000, 1000)
    y = randn(1000, 1000)
    return add_and_sum(x, y)

如果我們想要知道add_and_sum函數(shù)的性能,%prun會給出以下結(jié)果:

In [569]: %run prof_mod
In [570]: x = randn(3000, 3000)
In [571]: y = randn(3000, 3000)
In [572]: %prun add_and_sum(x, y)
          4 function calls in 0.049 seconds
    Ordered by: internal time
    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.036    0.036    0.046    0.046 prof_mod.py:3(add_and_sum)
        1    0.009    0.009    0.009    0.009 {method 'sum' of 'numpy.ndarray'}
        1    0.003    0.003    0.049    0.049 <string>:1(<module>)

這不是特別讓人理解。通過激活line_profiler的IPython擴展,可以使用新的命令% lprun。使用的唯一區(qū)別是我們必須向%lprun指明我們希望分析哪些函數(shù)。一般的語法是:

%lprun -f func1 -f func2 statement to profile

在這種情況下,我們想要對add_and_sum做分析,因此我們運行以下代碼:

In [573]: %lprun -f add_and_sum add_and_sum(x, y)
Timer unit: 1e-06 s
File: prof_mod.py
Function: add_and_sum at line 3
Total time: 0.045936 s
Line #      Hits      Time  Per Hit   % Time Line Contents
==========================================================
    3                                          def add_and_sum(x, y):
    4          1     36510  36510.0     79.5      added = x + y
    5          1      9425   9425.0     20.5     summed = added.sum(axis=1)
    6          1          1      1.0      0.0     return summed

這結(jié)果更容易解釋。在這種情況下,我們分析了我們在之前語句中使用的相同函數(shù)。查看之前的模塊代碼,我們可以調(diào)用并分析call_function以及add_and_sum,從而全面了解代碼的性能:


In [574]: %lprun -f add_and_sum -f call_function call_function()
Timer unit: 1e-06 s
File: prof_mod.py
Function: add_and_sum at line 3
Total time: 0.005526 s
Line #       Hits           Time  Per Hit    % Time  Line Contents
==============================================================
    3                                           def add_and_sum(x, y):
    4         1         4375   4375.0     79.2      added = x + y
    5         1         1149   1149.0     20.8      summed = added.sum(axis=1)
    6         1            2      2.0      0.0      return summed
File: prof_mod.py
Function: call_function at line 8
Total time: 0.121016 s
Line #       Hits           Time  Per Hit    % Time  Line Contents
==============================================================
    8                                           def call_function():
    9          1        57169  57169.0        47.2   x = randn(1000, 1000)
     10          1         58304  58304.0     48.2      y = randn(1000, 1000)
     11          1          5543    5543.0      4.6      return add_and_sum(x, y)

作為一個通用的經(jīng)驗規(guī)則,我傾向于使用%prun(基于cProfile)作為”宏觀“的性能分析,用%lprun(基于line_profiler)作為微觀分析。對于這兩個工具的理解都是非常有意義的。

:你必須明確指定要使用% lprun進行分析的函數(shù)的名稱,原因是“回溯”每行的執(zhí)行時間的開銷很大?;厮莶桓信d趣的函數(shù)可能會顯著改變分析結(jié)果。

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成,瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明:文章內(nèi)容(如有圖片或視頻亦包括在內(nèi))由作者上傳并發(fā)布,文章內(nèi)容僅代表作者本人觀點,簡書系信息發(fā)布平臺,僅提供信息存儲服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容