Extract actual function duration using sched_switch events for profiling

tracetools_analysis/tracetools_analysis/data_model/profile.py

@@ -20,7 +20,12 @@ from . import DataModel
 
 
 class ProfileDataModel(DataModel):
-    """Container to model pre-processed profiling data for analysis."""
+    """
+    Container to model pre-processed profiling data for analysis.
+
+    Duration is the time difference between the function entry and the function exit.
+    Actual duration is the actual time spent executing the function (or a child function).
+    """
 
     def __init__(self) -> None:
         """Constructor."""
@@ -32,6 +37,7 @@ class ProfileDataModel(DataModel):
             'parent_name',
             'start_timestamp',
             'duration',
+            'actual_duration',
         ])
 
     def add_duration(
@@ -42,6 +48,7 @@ class ProfileDataModel(DataModel):
         parent_name: str,
         start_timestamp: int,
         duration: int,
+        actual_duration: int,
     ) -> None:
         data = {
             'tid': tid,
@@ -50,6 +57,7 @@ class ProfileDataModel(DataModel):
             'parent_name': parent_name,
             'start_timestamp': start_timestamp,
             'duration': duration,
+            'actual_duration': actual_duration,
         }
         self.times = self.times.append(data, ignore_index=True)
 

tracetools_analysis/tracetools_analysis/processor/profile.py

@@ -18,7 +18,6 @@ from collections import defaultdict
 from typing import Dict
 from typing import List
 from typing import Tuple
-from typing import Type
 from typing import Union
 
 from tracetools_read import get_field
@@ -36,6 +35,7 @@ class ProfileHandler(EventHandler):
     It uses the following events:
         * lttng_ust_cyg_profile_fast:func_entry
         * lttng_ust_cyg_profile_fast:func_exit
+        * sched_switch
     """
 
     FUNCTIONS = {
@@ -59,6 +59,8 @@ class ProfileHandler(EventHandler):
                 self._handle_function_entry,
             'lttng_ust_cyg_profile_fast:func_exit':
                 self._handle_function_exit,
+            'sched_switch':
+                self._handle_sched_switch,
         }
         super().__init__(handler_map=handler_map, **kwargs)
 
@@ -67,30 +69,55 @@ class ProfileHandler(EventHandler):
 
         # Temporary buffers
         # tid ->
-        #   (list of functions currently executing (ordered by relative depth),
+        #   list:[
-        #    start timestamp of the function)
+        #           functions currently executing (ordered by relative depth), with info:
-        self._current_funcs: Dict[int, List[Tuple[str, int]]] = defaultdict(list)
+        #           [
-
+        #               function name,
-        # TODO get debug_info from babeltrace for
+        #               start timestamp,
-        # lttng_ust_cyg_profile_fast:func_entry events
+        #               last execution start timestamp of the function,
-        # (or resolve { address -> function } name another way)
+        #               total duration,
-        self.address_to_func = {
+        #           ]
-            int('0x7F6CD676CDB4', 16): 'get_next_ready_executable',
+        #        ]
-            int('0x7F6CD676BC54', 16): 'wait_for_work',
+        self._current_funcs: Dict[int, List[List[Union[str, int]]]] = defaultdict(list)
-            int('0x7F6CD678D0F8', 16): 'collect_entities',
-        }
 
     def get_data_model(self) -> ProfileDataModel:
         return self._data
 
+    def _handle_sched_switch(
+        self, event: Dict, metadata: EventMetadata
+    ) -> None:
+        timestamp = metadata.timestamp
+        # If function(s) currently running stop executing
+        prev_tid = get_field(event, 'prev_tid')
+        if prev_tid in self._current_funcs:
+            # Increment durations using last start timestamp
+            for info in self._current_funcs.get(prev_tid):
+                last_start = info[2]
+                total_duration = info[3]
+                total_duration += timestamp - last_start
+                info[2] = None
+                info[3] = total_duration
+        # If stopped function(s) start(s) executing again
+        next_tid = get_field(event, 'next_tid')
+        if next_tid in self._current_funcs:
+            # Set last start timestamp to now
+            for info in self._current_funcs.get(next_tid):
+                assert info[2] is None
+                info[2] = timestamp
+
     def _handle_function_entry(
         self, event: Dict, metadata: EventMetadata
     ) -> None:
         function_name = self._get_function_name(event)
         assert function_name is not None, f'cannot resolve function name for event: {event}'
-        # Push function data to stack
+        # Push function data to stack, setting both timestamps to now
         self._current_funcs[metadata.tid].append(
-            (metadata.timestamp, function_name)
+            [
+                function_name,
+                metadata.timestamp,
+                metadata.timestamp,
+                0,
+            ]
         )
 
     def _handle_function_exit(
@@ -100,17 +127,23 @@ class ProfileHandler(EventHandler):
         tid = metadata.tid
         tid_functions = self._current_funcs[tid]
         function_depth = len(tid_functions) - 1
-        (start_timestamp, start_function_name) = tid_functions.pop()
+        info = tid_functions.pop()
+        function_name = info[0]
+        start_timestamp = info[1]
+        last_start_timestamp = info[2]
+        total_duration = info[3]
         # Add to data model
-        parent_name = tid_functions[-1][1] if function_depth > 0 else None
+        parent_name = tid_functions[-1][0] if function_depth > 0 else None
         duration = metadata.timestamp - start_timestamp
+        actual_duration = (metadata.timestamp - last_start_timestamp) + total_duration
         self._data.add_duration(
             tid,
             function_depth,
-            start_function_name,
+            function_name,
             parent_name,
             start_timestamp,
-            duration
+            duration,
+            actual_duration,
         )
 
     def _get_function_name(
@@ -123,5 +156,12 @@ class ProfileHandler(EventHandler):
     def _resolve_function_address(
         self, address: int
     ) -> Union[str, None]:
-        # TODO get from trace/binaries
+        # TODO get debug_info from babeltrace for
-        return self.address_to_func.get(address, None)
+        # lttng_ust_cyg_profile_fast:func_entry events
+        # (or resolve { address -> function } name another way)
+        address_to_func = {
+            int('0x7F3418EC4DB4', 16): 'get_next_ready_executable',
+            int('0x7F3418EC3C54', 16): 'wait_for_work',
+            int('0x7F3418EE50F8', 16): 'collect_entities',
+        }
+        return address_to_func.get(address, None)