How to track functions executions in real time?

DB3D 0
Viewed 57

I created my own profiler for my python plugin, it works by procedurally injecting a profiling wrapper for every single functions/class functions of my modules, it is very rough, and surprisingly difficult example: https://blender.stackexchange.com/questions/273803/profiling-a-blender-plugin/273804#273804.

It allows me to see which functions are executed in my python plugin in real-time. see below, when I click on a button, I'll see all related executions.

How can I achieve the same effect with cProfile or another built-in module perhaps? the goal is to show all functions execution (filtering X module) in the console in real-time , w/o manually adding decorators to many functions

enter image description here

debugging python
1 Answers

You can track function execution with sys.setprofile or sys.settrace - official documentation.

Here is a simple function profiler:

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)

Results:

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

Useful link: https://explog.in/notes/settrace.html

u1234x12340
Related