niklas/tracetools_analysis
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Merge branch 'executor-profiling' into 'master'

Browse source 
Executor profiling

See merge request micro-ROS/ros_tracing/tracetools_analysis!16
This commit is contained in:
Christophe Bedard 2019-08-15 13:05:56 +00:00
commit 34e8442f06
14 changed files with 290 additions and 711 deletions
Download patch file Download diff file Expand all files Collapse all files

5
tracetools_analysis/analysis/callback_duration.ipynb
View file

@ -71,8 +71,7 @@
"pickle_path = os.path.expanduser(pickle_path)\n",
"events = load_pickle(pickle_path)\n",
"handler = Ros2Handler.process(events)\n",
"data_model = handler.get_data_model()\n",
"#data_model.print_model()"
"#handler.data.print_model()"
]
},
{
@ -553,7 +552,7 @@
}
],
"source": [
"data_util = utils.RosDataModelUtil(data_model)\n",
"data_util = utils.RosDataModelUtil(handler.data)\n",
"\n",
"callback_symbols = data_util.get_callback_symbols()\n",
"\n",

632
tracetools_analysis/analysis/profile.ipynb
View file

File diff suppressed because one or more lines are too long

6
tracetools_analysis/launch/profile.launch.py
View file

@ -27,6 +27,10 @@ def generate_launch_description():
events_ust=[
'lttng_ust_cyg_profile_fast:func_entry',
'lttng_ust_cyg_profile_fast:func_exit',
'lttng_ust_statedump:start',
'lttng_ust_statedump:end',
'lttng_ust_statedump:bin_info',
'lttng_ust_statedump:build_id',
] + DEFAULT_EVENTS_ROS,
events_kernel=[
'sched_switch',
@ -34,7 +38,7 @@ def generate_launch_description():
),
Node(
package='ros_performance',
node_executable='nopub',
node_executable='ros',
output='screen',
),
])

114
tracetools_analysis/test/tracetools_analysis/test_data_model_util.py Normal file
View file

@ -0,0 +1,114 @@
# Copyright 2019 Robert Bosch GmbH
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
from datetime import datetime
from datetime import timezone
import unittest
from pandas import DataFrame
from pandas.util.testing import assert_frame_equal
from tracetools_analysis.utils import DataModelUtil
class TestDataModelUtil(unittest.TestCase):
def __init__(self, *args) -> None:
super().__init__(
*args,
)
def test_convert_time_columns(self) -> None:
input_df = DataFrame(
data=[
{
'timestamp': 1565177400000*1000000,
'random_thingy': 'abc',
'some_duration': 3000000,
'const_number': 123456,
},
{
'timestamp': 946684800000*1000000,
'random_thingy': 'def',
'some_duration': 10000000,
'const_number': 789101112,
},
],
)
expected_df = DataFrame(
data=[
{
'timestamp': datetime(2019, 8, 7, 11, 30, 0, tzinfo=timezone.utc),
'random_thingy': 'abc',
'some_duration': 3,
'const_number': 123456,
},
{
'timestamp': datetime(2000, 1, 1, 0, 0, 0, tzinfo=timezone.utc),
'random_thingy': 'def',
'some_duration': 10,
'const_number': 789101112,
},
],
)
result_df = DataModelUtil.convert_time_columns(
input_df,
['some_duration'],
['timestamp'],
inplace=True,
)
assert_frame_equal(result_df, expected_df, check_dtype=False)
def test_compute_column_difference(self) -> None:
input_df = DataFrame(
data=[
{
'a': 10,
'b': 13,
'c': 1,
},
{
'a': 1,
'b': 3,
'c': 69,
},
],
)
expected_df = DataFrame(
data=[
{
'a': 10,
'b': 13,
'c': 1,
'diff': 3,
},
{
'a': 1,
'b': 3,
'c': 69,
'diff': 2,
},
],
)
DataModelUtil.compute_column_difference(
input_df,
'b',
'a',
'diff',
)
assert_frame_equal(input_df, expected_df)
if __name__ == '__main__':
unittest.main()

24
tracetools_analysis/test/tracetools_analysis/test_profile_handler.py
View file

@ -270,6 +270,13 @@ expected = [
]
address_to_func = {
'0xfA': '0xfA',
'0xfAA': '0xfAA',
'0xfB': '0xfB',
}
class TestProfileHandler(unittest.TestCase):
def __init__(self, *args) -> None:
@ -292,27 +299,26 @@ class TestProfileHandler(unittest.TestCase):
return expected_df.append(expected_data, ignore_index=True)
@staticmethod
def add_fake_fields(events: List[DictEvent]) -> None:
# Actual value does not matter here; it just needs to be there
def transform_fake_fields(events: List[DictEvent]) -> None:
for event in events:
# Actual value does not matter here; it just needs to be there
event['cpu_id'] = 69
if event['_name'] == 'lttng_ust_cyg_profile_fast:func_entry':
# The 'addr' field is supposed to be an int
event['addr'] = ProfileHandler.addr_to_int(event['addr'])
@classmethod
def setUpClass(cls):
cls.add_fake_fields(input_events)
cls.transform_fake_fields(input_events)
cls.expected = cls.build_expected_df(expected)
cls.handler = ProfileHandler()
cls.handler = ProfileHandler(address_to_func=address_to_func)
cls.processor = Processor(cls.handler)
cls.processor.process(input_events)
def test_profiling(self) -> None:
handler = self.__class__.handler
expected_df = self.__class__.expected
result_df = handler.get_data_model().times
print('RESULT')
print(result_df.to_string())
print('EXPECTED')
print(expected_df.to_string())
result_df = handler.data.times
assert_frame_equal(result_df, expected_df)

2
tracetools_analysis/tracetools_analysis/data_model/cpu_time.py
View file

@ -49,7 +49,7 @@ class CpuTimeDataModel(DataModel):
'duration': duration,
'cpu_id': cpu_id,
}
self.times = self.times.append(data, ignore_index=True)
self.times.loc[len(self.times.index)] = data
def print_model(self) -> None:
"""Debug method to print every contained df."""

2
tracetools_analysis/tracetools_analysis/data_model/profile.py
View file

@ -59,7 +59,7 @@ class ProfileDataModel(DataModel):
'duration': duration,
'actual_duration': actual_duration,
}
self.times = self.times.append(data, ignore_index=True)
self.times.loc[len(self.times.index)] = data
def print_model(self) -> None:
"""Debug method to print every contained df."""

2
tracetools_analysis/tracetools_analysis/data_model/ros.py
View file

@ -143,7 +143,7 @@ class RosDataModel(DataModel):
'duration': duration,
'intra_process': intra_process,
}
self.callback_instances = self.callback_instances.append(data, ignore_index=True)
self.callback_instances.loc[len(self.callback_instances.index)] = data
def print_model(self) -> None:
"""Debug method to print every contained df."""

2
tracetools_analysis/tracetools_analysis/process.py
View file

@ -41,4 +41,4 @@ def main():
time_diff = time.time() - start_time
print(f'processed {len(events)} events in {time_diff * 1000:.2f} ms')
ros2_handler.get_data_model().print_model()
ros2_handler.data.print_model()

12
tracetools_analysis/tracetools_analysis/processor/__init__.py
View file

@ -104,7 +104,7 @@ class EventHandler(Dependant):
Base event handling class.
Provides handling functions for some events, depending on the name.
To be subclassed.
Passes that on to a data model. To be subclassed.
"""
def __init__(
@ -130,10 +130,20 @@ class EventHandler(Dependant):
"""Get the handler functions map."""
return self._handler_map
@property
def data(self) -> None:
"""Get the data model."""
return None
def register_processor(self, processor: 'Processor') -> None:
"""Register processor with this `EventHandler` so that it can query other handlers."""
self.processor = processor
@staticmethod
def int_to_hex_str(addr: int) -> str:
"""Format an `int` into an hex `str`."""
return f'0x{addr:X}'
@classmethod
def process(cls, events: List[DictEvent], **kwargs) -> 'EventHandler':
"""

14
tracetools_analysis/tracetools_analysis/processor/cpu_time.py
View file

@ -39,16 +39,20 @@ class CpuTimeHandler(EventHandler):
'sched_switch':
self._handle_sched_switch,
}
super().__init__(handler_map=handler_map, **kwargs)
super().__init__(
handler_map=handler_map,
**kwargs,
)
self._data = CpuTimeDataModel()
self._data_model = CpuTimeDataModel()
# Temporary buffers
# cpu_id -> start timestamp of the running thread
self._cpu_start: Dict[int, int] = {}
def get_data_model(self) -> CpuTimeDataModel:
return self._data
@property
def data(self) -> CpuTimeDataModel:
return self._data_model
def _handle_sched_switch(
self, event: Dict, metadata: EventMetadata
@ -62,6 +66,6 @@ class CpuTimeHandler(EventHandler):
if prev_timestamp is not None:
prev_tid = get_field(event, 'prev_tid')
duration = timestamp - prev_timestamp
self._data.add_duration(prev_tid, prev_timestamp, duration, cpu_id)
self.data.add_duration(prev_tid, prev_timestamp, duration, cpu_id)
# Set start timestamp of next thread
self._cpu_start[cpu_id] = timestamp

44
tracetools_analysis/tracetools_analysis/processor/profile.py
View file

@ -35,12 +35,22 @@ class ProfileHandler(EventHandler):
* lttng_ust_cyg_profile_fast:func_entry
* lttng_ust_cyg_profile_fast:func_exit
* sched_switch
TODO get debug_info from babeltrace for
lttng_ust_cyg_profile_fast:func_entry events
(or resolve { address -> function } name another way)
"""
def __init__(
self,
address_to_func: Dict[Union[int, str], str] = {},
**kwargs,
) -> None:
"""
Constructor.
:param address_to_func: the mapping from function address (`int` or hex `str`) to name
"""
handler_map = {
'lttng_ust_cyg_profile_fast:func_entry':
self._handle_function_entry,
@ -49,9 +59,15 @@ class ProfileHandler(EventHandler):
'sched_switch':
self._handle_sched_switch,
}
super().__init__(handler_map=handler_map, **kwargs)
super().__init__(
handler_map=handler_map,
**kwargs,
)
self._data = ProfileDataModel()
self._data_model = ProfileDataModel()
self._address_to_func = {
self.addr_to_int(addr): name for addr, name in address_to_func.items()
}
# Temporary buffers
# tid ->
@ -66,8 +82,14 @@ class ProfileHandler(EventHandler):
# ]
self._current_funcs: Dict[int, List[List[Union[str, int]]]] = defaultdict(list)
def get_data_model(self) -> ProfileDataModel:
return self._data
@staticmethod
def addr_to_int(addr: Union[int, str]) -> int:
"""Transform an address into an `int` if it's a hex `str`."""
return int(addr, 16) if isinstance(addr, str) else addr
@property
def data(self) -> ProfileDataModel:
return self._data_model
def _handle_sched_switch(
self, event: Dict, metadata: EventMetadata
@ -119,7 +141,7 @@ class ProfileHandler(EventHandler):
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(
self.data.add_duration(
tid,
function_depth,
function_name,
@ -135,18 +157,10 @@ class ProfileHandler(EventHandler):
address = get_field(event, 'addr')
resolution = self._resolve_function_address(address)
if resolution is None:
resolution = str(address)
resolution = self.int_to_hex_str(address)
return resolution
def _resolve_function_address(
self, address: int
) -> Union[str, None]:
# TODO get debug_info from babeltrace for
# 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)
return self._address_to_func.get(address, None)

36
tracetools_analysis/tracetools_analysis/processor/ros2.py
View file

@ -63,15 +63,19 @@ class Ros2Handler(EventHandler):
'ros2:callback_end':
self._handle_callback_end,
}
super().__init__(handler_map=handler_map, **kwargs)
super().__init__(
handler_map=handler_map,
**kwargs,
)
self._data = RosDataModel()
self._data_model = RosDataModel()
# Temporary buffers
self._callback_instances = {}
def get_data_model(self) -> RosDataModel:
return self._data
@property
def data(self) -> RosDataModel:
return self._data_model
def _handle_rcl_init(
self, event: Dict, metadata: EventMetadata
@ -80,7 +84,7 @@ class Ros2Handler(EventHandler):
timestamp = metadata.timestamp
pid = metadata.pid
version = get_field(event, 'version')
self._data.add_context(context_handle, timestamp, pid, version)
self.data.add_context(context_handle, timestamp, pid, version)
def _handle_rcl_node_init(
self, event: Dict, metadata: EventMetadata
@ -91,7 +95,7 @@ class Ros2Handler(EventHandler):
rmw_handle = get_field(event, 'rmw_handle')
name = get_field(event, 'node_name')
namespace = get_field(event, 'namespace')
self._data.add_node(handle, timestamp, tid, rmw_handle, name, namespace)
self.data.add_node(handle, timestamp, tid, rmw_handle, name, namespace)
def _handle_rcl_publisher_init(
self, event: Dict, metadata: EventMetadata
@ -102,7 +106,7 @@ class Ros2Handler(EventHandler):
rmw_handle = get_field(event, 'rmw_publisher_handle')
topic_name = get_field(event, 'topic_name')
depth = get_field(event, 'queue_depth')
self._data.add_publisher(handle, timestamp, node_handle, rmw_handle, topic_name, depth)
self.data.add_publisher(handle, timestamp, node_handle, rmw_handle, topic_name, depth)
def _handle_subscription_init(
self, event: Dict, metadata: EventMetadata
@ -113,7 +117,7 @@ class Ros2Handler(EventHandler):
rmw_handle = get_field(event, 'rmw_subscription_handle')
topic_name = get_field(event, 'topic_name')
depth = get_field(event, 'queue_depth')
self._data.add_subscription(handle, timestamp, node_handle, rmw_handle, topic_name, depth)
self.data.add_subscription(handle, timestamp, node_handle, rmw_handle, topic_name, depth)
def _handle_rclcpp_subscription_callback_added(
self, event: Dict, metadata: EventMetadata
@ -121,7 +125,7 @@ class Ros2Handler(EventHandler):
handle = get_field(event, 'subscription_handle')
timestamp = metadata.timestamp
callback_object = get_field(event, 'callback')
self._data.add_callback_object(handle, timestamp, callback_object)
self.data.add_callback_object(handle, timestamp, callback_object)
def _handle_rcl_service_init(
self, event: Dict, metadata: EventMetadata
@ -131,7 +135,7 @@ class Ros2Handler(EventHandler):
node_handle = get_field(event, 'node_handle')
rmw_handle = get_field(event, 'rmw_service_handle')
service_name = get_field(event, 'service_name')
self._data.add_service(handle, timestamp, node_handle, rmw_handle, service_name)
self.data.add_service(handle, timestamp, node_handle, rmw_handle, service_name)
def _handle_rclcpp_service_callback_added(
self, event: Dict, metadata: EventMetadata
@ -139,7 +143,7 @@ class Ros2Handler(EventHandler):
handle = get_field(event, 'service_handle')
timestamp = metadata.timestamp
callback_object = get_field(event, 'callback')
self._data.add_callback_object(handle, timestamp, callback_object)
self.data.add_callback_object(handle, timestamp, callback_object)
def _handle_rcl_client_init(
self, event: Dict, metadata: EventMetadata
@ -149,7 +153,7 @@ class Ros2Handler(EventHandler):
node_handle = get_field(event, 'node_handle')
rmw_handle = get_field(event, 'rmw_client_handle')
service_name = get_field(event, 'service_name')
self._data.add_client(handle, timestamp, node_handle, rmw_handle, service_name)
self.data.add_client(handle, timestamp, node_handle, rmw_handle, service_name)
def _handle_rcl_timer_init(
self, event: Dict, metadata: EventMetadata
@ -158,7 +162,7 @@ class Ros2Handler(EventHandler):
timestamp = metadata.timestamp
period = get_field(event, 'period')
tid = metadata.tid
self._data.add_timer(handle, timestamp, period, tid)
self.data.add_timer(handle, timestamp, period, tid)
def _handle_rclcpp_timer_callback_added(
self, event: Dict, metadata: EventMetadata
@ -166,7 +170,7 @@ class Ros2Handler(EventHandler):
handle = get_field(event, 'timer_handle')
timestamp = metadata.timestamp
callback_object = get_field(event, 'callback')
self._data.add_callback_object(handle, timestamp, callback_object)
self.data.add_callback_object(handle, timestamp, callback_object)
def _handle_rclcpp_callback_register(
self, event: Dict, metadata: EventMetadata
@ -174,7 +178,7 @@ class Ros2Handler(EventHandler):
callback_object = get_field(event, 'callback')
timestamp = metadata.timestamp
symbol = get_field(event, 'symbol')
self._data.add_callback_symbol(callback_object, timestamp, symbol)
self.data.add_callback_symbol(callback_object, timestamp, symbol)
def _handle_callback_start(
self, event: Dict, metadata: EventMetadata
@ -193,7 +197,7 @@ class Ros2Handler(EventHandler):
del self._callback_instances[callback_object]
duration = metadata.timestamp - metadata_start.timestamp
is_intra_process = get_field(event_start, 'is_intra_process', raise_if_not_found=False)
self._data.add_callback_instance(
self.data.add_callback_instance(
callback_object,
metadata_start.timestamp,
duration,

106
tracetools_analysis/tracetools_analysis/utils.py
View file

@ -25,25 +25,88 @@ from typing import Union
from pandas import DataFrame
from .data_model import DataModel
from .data_model.cpu_time import CpuTimeDataModel
from .data_model.profile import ProfileDataModel
from .data_model.ros import RosDataModel
class ProfileDataModelUtil():
class DataModelUtil():
"""
Profiling data model utility class.
Base data model util class, which provides functions to get more info about a data model.
Provides functions to get more info on the data.
This class provides basic util functions.
"""
def __init__(self, data_model: DataModel) -> None:
"""
Constructor.
:param data_model: the data model
"""
self.__data = data_model
@property
def data(self) -> DataModel:
return self.__data
@staticmethod
def convert_time_columns(
original: DataFrame,
columns_ns_to_ms: List[str] = [],
columns_ns_to_datetime: List[str] = [],
inplace: bool = True,
) -> DataFrame:
"""
Convert time columns from nanoseconds to either milliseconds or `datetime` objects.
:param original: the original `DataFrame`
:param columns_ns_to_ms: the columns for which to convert ns to ms
:param columns_ns_to_datetime: the columns for which to convert ns to `datetime`
:param inplace: whether to convert in place or to return a copy
:return: the resulting `DataFrame`
"""
df = original if inplace else original.copy()
# Convert from ns to ms
if len(columns_ns_to_ms) > 0:
df[columns_ns_to_ms] = df[columns_ns_to_ms].applymap(
lambda t: t / 1000000.0
)
# Convert from ns to ms + ms to datetime, as UTC
if len(columns_ns_to_datetime) > 0:
df[columns_ns_to_datetime] = df[columns_ns_to_datetime].applymap(
lambda t: dt.utcfromtimestamp(t / 1000000000.0)
)
return df
@staticmethod
def compute_column_difference(
df: DataFrame,
left_column: str,
right_column: str,
diff_column: str,
) -> None:
"""
Create new column with difference between two columns.
:param df: the dataframe (inplace)
:param left_column: the name of the left column
:param right_column: the name of the right column
:param diff_column: the name of the new column with differences
"""
df[diff_column] = df.apply(lambda row: row[left_column] - row[right_column], axis=1)
class ProfileDataModelUtil(DataModelUtil):
"""Profiling data model utility class."""
def __init__(self, data_model: ProfileDataModel) -> None:
"""
Constructor.
:param data_model: the data model object to use
"""
self.data = data_model
super().__init__(data_model)
def with_tid(self, tid: int) -> DataFrame:
return self.data.times.loc[self.data.times['tid'] == tid]
@ -81,6 +144,12 @@ class ProfileDataModelUtil():
(tid_df['depth'] == depth) &
(tid_df['function_name'] == name)
][['start_timestamp', 'duration', 'actual_duration']]
self.compute_column_difference(
data,
'duration',
'actual_duration',
'duration_difference',
)
functions_data.append({
'depth': depth,
'function_name': name,
@ -90,12 +159,8 @@ class ProfileDataModelUtil():
return functions_data
class CpuTimeDataModelUtil():
"""
CPU time data model utility class.
Provides functions to get info on a CPU time data model.
"""
class CpuTimeDataModelUtil(DataModelUtil):
"""CPU time data model utility class."""
def __init__(self, data_model: CpuTimeDataModel) -> None:
"""
@ -103,19 +168,15 @@ class CpuTimeDataModelUtil():
:param data_model: the data model object to use
"""
self.data = data_model
super().__init__(data_model)
def get_time_per_thread(self) -> DataFrame:
"""Get a DataFrame of total duration for each thread."""
return self.data.times.loc[:, ['tid', 'duration']].groupby(by='tid').sum()
class RosDataModelUtil():
"""
ROS data model utility class.
Provides functions to get info on a ROS data model.
"""
class RosDataModelUtil(DataModelUtil):
"""ROS data model utility class."""
def __init__(self, data_model: RosDataModel) -> None:
"""
@ -123,7 +184,7 @@ class RosDataModelUtil():
:param data_model: the data model object to use
"""
self.data = data_model
super().__init__(data_model)
def _prettify(self, original: str) -> str:
"""
@ -210,13 +271,8 @@ class RosDataModelUtil():
self.data.callback_instances.loc[:, 'callback_object'] == callback_obj,
['timestamp', 'duration']
]
# Transform both columns to ms
data[['timestamp', 'duration']] = data[
['timestamp', 'duration']
].apply(lambda d: d / 1000000.0)
# Transform start timestamp column to datetime objects
data['timestamp'] = data['timestamp'].apply(lambda t: dt.fromtimestamp(t / 1000.0))
return data
# Time conversion
return self.convert_time_columns(data, ['timestamp', 'duration'], ['timestamp'])
def get_node_tid_from_name(
self, node_name: str