added major feature to Trace_Call__Handle: capture the start, end and…

… duration timings of a call

fixed tests to reflect new feature and required config & vars changes

osbot_utils/utils/trace/Trace_Call__Config.py

@@ -5,6 +5,7 @@
 class Trace_Call__Config(Kwargs_To_Self):
     title                     : str
     capture_locals            : bool = True
+    capture_duration          : bool = False
     capture_frame             : bool = True
     capture_frame_stats       : bool = False
     capture_source_code       : bool

osbot_utils/utils/trace/Trace_Call__Stack.py

@@ -1,4 +1,5 @@
 import linecache
+import time
 
 from osbot_utils.base_classes.Kwargs_To_Self import Kwargs_To_Self
 from osbot_utils.utils.trace.Trace_Call__Config import Trace_Call__Config
@@ -9,6 +10,7 @@ class Trace_Call__Stack(Kwargs_To_Self):
     call_index : int
     stack_data : list
     config     : Trace_Call__Config
+    root_node  : Trace_Call__Stack_Node
 
     def __eq__(self, target):
         if self is target:
@@ -51,6 +53,8 @@ def add_stack_node(self, stack_node : Trace_Call__Stack_Node, frame=None):
         if type(stack_node) is Trace_Call__Stack_Node:
             if self.stack_data:                                             # if there are items in the stack
                 self.top().children.append(stack_node)                      # add an xref to the new node to the children of the top node
+            else:
+                self.root_node = stack_node                                 # if not this is the first node and capture it as a root node
             self.stack_data.append(stack_node)                              # append the new node to the stack
             return True
         return False
@@ -74,6 +78,8 @@ def create_stack_node(self, frame, full_name, source_code, call_index):
                 new_node.frame = frame
             if self.config.capture_locals:
                 new_node.locals = frame.f_locals
+            if self.config.capture_duration:
+                new_node.call_start = time.perf_counter()
         return new_node
 
     def map_source_code(self, frame):
@@ -115,12 +121,20 @@ def new_stack_node(self, name):
     def nodes(self):
         return self.stack_data
 
-    def pop(self, frame):
+    def remove_from_top(self, top_node):
+        if self.config.capture_duration:
+            top_node.call_end     = time.perf_counter()
+            top_node.call_duration = top_node.call_end - top_node.call_start
+        self.stack_data.pop()
+        return True
+    def pop(self, target):
         top_node = self.top()
-        if frame and top_node :
-            if frame is top_node.frame:     # only if they match, pop the stack (since we are only capturing a subset of the stack
-                self.stack_data.pop()
-                return True
+        if target and top_node :
+            if type(target) is Trace_Call__Stack_Node:      # handle the case when target is Trace_Call__Stack_Node
+                if target == top_node:                      # if they match, pop the stack (since we are only capturing a subset of the stack)
+                    return self.remove_from_top(top_node)
+            elif target is top_node.frame:                  # if not assume target is a frame
+                return self.remove_from_top(top_node)               # if they match, pop the stack (since we are only capturing a subset of the stack)
         return False
 
     def push(self, frame):

osbot_utils/utils/trace/Trace_Call__Stack_Node.py

@@ -4,7 +4,10 @@
 
 
 class Trace_Call__Stack_Node(Kwargs_To_Self):
+    call_duration       : float
+    call_end            : float
     call_index          : int
+    call_start          : float
     children            : list
     locals              : dict
     frame               : None

tests/utils/trace/test_Trace_Call_Stats.py

@@ -25,12 +25,15 @@ def test___kwargs__(self):
         assert Trace_Call__Stats().__locals__      () == expected_locals
 
     def test_log_frame(self):
-        print()
         test_frames = Frames_Test_Data()
         stats           = self.trace_call_stats
 
         stats.log_frame(test_frames.frame_1)
         stats.log_frame(test_frames.frame_2)
 
-        pprint(stats.frames_stats())
+        assert stats.frames_stats() == { 'tests':
+                                             { 'utils':
+                                                   { 'trace':
+                                                         { 'test_Trace_Call__Stack': { 'get_frame_1': 1, 'get_frame_2': 1}}}}}
+
 

tests/utils/trace/test_Trace_Call__Config.py

@@ -13,7 +13,8 @@ def test__init__(self):
         assert type(default_value(Trace_Call__Config)) is Trace_Call__Config
 
     def test__kwargs__(self):
-        expected_data = { 'capture_frame'            : True  ,
+        expected_data = { 'capture_duration'         : False ,
+                          'capture_frame'            : True  ,
                           'capture_frame_stats'      : False ,
                           'capture_locals'           : True  ,
                           'capture_source_code'      : False ,

tests/utils/trace/test_Trace_Call__Stack.py

@@ -7,7 +7,7 @@
 from osbot_utils.utils.Dev import pprint
 from osbot_utils.utils.Functions import method_line_number
 
-from osbot_utils.utils.Misc import random_string, random_int
+from osbot_utils.utils.Misc import random_string, random_int, wait_for
 from osbot_utils.utils.trace.Trace_Call__Handler import DEFAULT_ROOT_NODE_NODE_TITLE
 
 from osbot_utils.utils.trace.Trace_Call__Stack import Trace_Call__Stack
@@ -164,6 +164,66 @@ def test_map_source_code(self):
                                  'source_code_location': source_code_location                           }
 
 
+    def test_push_and_pop(self):
+        self.stack.config.capture_duration = True
+        test_data = Frames_Test_Data()
+        frame_1   = test_data.frame_1
+        frame_2   = test_data.frame_2
+        frame_3   = test_data.frame_3
+        stack = self.stack
+        assert stack == []
+
+        node_1 = stack.push(frame_1)       ; assert stack == [node_1]
+        node_2 = stack.push(frame_2)       ; assert stack == [node_1,node_2]
+        node_3 = stack.push(frame_3)       ; assert stack == [node_1, node_2, node_3]
+        node_4 = stack.push(frame_1)       ; assert stack == [node_1, node_2, node_3, node_4]
+
+        assert stack.root_node == node_1
+        assert stack.pop(node_1 ) is False ; assert stack == [node_1, node_2, node_3, node_4]
+        assert stack.pop(node_2 ) is False ; assert stack == [node_1, node_2, node_3, node_4]
+        assert stack.pop(node_3 ) is False ; assert stack == [node_1, node_2, node_3, node_4]
+        assert stack.pop(node_4 ) is True  ; assert stack == [node_1, node_2, node_3        ]
+
+        node_5 = stack.push(frame_3)       ; assert stack == [node_1, node_2, node_3, node_5]
+        assert stack.pop(node_1 ) is False ; assert stack == [node_1, node_2, node_3, node_5]
+        assert stack.pop(node_2 ) is False ; assert stack == [node_1, node_2, node_3, node_5]
+        assert stack.pop(node_3 ) is False ; assert stack == [node_1, node_2, node_3, node_5]
+        assert stack.pop(node_5 ) is True  ; assert stack == [node_1, node_2, node_3]
+
+        assert stack.pop(frame_1) is False ; assert stack == [node_1, node_2, node_3        ]
+        assert stack.pop(frame_2) is False ; assert stack == [node_1, node_2, node_3        ]
+        assert stack.pop(frame_3) is True  ; assert stack == [node_1, node_2,               ]
+
+        node_6 = stack.push(frame_1)       ; assert stack == [node_1, node_2, node_6        ]
+        assert stack.pop(frame_3) is False ; assert stack == [node_1, node_2, node_6        ]
+        assert stack.pop(frame_2) is False ; assert stack == [node_1, node_2, node_6        ]
+        assert stack.pop(frame_1) is True  ; assert stack == [node_1, node_2                ]
+        assert stack.pop(frame_2) is True  ; assert stack == [node_1                        ]
+        assert stack.pop(frame_1) is True  ; assert stack == [                            ]
+
+        assert stack.pop(frame_1) is False
+        assert stack.pop(frame_2) is False
+        assert stack.pop(frame_3) is False
+
+        assert stack           == []
+        assert stack.root_node == node_1
+
+        assert node_1.children == [node_2        ]
+        assert node_2.children == [node_3, node_6]
+        assert node_3.children == [node_4, node_5]
+        assert node_4.children == [              ]
+        assert node_5.children == [              ]
+        assert node_6.children == [              ]
+
+        assert node_1.frame == frame_1
+        assert node_2.frame == frame_2
+        assert node_3.frame == frame_3
+        assert node_4.frame == frame_1
+        assert node_5.frame == frame_3
+        assert node_6.frame == frame_1
+
+        assert node_1.call_start < node_1.call_end
+        assert node_1.call_duration < 0.0003                # these values should be very quick
 
     def test_stack_top(self):
         test_data = Frames_Test_Data()

tests/utils/trace/test_Trace_Call__Stack_Node.py

@@ -11,7 +11,10 @@ def setUp(self):
         self.stack_node = Trace_Call__Stack_Node()
 
     def test___locals__(self):
-        expected_values = { 'call_index'            : 0   ,
+        expected_values = { 'call_duration'         : 0   ,
+                            'call_end'              : 0   ,
+                            'call_index'            : 0   ,
+                            'call_start'            : 0   ,
                             'children'              : []  ,
                             'frame'                 : None,
                             'func_name'             : ''  ,
@@ -34,12 +37,15 @@ def test_data(self):
 
         stack_node  = Trace_Call__Stack_Node(call_index=call_index, name=name)
 
-        assert stack_node.__locals__() == { "name"                : name       ,
+        assert stack_node.__locals__() == { 'call_duration'       : 0          ,
+                                            'call_end'            : 0          ,
+                                            'call_index'          : call_index ,
+                                            'call_start'          : 0          ,
+                                            "name"                : name       ,
                                             'locals'              : {}         ,
                                             'frame'               : None       ,
                                             "children"            : []         ,
                                             'func_name'           : ''         ,
-                                            "call_index"          : call_index ,
                                             'module'              : ''         ,
                                             'source_code'         : ''         ,
                                             'source_code_caller'  : ''         ,

tests/utils/trace/test_Trace_Files.py

@@ -40,35 +40,6 @@ def test___init__(self):
         assert Trace_Files(files=[]       ).files == []
         assert Trace_Files(files=['a,b,c']).files == ['a,b,c']
 
-    @pytest.mark.skip("needs fixing after the refactoring of the Trace_Call__Handler")
-    def test_trace_call(self):
-
-        def method_a():
-            method_b()
-
-        def method_b() :
-            print('in method_b')
-
-        kwargs = {"capture_start_with": ['t','o']}
-        with Trace_Files(**kwargs) as trace_file:
-            #trace_file.config.print_on_exit = True                          # To hit the 'print_traces' line in __exit__
-            pprint(str_md5('aaa'))
-            method_a()
-            method_b()
-
-        assert len(unique(trace_file.files)) > 1
-
-        # #pprint(unique(trace_file.files))
-        #
-        # ast_merge = Ast_Merge()
-        # for file in unique(trace_file.files):
-        #     print(file)
-        #     ast_merge.merge_file(file)
-        #
-        # print(ast_merge.source_code())
-
-
-