From abb791a17440fcefcd78a1da977d8fd1f9f5d67b Mon Sep 17 00:00:00 2001 From: Dinis Cruz Date: Tue, 9 Jan 2024 03:54:35 +0000 Subject: [PATCH] Added another major feature to Trace_Call: the ability to capture the source code lines that have been executed this is the first pass at writing this feature, and there are lots of areas for optimisation and performance improvements --- osbot_utils/utils/trace/Trace_Call.py | 6 +- osbot_utils/utils/trace/Trace_Call__Config.py | 2 +- .../utils/trace/Trace_Call__Handler.py | 62 ++++++++++++++++++- .../utils/trace/Trace_Call__Print_Traces.py | 18 +++++- osbot_utils/utils/trace/Trace_Call__Stack.py | 1 + .../utils/trace/Trace_Call__Stack_Node.py | 1 + .../utils/trace/Trace_Call__View_Model.py | 6 +- tests/utils/trace/test_Trace_Call.py | 2 +- tests/utils/trace/test_Trace_Call__Config.py | 6 +- tests/utils/trace/test_Trace_Call__Handler.py | 38 +++++++++++- .../trace/test_Trace_Call__Stack_Node.py | 2 + 11 files changed, 128 insertions(+), 16 deletions(-) diff --git a/osbot_utils/utils/trace/Trace_Call.py b/osbot_utils/utils/trace/Trace_Call.py index 85b3e9dc..a40a596a 100644 --- a/osbot_utils/utils/trace/Trace_Call.py +++ b/osbot_utils/utils/trace/Trace_Call.py @@ -12,19 +12,19 @@ def trace_calls(title=None, print=True, show_locals=False, source_code=False, ignore=None, include=None, max_string=None, show_types=False, show_caller=False, show_class=False, show_path=False, show_duration=False, duration_bigger_than=0, contains=None, show_internals=False, - extra_data=False): + extra_data=False, show_lines=False): def decorator(func): @wraps(func) def wrapper(*args, **kwargs): config_kwargs = dict(title=title, print_on_exit=print, print_locals=show_locals, - capture_source_code=source_code, ignore_start_with=ignore, + trace_capture_source_code=source_code, ignore_start_with=ignore, capture_start_with=include, print_max_string_length=max_string, show_parent_info=show_types, show_method_class=show_class, show_caller=show_caller, show_source_code_path=show_path, capture_duration=show_duration, print_duration= show_duration, with_duration_bigger_than=duration_bigger_than, trace_capture_contains=contains, trace_show_internals=show_internals, - capture_extra_data=extra_data) + capture_extra_data=extra_data, trace_capture_lines=show_lines) config = Trace_Call__Config(**config_kwargs) with Trace_Call(config=config): diff --git a/osbot_utils/utils/trace/Trace_Call__Config.py b/osbot_utils/utils/trace/Trace_Call__Config.py index a790a70e..0ca2b076 100644 --- a/osbot_utils/utils/trace/Trace_Call__Config.py +++ b/osbot_utils/utils/trace/Trace_Call__Config.py @@ -9,7 +9,7 @@ class Trace_Call__Config(Kwargs_To_Self): capture_extra_data : bool capture_frame : bool = True capture_frame_stats : bool - capture_source_code : bool + trace_capture_lines : bool = False capture_start_with : list ignore_start_with : list print_duration : bool diff --git a/osbot_utils/utils/trace/Trace_Call__Handler.py b/osbot_utils/utils/trace/Trace_Call__Handler.py index e3ecb87c..2679b928 100644 --- a/osbot_utils/utils/trace/Trace_Call__Handler.py +++ b/osbot_utils/utils/trace/Trace_Call__Handler.py @@ -1,4 +1,8 @@ +import inspect import linecache + +from osbot_utils.utils.Objects import obj_info + from osbot_utils.base_classes.Kwargs_To_Self import Kwargs_To_Self from osbot_utils.utils.trace.Trace_Call__Config import Trace_Call__Config from osbot_utils.utils.trace.Trace_Call__Stack import Trace_Call__Stack @@ -18,6 +22,53 @@ def __init__(self, **kwargs): self.trace_title = self.config.title or DEFAULT_ROOT_NODE_NODE_TITLE # Title for the trace root node self.stack.config = self.config + def add_default_root_node(self): + return self.stack.add_node(title=self.trace_title) + + def add_line(self, frame): + if self.config.trace_capture_lines: + if frame: + target_node = self.stack.top() # lines captured are added to the current top of the stack + if self.stack.top(): + target_node__func_name = target_node.func_name + target_node__module = target_node.module + frame_func_name = frame.f_code.co_name + frame_module = frame.f_globals.get("__name__", "") + if frame_func_name == target_node__func_name: + if frame_module == target_node__module: + return self.add_line_to_node(frame, target_node, 'line') + return False + + def add_line_to_node(self, frame, target_node, event): + if frame and target_node: + func_name = frame.f_code.co_name + module = frame.f_globals.get("__name__", "") + if event == 'call': # if this is a call we need to do the code below to get the actual method signature (and decorators) + function_name = frame.f_code.co_name + filename = frame.f_code.co_filename # Get the filename where the function is defined + start_line_number = frame.f_code.co_firstlineno # Get the starting line number + source_lines = inspect.getsource(frame.f_code).split('\n') + def_line_number = start_line_number # Try to find the actual 'def' line + for line in source_lines: + if line.strip().startswith('def ' + function_name): + break + def_line_number += 1 + else: + def_line_number = start_line_number # If the 'def' line wasn't found, default to the starting line + + line = linecache.getline(filename, def_line_number).rstrip() # todo: refactor this to not capture this info here, and to use the Ast_* utils to get a better source code mapping + else: + filename = frame.f_code.co_filename # get the filename + line_number = frame.f_lineno # get the current line number + line = linecache.getline(filename, line_number) # get the line + + if line: + self.stack.line_index += 1 + line_data = dict(index = self.stack.line_index, func_name=func_name, module=module, line = line.rstrip(), event=event) + target_node.lines.append(line_data) + return True + return False + def add_frame(self, frame): return self.handle_event__call(frame) @@ -30,7 +81,13 @@ def handle_event__call(self, frame): if self.config.capture_frame_stats: self.stats.log_frame(frame) if self.should_capture(frame): - return self.stack.add_frame(frame) + new_node = self.stack.add_frame(frame) + if self.config.trace_capture_lines: + self.add_line_to_node(frame, new_node,'call') + return new_node + + def handle_event__line(self, frame): + return self.add_line(frame) def handle_event__return(self, frame, return_value=None): @@ -93,7 +150,8 @@ def trace_calls(self, frame, event, arg): elif event == 'exception': self.stats.event_exception +=1 # for now don't handle exception events elif event == 'line': - self.stats.event_line +=1 # for now don't handle line events + self.handle_event__line(frame) + self.stats.event_line +=1 else: self.stats.event_unknown += 1 diff --git a/osbot_utils/utils/trace/Trace_Call__Print_Traces.py b/osbot_utils/utils/trace/Trace_Call__Print_Traces.py index f8d2c4d3..e7741582 100644 --- a/osbot_utils/utils/trace/Trace_Call__Print_Traces.py +++ b/osbot_utils/utils/trace/Trace_Call__Print_Traces.py @@ -75,7 +75,6 @@ def format_multiline(value, left_padding): indented_lines = [lines[0]] + [" " * (left_padding +1) + line for line in lines[1:]] return '\n│'.join(indented_lines) - # Second pass to print the keys and values aligned padding = " " * len(formatted_line) for key, (value, color) in formatted_data.items(): # Calculate the number of spaces needed for alignment @@ -84,6 +83,20 @@ def format_multiline(value, left_padding): value = format_multiline(value, len(var_name)- len(text_light_grey(''))) # this logic makes sure that the local's values are column aligned print(f'│{var_name}{color}{value}{RESET}') + def print_lines(self, lines, formatted_line): + if lines: + padding = " " * len(formatted_line) + for line in lines: + index = line.get('index') + #func_name = line.get('func_name') + #module = line.get('module') + event = line.get('event') + line = line.get('line') + if event == 'call': + print(f"{padding} {text_grey(index):12} {text_bold_green(line)}") + else: + print(f"{padding} {text_grey(index):12} {text_olive(line)}") + def print_traces(self, view_model, trace_capture_source_code = False): print() print("--------- CALL TRACER ----------") @@ -144,6 +157,9 @@ def print_traces(self, view_model, trace_capture_source_code = False): else: print(f"{text_bold(formatted_line)}{padding} {parent_info}") + if self.config.trace_capture_lines: + self.print_lines(item.get('lines'), f'{prefix}{tree_branch}') + if self.config.print_locals: self.formatted_local_data(locals, f'{prefix}{tree_branch}') diff --git a/osbot_utils/utils/trace/Trace_Call__Stack.py b/osbot_utils/utils/trace/Trace_Call__Stack.py index 2c4aa229..c369e6ef 100644 --- a/osbot_utils/utils/trace/Trace_Call__Stack.py +++ b/osbot_utils/utils/trace/Trace_Call__Stack.py @@ -13,6 +13,7 @@ class Trace_Call__Stack(Kwargs_To_Self): stack_data : list config : Trace_Call__Config root_node : Trace_Call__Stack_Node + line_index : int def __eq__(self, target): if self is target: diff --git a/osbot_utils/utils/trace/Trace_Call__Stack_Node.py b/osbot_utils/utils/trace/Trace_Call__Stack_Node.py index 89dfe2ba..f0b60f65 100644 --- a/osbot_utils/utils/trace/Trace_Call__Stack_Node.py +++ b/osbot_utils/utils/trace/Trace_Call__Stack_Node.py @@ -14,6 +14,7 @@ class Trace_Call__Stack_Node(Kwargs_To_Self): locals : dict frame : None func_name : str + lines : list module : str name : str source_code : str diff --git a/osbot_utils/utils/trace/Trace_Call__View_Model.py b/osbot_utils/utils/trace/Trace_Call__View_Model.py index 2e41e0a0..ae7894b7 100644 --- a/osbot_utils/utils/trace/Trace_Call__View_Model.py +++ b/osbot_utils/utils/trace/Trace_Call__View_Model.py @@ -23,7 +23,8 @@ def create_view_model(self, json_list, level=0, prefix="", view_model=None): components = node.name.split('.') duration = node.call_duration extra_data = node.extra_data - locals = node.locals + frame_locals = node.locals + lines = node.lines source_code = node.source_code source_code_caller = node.source_code_caller source_code_location = node.source_code_location @@ -55,7 +56,8 @@ def create_view_model(self, json_list, level=0, prefix="", view_model=None): 'extra_data' : extra_data , 'method_name' : method_name , 'method_parent' : method_parent , - 'locals' : locals , + 'lines' : lines , + 'locals' : frame_locals , # todo finish refactoring use of locals to frame_locals 'parent_info' : parent_info , 'prefix' : prefix , 'source_code' : source_code , diff --git a/tests/utils/trace/test_Trace_Call.py b/tests/utils/trace/test_Trace_Call.py index f8c2bd4a..32018cdd 100644 --- a/tests/utils/trace/test_Trace_Call.py +++ b/tests/utils/trace/test_Trace_Call.py @@ -58,7 +58,7 @@ def test___exit__(self): mock_stop.assert_called_with() self.trace_call.create_view_model() # this is populated by the self.trace_view_model.view_model object - assert self.trace_view_model.view_model == [{ 'duration': 0.0, 'extra_data': {}, 'prefix': '', 'tree_branch': '─── ', 'emoji': '📦 ', + assert self.trace_view_model.view_model == [{ 'duration': 0.0, 'extra_data': {}, 'lines': [],'prefix': '', 'tree_branch': '─── ', 'emoji': '📦 ', 'method_name': '', 'method_parent': '', 'parent_info': '', 'locals': {}, 'source_code': '', 'source_code_caller': '', 'source_code_location': ''}] diff --git a/tests/utils/trace/test_Trace_Call__Config.py b/tests/utils/trace/test_Trace_Call__Config.py index 97a5cf68..1ea87f6e 100644 --- a/tests/utils/trace/test_Trace_Call__Config.py +++ b/tests/utils/trace/test_Trace_Call__Config.py @@ -18,19 +18,19 @@ def test__kwargs__(self): 'capture_frame' : True , 'capture_frame_stats' : False , 'capture_locals' : True , - 'capture_source_code' : False , 'capture_start_with' : [] , 'ignore_start_with' : [] , 'print_locals' : False , 'print_max_string_length' : 100 , 'print_on_exit' : False , - 'print_duration' : False, + 'print_duration' : False, 'show_caller' : False , - 'show_method_class' : False , + 'show_method_class' : False , 'show_parent_info' : True , 'show_source_code_path' : False , 'title' : '' , 'trace_capture_all' : False , + 'trace_capture_lines' : False , 'trace_capture_source_code': False , 'trace_capture_start_with' : [] , 'trace_capture_contains' : [] , diff --git a/tests/utils/trace/test_Trace_Call__Handler.py b/tests/utils/trace/test_Trace_Call__Handler.py index 5b4d3b3b..26565dd1 100644 --- a/tests/utils/trace/test_Trace_Call__Handler.py +++ b/tests/utils/trace/test_Trace_Call__Handler.py @@ -15,6 +15,7 @@ from osbot_utils.utils.trace.Trace_Call__Stack import Trace_Call__Stack from osbot_utils.utils.trace.Trace_Call__Stack_Node import Trace_Call__Stack_Node from osbot_utils.utils.trace.Trace_Call__Stats import Trace_Call__Stats +from tests.utils.trace.test_Trace_Call__Stack import Frames_Test_Data class test_Trace_Call__Handler(TestCase): @@ -76,6 +77,38 @@ def test_handle_event__call(self): assert len(stack) == 1 assert new_node == Trace_Call__Stack_Node(call_index=1, frame=sample_frame, func_name='test_handle_event__call', name= 'test_Trace_Call__Handler.test_Trace_Call__Handler.test_handle_event__call', module='test_Trace_Call__Handler') + def test_handle_event__line(self): + config = self.handler.config + handle_event__call = self.handler.handle_event__call + handle_event__line = self.handler.handle_event__line + stack = self.handler.stack + test_frames = Frames_Test_Data() + frame_1 = test_frames.frame_1 + frame_2 = test_frames.frame_2 + frame_3 = test_frames.frame_3 + + # case 1: invoke with bad data + assert handle_event__line(frame=None) is False + + # case 2: invoke with valid frame by no stack + assert len(stack) == 0 + assert handle_event__line(frame=frame_1) is False + + + # # case 3: invoke with valid frame and valid stack + # + self.handler.add_default_root_node() + + assert len(stack) == 1 + assert stack[0].data() == Trace_Call__Stack_Node(name=DEFAULT_ROOT_NODE_NODE_TITLE).data() + config.trace_capture_lines = True + config.trace_capture_all = True + + handle_event__call(frame=frame_1) # simulate being inside a function + top_stack = self.handler.stack.top() + assert handle_event__line(frame=frame_1) is not None # add line using handle_event__line + #todo: finish test and add more cases + def test_handle_event__return(self): config = self.handler.config @@ -89,11 +122,10 @@ def test_handle_event__return(self): # case 2: invoke with valid frame by no stack assert len(stack) == 0 - assert handle_event__return(frame=None) is False + assert handle_event__return(frame=sample_frame) is False # case 3: invoke with valid frame and valid stack - - self.handler.stack.add_node(title=DEFAULT_ROOT_NODE_NODE_TITLE) # add a root node + self.handler.add_default_root_node() assert len(stack) == 1 assert stack[0].data() == Trace_Call__Stack_Node(name=DEFAULT_ROOT_NODE_NODE_TITLE).data() diff --git a/tests/utils/trace/test_Trace_Call__Stack_Node.py b/tests/utils/trace/test_Trace_Call__Stack_Node.py index 2de87ecf..4a06e8d5 100644 --- a/tests/utils/trace/test_Trace_Call__Stack_Node.py +++ b/tests/utils/trace/test_Trace_Call__Stack_Node.py @@ -19,6 +19,7 @@ def test___locals__(self): 'extra_data' : {} , 'frame' : None, 'func_name' : '' , + 'lines' : [] , 'locals' : {} , 'name' : '' , 'module' : '' , @@ -44,6 +45,7 @@ def test_data(self): 'call_start' : 0 , 'extra_data' : {} , "name" : name , + 'lines' : [] , 'locals' : {} , 'frame' : None , "children" : [] ,