Python 學習筆記 - 效能分析

載入 Julia Set

書中使用 julia set 來進行程式執行時間的分析。

print & Decorator

calculate_z_serial_purepython 為需要被計時的函式

直覺的分析方式可以用 print 函式，計算 func. 執行前後的時間間隔

# 擴展 julia pseudo code  
def calculate_z_serial_purepython(maxiter, zs, cs):  
 output = [0] * len(zs)  
 for i in range(len(zs)):  
 n = 0  
 z = zs[i]  
 c = cs[i]  
 while abs(z) < 2 and n < maxiter:  
 z = z * z + c  
 n += 1  
 output[i] = n  
 return output  
  
# 建構座標串列，作為函式輸入  
def calc_pure_python(desired_width, max_iterations):  
   
 ... ...  
  
 print("Length of x:", len(x))  
 print("Total elements:", len(zs))  
 start_time = time.time()  
 output = calculate_z_serial_purepython(max_iterations, zs, cs)  
 end_time = time.time()  
 secs = end_time - start_time  
 print(calculate_z_serial_purepython.__name__ + " took", secs, " seconds")  
 pass  
  
if __name__ == "__main__":  
 calc_pure_python(desired_width=10000, max_iterations=300)

此外我們也可以透過定義裝飾器 (Decorator) ，自動化計時

可以看出執行時間比 calc_pure_python 稍微快一點點，差在於 呼叫函式 的開銷。

def timefn(fn):  
 @wraps(fn)  
 def measure_time(*args, **kwargs):  
 t1 = time.time()  
 result = fn(*args, **kwargs)  
 t2 = time.time()  
 print("@timefn:" + fn.__name__ + " took " + str(t2 - t1) + " seconds")  
 return result  
 return measure_time  
  
@timefn  
def calculate_z_serial_purepython(maxiter, zs, cs):  
 ... ...  
 pass

>>>  
Length of x: 10001  
Total elements: 22232223  
@timefn:
calculate_z_serial_purepython took 12.860910654067993 seconds  
calculate_z_serial_purepython took 12.861911058425903  seconds

使用 timeit 模組

1 2	python -m timeit -n 2 -r 3 -s "import julia_set" \ "julia_set.calc_pure_python(desired_width=10000, max_iterations=300)"

>>>  
Length of x: 10001  
Total elements: 22232223  
@timefn:
calculate_z_serial_purepython took 13.562626361846924 seconds  
calculate_z_serial_purepython took 13.562626361846924  seconds  
Length of x: 10001  
 ... ...  
 ... ...  
2 loops, best of 3: 24.3 sec per loop

使用 Unix time 計時

1	$ /usr/bin/time --verbose python julia_set.py

Length of x: 10001  
Total elements: 22232223  
@timefn:
calculate_z_serial_purepython took 13.609860897064209 seconds  
calculate_z_serial_purepython took 13.609860897064209  seconds  
 Command being timed: "python julia_set.py"  
 User time (seconds): 12.53  
 System time (seconds): 0.50  
 Percent of CPU this job got: 99%  
 Elapsed (wall clock) time (h:mm:ss or m:ss): 0:13.03  
 Average shared text size (kbytes): 0  
 Average unshared data size (kbytes): 0  
 Average stack size (kbytes): 0  
 Average total size (kbytes): 0  
 Maximum resident set size (kbytes): 2649264  
 Average resident set size (kbytes): 0  
 Major (requiring I/O) page faults: 0  
 Minor (reclaiming a frame) page faults: 516303  
 Voluntary context switches: 1  
 Involuntary context switches: 23  
 Swaps: 0  
 File system inputs: 0  
 File system outputs: 0  
 Socket messages sent: 0  
 Socket messages received: 0  
 Signals delivered: 0  
 Page size (bytes): 4096  
 Exit status: 0

注意:

Major (requiring I/O) page faults 可顯示出哪些程式由於資料從 RAM 搬移至 DISK，進行磁碟存取而導致運作速度降低。

使用 cPython 模組

cPython 是標準程式庫的內建分析工具，他可以連接至 CPython 內的虛擬機器查看每個函式的執行時間。他會耗費更大的執行開銷，但式可以獲取更多資訊。

1	python -m cProfile -s cumulative julia_set.py

參數解釋

Para.	Description
ncalls	調用次數
tottime	在指定函数中消耗的總時間 (不含調用子含式時間)
percall	是 tottime 除以 ncalls 的商
cumtime	指定的函数及其所有子函数消耗的累計時間
percall	是 cumtime 除以原始調用 (次数) 的商 (含數運行一次的平均時間)
filename	提供相應數據的每個函式

>>>  
Length of x: 10001  
Total elements: 22232223  
@timefn:calculate_z_serial_purepython took 17.469009399414062 seconds  
 85723442 function calls in 33.889 seconds  
  
 Ordered by: cumulative time  
  
 ncalls  tottime  percall  cumtime  percall filename:lineno(function)  
 1    0.000    0.000   33.889   33.889 {built-in method builtins.exec}  
 1    0.550    0.550   33.889   33.889 julia_set.py:1(<module>)  
 1   12.257   12.257   33.339   33.339 julia_set.py:7(calc_pure_python)  
 1    0.000    0.000   17.470   17.470 julia_set.py:42(measure_time)  
 1   13.078   13.078   17.470   17.470 julia_set.py:52(calculate_z_serial_purepython)  
 41246738    4.392    0.000    4.392    0.000 {built-in method builtins.abs}  
 44476670    3.611    0.000    3.611    0.000 {method 'append' of 'list' objects}  
 4    0.001    0.000    0.001    0.000 {built-in method builtins.print}  
 1    0.000    0.000    0.000    0.000 julia_set.py:41(timefn)  
 1    0.000    0.000    0.000    0.000 functools.py:34(update_wrapper)  
 1    0.000    0.000    0.000    0.000 functools.py:64(wraps)  
 4    0.000    0.000    0.000    0.000 {built-in method builtins.len}  
 4    0.000    0.000    0.000    0.000 {built-in method time.time}  
 7    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}  
 1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}  
 5    0.000    0.000    0.000    0.000 {built-in method builtins.setattr}  
 1    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}

透過 pstats 模組格式化表格查看。

為了進一步控制 cProfile 結果，可以儲存成一個統計檔案 profile.stats，並以 python 分析它。

1	python -m cProfile -o profile.stats julia_set.py

使用 pstats 載入分析：

import pstats  
p = pstats.Stats("profile.stats")  
p.sort_stats("cumulative")  
p.print_stats()

>>>  
Wed Jan 13 16:38:37 2021    profile.stats  
  
 85723442 function calls in 33.296 seconds  
  
 Ordered by: cumulative time  
  
 ncalls  tottime  percall  cumtime  percall filename:lineno(function)  
 1    0.000    0.000   33.296   33.296 {built-in method builtins.exec}  
 1    0.534    0.534   33.296   33.296 julia_set.py:1(<module>)  
 1   11.865   11.865   32.762   32.762 julia_set.py:7(calc_pure_python)  
 1    0.000    0.000   17.240   17.240 julia_set.py:42(measure_time)  
 1   12.872   12.872   17.240   17.240 julia_set.py:52(calculate_z_serial_purepython)  
 41246738    4.368    0.000    4.368    0.000 {built-in method builtins.abs}  
 44476670    3.656    0.000    3.656    0.000 {method 'append' of 'list' objects}  
 4    0.001    0.000    0.001    0.000 {built-in method builtins.print}  
 1    0.000    0.000    0.000    0.000 julia_set.py:41(timefn)  
 1    0.000    0.000    0.000    0.000 C:\ProgramData\Anaconda3\lib\functools.py:34(update_wrapper)  
 4    0.000    0.000    0.000    0.000 {built-in method builtins.len}  
 1    0.000    0.000    0.000    0.000 C:\ProgramData\Anaconda3\lib\functools.py:64(wraps)  
 4    0.000    0.000    0.000    0.000 {built-in method time.time}  
 7    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}  
 1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}  
 5    0.000    0.000    0.000    0.000 {built-in method builtins.setattr}  
 1    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}

使用 SnakeViz 將 cProfile 的輸出視覺化

執行 snakeviz profile.stats 可以將 CPU 耗費資源以圖表方式視覺化呈現，寬度表示執行所耗費時間。
下方表格則是歸納出函式的耗費時間，為了與人溝通解釋，圖表可以快速讓聽者了解你的觀點。

Sean talks