大貓咪的新玩具大貓咪的新玩具
文章 系列 標籤 分類 連結
大貓咪的新玩具大貓咪的新玩具

目錄

廣告 AD

目錄

Python：分析程式執行時間的技巧

  收錄於 Python
     約 2075 字   預計閱讀 10 分鐘    次閱讀         CC BY-NC 4.0   
Python：分析程式執行時間的技巧

有時候要測量一下程式執行的時間

這些都是好用的方法~~

廣告 AD

以下的這些方法不只能用來測量時間，也能用來測量系統資源，像是記憶體之類的，可以透過 psutil，但以下用執行時間來範例。

一般的時候我們會使用 with 來控制資源的使用和釋放，這裡我們可以借助這個功能來測量區段的花費時間，只是控制的不是資源，而是紀錄時間。

我們首先要創建一個 object，並實作以下兩個 function：

  • __enter__: 進入 with 時，紀錄開始時間。
  • __exit__: 離開 with 時，印出花費時間。

Python

from timeit import default_timer as timer

class TimeTracer(object):
    def __init__(self):
        pass
    
    def __enter__(self):
        self.start = timer()
        return self

    def __exit__(self, *args):
        self.print_cur_elasped_time()
        
    def print_cur_elasped_time(self):
        end = timer()
        print(f"Elapsed Time: {end - self.start} seconds")

使用範例：

Python

import time

with TimeTracer() as t:
    time.sleep(1)
    t.print_cur_elasped_time()
    time.sleep(2)

shell

Elapsed Time: 1.0001020130002871 seconds
Elapsed Time: 3.0002913089992944 seconds

如果我們要改測量某個 function 的花費時間，我們一樣可以使用 Section 的方法將呼叫的 code 包起來，像是這樣：

Python

with TimeTracer() as t:
    func()

但是每個呼叫的地方都要修改，有點麻煩，我們可以改成用 with 包 function 裡面的 code，例如：

Python

def func():
    with TimeTracer() as t:
       ...

這樣我如果要測量很多個 function 也是很麻煩，要改很多個，因此我們可以用 decorator：

Python

from timeit import default_timer as timer

def time_decorator(func):
    def wrapper():
        start = timer()
        func()
        end = timer()
        print(f"[{func.__name__}] Elapsed Time: {end - start} seconds")
    return wrapper

使用範例：

Python

import time

@time_decorator
def func():
    time.sleep(1)

func()

shell

[func] Elapsed Time: 1.000097033000202 seconds

如果要用先前的方法來逐行的測量，想必是一件麻煩的事情，因此這裡要使用到 sys.settrace 來註冊 trace function，可以在事件發生的時候，呼叫我們設定的 function。

trace function 會接收 3 種參數：

  • frame: 目前的 stack frame。
  • event: 事件種類。
    • call: function 被呼叫，或是進入新的 code block。
    • line: 執行新的一行 code 之前。
    • return: function 要 return 之前。
    • exception: 發生 exception。
    • opcode: 要執行新的 opcode 之前。
  • arg: 根據 event 的不同會有不同的定義。
    • return: 回傳值
    • exception: (exception, value, traceback)

我們會使用 sys.settrace 註冊 trace function，並且我們只關注 call 和 line 兩種 event，接著紀錄時間和從 frame 拿到當前 funcion 的名稱、所在檔案名稱和行數，最後將之都印出來。

Python

from timeit import default_timer as timer 
import sys

prev_time = timer()

def trace_lines(frame, event, arg):

    if event not in ['call', 'line']:
        return None
    
    global prev_time
    current = timer()
    elapsed = current - prev_time
    prev_time = current
    
    co = frame.f_code
    func_name = co.co_name
    line_no = frame.f_lineno
    filename = co.co_filename
    
    print(f'[{filename}] {func_name}:{line_no} {elapsed} seconds')

    return trace_lines

def func():
    a = 10
    b = 20
    c = a + b
    return c

sys.settrace(trace_lines)
func()
sys.settrace(None)

shell

[test.py] func:25 0.000004399975296 seconds
[test.py] func:26 0.000178300018888 seconds
[test.py] func:27 0.000152699998580 seconds
[test.py] func:28 0.000122500001453 seconds
[test.py] func:29 0.000098999997135 seconds

如果說要關注特定某些 function 時，也可以使用到 decorator，這裡我們將 trace function 包成 class，並且將目標 function 名稱傳進去用做判斷，並且創建一個 time_line_decorator 當作 function decorator，只要在想 trace 的 function 上加上這個 decorator 即可。

Python

from timeit import default_timer as timer 
import sys

class TimeLineTracer():
    def __init__(self, func_name):
        self.func_name = func_name
        self.prev_time = timer()

    def __enter__(self):
        sys.settrace(self.trace_lines)
        return self

    def __exit__(self, *args, **kwargs):
        sys.settrace(None)

    def trace_lines(self, frame, event, arg):
        if frame.f_code.co_name != self.func_name:
            return None

        if event not in ['call', 'line']:
            return None
        
        current = timer()
        elapsed = current - self.prev_time
        self.prev_time = current
        
        co = frame.f_code
        func_name = co.co_name
        line_no = frame.f_lineno
        filename = co.co_filename
        
        print(f'[{filename}] {func_name}:{line_no} {elapsed} seconds')

        return self.trace_lines

def time_line_decorator(func):
    def wrapper(*args, **kwargs):
        with TimeLineTracer(func.__name__):
            return_value = func(*args, **kwargs)
        return return_value
    return wrapper

@time_line_decorator
def func1():
    a = 10
    b = 20
    c = a + b
    return c

def func2():
    a = 10
    b = 20
    c = a + b
    return c

func1()
func2()

shell

[test.py] func1:43 0.000012999982573 seconds
[test.py] func1:45 0.000219700043090 seconds
[test.py] func1:46 0.000119699980132 seconds
[test.py] func1:47 0.000130400003400 seconds
[test.py] func1:48 0.000111899978947 seconds

最後，如果你要分析程式哪邊的耗時比較多，藉以來定位程式需要改進的地方，可以直接透過 command line 來使用：

shell

python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)

可以透過 -o 來將輸出儲存到檔案中，預設為標準輸出，-s 則是在使用標準輸出的時候用來設定排序的參數，後面接著要測試的 module 或是 script。

排序通常都使用：

  • cumulative / cumtime
  • calls / ncalls
  • time / tottime

以下為測試上面範例程式的輸出：

shell

$ py -m cProfile -s cumtime test.py
[test.py] func:25 0.000003600027412 seconds
[test.py] func:26 0.000179799972102 seconds
[test.py] func:27 0.000151399988681 seconds
[test.py] func:28 0.000120100041386 seconds
[test.py] func:29 0.000107100000605 seconds
         544 function calls (538 primitive calls) in 0.003 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      2/1    0.000    0.000    0.003    0.003 {built-in method builtins.exec}
        1    0.000    0.000    0.003    0.003 test.py:1(<module>)
      2/1    0.000    0.000    0.002    0.002 <frozen importlib._bootstrap>:1165(_find_and_load)
      2/1    0.000    0.000    0.002    0.002 <frozen importlib._bootstrap>:1120(_find_and_load_unlocked)
      2/1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap>:666(_load_unlocked)
        1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap_external>:934(exec_module)
      4/2    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap>:233(_call_with_frames_removed)
        1    0.000    0.000    0.001    0.001 timeit.py:1(<module>)
        2    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap>:1054(_find_spec)
        2    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap>:566(module_from_spec)
        1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap_external>:1499(find_spec)
        1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap_external>:1467(_get_spec)
        1    0.001    0.001    0.001    0.001 test.py:25(func)
        4    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap_external>:1607(find_spec)
        1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap>:770(create_module)
        1    0.001    0.001    0.001    0.001 {built-in method _imp.create_builtin}
        1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap_external>:1007(get_code)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1127(get_data)
        6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:140(_path_stat)
        6    0.000    0.000    0.000    0.000 {built-in method nt.stat}
       20    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:96(_path_join)
        1    0.000    0.000    0.000    0.000 {built-in method io.open_code}
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:493(_init_module_attrs)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:437(cache_from_source)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:727(_compile_bytecode)
        1    0.000    0.000    0.000    0.000 {built-in method marshal.loads}
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:392(cached)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:567(_get_cached)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:169(__enter__)
        1    0.000    0.000    0.000    0.000 {method 'read' of '_io.BufferedReader' objects}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:159(_path_isfile)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1146(path_stats)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:150(_path_is_mode_type)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1602(_get_spec)
       20    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:119(<listcomp>)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:179(_get_module_lock)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:778(spec_from_file_location)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:132(_path_split)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.__build_class__}
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:748(find_spec)
       66    0.000    0.000    0.000    0.000 {method 'endswith' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {built-in method builtins.max}
       45    0.000    0.000    0.000    0.000 {built-in method builtins.len}
       43    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method '__exit__' of '_io._IOBase' objects}
       10    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
       62    0.000    0.000    0.000    0.000 {method 'rstrip' of 'str' objects}
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:173(__exit__)
        6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:134(<genexpr>)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:100(acquire)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:71(__init__)
       22    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:244(_verbose_message)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:642(_classify_pyc)
       22    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:172(_path_isabs)
        5    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1424(_path_importer_cache)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:778(exec_module)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:422(spec_from_loader)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:920(find_spec)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:125(release)
        3    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:84(_unpack_uint32)
        4    0.000    0.000    0.000    0.000 {built-in method _thread.allocate_lock}
       22    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:675(_validate_timestamp_pyc)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:198(cb)
        4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:67(_relax_case)
       10    0.000    0.000    0.000    0.000 {method 'rpartition' of 'str' objects}
        2    0.000    0.000    0.000    0.000 {built-in method _imp.is_builtin}
        4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:1030(__exit__)
        9    0.000    0.000    0.000    0.000 {built-in method builtins.hasattr}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:599(_check_name_wrapper)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:405(parent)
        1    0.000    0.000    0.000    0.000 {built-in method _imp.exec_builtin}
        4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:1026(__enter__)
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:357(__init__)
        4    0.000    0.000    0.000    0.000 {method 'rfind' of 'str' objects}
        1    0.000    0.000    0.000    0.000 timeit.py:86(Timer)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:254(_requires_builtin_wrapper)
        1    0.000    0.000    0.000    0.000 {built-in method nt.getcwd}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:48(_new_module)
        7    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
        8    0.000    0.000    0.000    0.000 {built-in method _imp.release_lock}
        1    0.000    0.000    0.000    0.000 {built-in method nt._path_splitroot}
        8    0.000    0.000    0.000    0.000 {built-in method _imp.acquire_lock}
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:165(__init__)
        4    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.lock' objects}
        6    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
        3    0.000    0.000    0.000    0.000 {built-in method from_bytes}
        4    0.000    0.000    0.000    0.000 {built-in method _thread.get_ident}
        3    0.000    0.000    0.000    0.000 {built-in method nt.fspath}
        2    0.000    0.000    0.000    0.000 {method 'pop' of 'dict' objects}
        2    0.000    0.000    0.000    0.000 {built-in method sys.settrace}
        1    0.000    0.000    0.000    0.000 {built-in method _imp.find_frozen}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1097(__init__)
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:413(has_location)
        1    0.000    0.000    0.000    0.000 {built-in method _imp._fix_co_filename}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:931(create_module)
        1    0.000    0.000    0.000    0.000 {built-in method time.perf_counter}
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1122(get_filename)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:795(is_package)

Python：分析程式執行時間的技巧

WAT：檢視 Python 物件，一款強大的 Debug 工具

Python：分析程式執行時間的技巧

py-spy: 找出 Python 程式性能瓶頸

Python：分析程式執行時間的技巧

Pexpect：自動化的神奇工具，讓自動化變得更簡單

Python：分析程式執行時間的技巧

加速大型語言模型：運用 ONNX 格式推理和 KV Cache 的使用

Python：分析程式執行時間的技巧

掌握 Python Decorators：從基礎到進階的各種寫法

廣告 AD
更新於 2024-07-14
CC BY-NC 4.0
閱讀原始文檔
 Python, Trace, Debug
 | 主頁