debugging 如何真实的跟踪功能执行情况?

deikduxw  于 2022-11-14  发布在  其他
关注(0)|答案(1)|浏览(139)

我为我的python插件创建了我自己的分析器,它的工作原理是程序化地为我的模块的每个函数/类函数注入一个分析 Package 器,这是非常粗糙的,令人惊讶的困难的例子:https://blender.stackexchange.com/questions/273803/profiling-a-blender-plugin/273804#273804。
它可以让我看到哪些函数在我的python插件中实时执行。见下面,当我点击一个按钮,我会看到所有相关的执行。

**我怎样才能使用cProfile或其他内置模块达到同样的效果?**目标是在控制台中实时显示所有函数的执行情况(过滤X模块),而无需手动向许多函数添加装饰器

kg7wmglp

kg7wmglp1#

您可以使用sys.setprofilesys.settrace(官方文档)跟踪函数执行。
下面是一个简单的函数分析器:

import os
import sys
import time
from collections import defaultdict
from datetime import datetime
from types import FrameType

import numpy as np

CALL_STACK = defaultdict(list)

def function_time_profiler(frame: FrameType, event: str, arg):

    # check possible options here https://docs.python.org/3/library/sys.html#sys.setprofile
    # now we are going to trace functions
    if event == "call":
        # where is the function is defined
        source_code_path = os.path.abspath(frame.f_code.co_filename)

        # by default all the functions are traced
        # including standard libs
        # now we skip tracing all functions from installed libraries
        # and tracing only user defined function
        # you may need to change this behaviour for your specific needs
        if not source_code_path.startswith(sys.prefix):
            function_name = frame.f_code.co_name
            func_key = f"{source_code_path}:{function_name}"
            current_time = datetime.now()
            # save the time at the moment of a call
            CALL_STACK[func_key].append(current_time)
            print(f"Calling function: '{func_key}' at {current_time}")

    # function exiting
    if event == "return":
        source_code_path = os.path.abspath(frame.f_code.co_filename)
        function_name = frame.f_code.co_name
        func_key = f"{source_code_path}:{function_name}"

        if func_key in CALL_STACK:
            # previously we saved the time when the function was called
            # so we can measure elapsed time
            func_start_time = CALL_STACK[func_key].pop()
            elapsed = (datetime.now() - func_start_time).total_seconds()
            print(
                f"Exiting function '{source_code_path}:{function_name}'. Execution time: {elapsed} seconds"
            )

    return function_time_profiler

def my_func_a(a):
    time.sleep(0.2)
    return a * a

def my_func_b(a, b):
    s = 0
    for _ in range(a):
        s += my_func_a(a)
    return a + np.sqrt(b)

# Start profiling
sys.setprofile(function_time_profiler)

r = my_func_b(5, 25)
assert r == (0 + 1 + 2 + 4) + 5

# Stop profiling
sys.setprofile(None)
sys.setprofile(function_time_profiler)

结果:

Calling function: '/home/u1234x1234/so/exp.py:my_func_b' at 2022-09-08 22:23:58.885964
Calling function: '/home/u1234x1234/so/exp.py:my_func_a' at 2022-09-08 22:23:58.885989
Exiting function '/home/u1234x1234/so/exp.py:my_func_a'. Execution time: 0.200249 seconds
Calling function: '/home/u1234x1234/so/exp.py:my_func_a' at 2022-09-08 22:23:59.086269
Exiting function '/home/u1234x1234/so/exp.py:my_func_a'. Execution time: 0.200262 seconds
Calling function: '/home/u1234x1234/so/exp.py:my_func_a' at 2022-09-08 22:23:59.286568
Exiting function '/home/u1234x1234/so/exp.py:my_func_a'. Execution time: 0.20027 seconds
Calling function: '/home/u1234x1234/so/exp.py:my_func_a' at 2022-09-08 22:23:59.486873
Exiting function '/home/u1234x1234/so/exp.py:my_func_a'. Execution time: 0.200266 seconds
Calling function: '/home/u1234x1234/so/exp.py:my_func_a' at 2022-09-08 22:23:59.687175
Exiting function '/home/u1234x1234/so/exp.py:my_func_a'. Execution time: 0.200265 seconds
Exiting function '/home/u1234x1234/so/exp.py:my_func_b'. Execution time: 1.001529 seconds

有用链接:https://explog.in/notes/settrace.html

相关问题