feat: support sim_time (#149)

Signed-off-by: takeshi.iwanari <take.iwiw2222@gmail.com>

.github/workflows/test_autoware.yaml

@@ -76,6 +76,7 @@ jobs:
           export trace_data_name=`basename ${trace_data}`
           export start_strip=0
           export end_strip=0
+          export sim_time=false
           export component_list_json=component_list.json
           export target_path_json=target_path.json
           export max_node_depth=20
@@ -93,6 +94,7 @@ jobs:
               -e trace_data_name \
               -e start_strip \
               -e end_strip \
+              -e sim_time \
               -e component_list_json \
               -e target_path_json \
               -e max_node_depth \

compare/makereport_and_compare.sh

@@ -31,14 +31,15 @@ trace_data="$(pwd)"/session-20231114050140
 sample_autoware_dir="${script_path}"/sample_autoware
 start_strip=0
 end_strip=0
+sim_time=false
 component_list_json=component_list.json
 target_path_json=target_path.json
 max_node_depth=20
 timeout=120
 draw_all_message_flow=false
 report_store_dir=./output
 relpath_from_report_store_dir=false
-export trace_data start_strip end_strip component_list_json target_path_json max_node_depth timeout draw_all_message_flow report_store_dir relpath_from_report_store_dir
+export trace_data start_strip end_strip sim_time component_list_json target_path_json max_node_depth timeout draw_all_message_flow report_store_dir relpath_from_report_store_dir
 cd "${sample_autoware_dir}" || exit
 sh "${script_path}"/report/report_analysis/make_report.sh
 mv output/report_session-20231114050140 "${work_dir}"/.

docker/README.md

@@ -42,6 +42,7 @@ report_store_dir="${work_dir}"
 export trace_data_name=`basename ${trace_data}`
 export start_strip=0
 export end_strip=0
+export sim_time=false
 export component_list_json=component_list.json
 export target_path_json=target_path.json
 export max_node_depth=20
@@ -60,6 +61,7 @@ docker run -it --rm \
     -e trace_data_name \
     -e start_strip \
     -e end_strip \
+    -e sim_time \
     -e component_list_json \
     -e target_path_json \
     -e max_node_depth \

report/README.md

@@ -28,6 +28,7 @@ export note_text_top=./note_text_top.txt             # Path to setting file
 export note_text_bottom=./note_text_bottom.txt       # Path to setting file
 export start_strip=120                               # strip time at the start [sec] for analysis
 export end_strip=30                                  # strip time at the end [sec] for analysis
+export sim_time=false                                # use simulation time (ROS time) or system time
 export trace_data=~/.ros/tracing/session-yyyymmddhhmmss  # Path to CARET trace data (CTF file)
 sh ${script_path}/make_report.sh
 ```
@@ -61,6 +62,7 @@ export note_text_top=./note_text_top.txt             # Path to setting file
 export note_text_bottom=./note_text_bottom.txt       # Path to setting file
 export start_strip=120                               # strip time at the start [sec] for analysis
 export end_strip=30                                  # strip time at the end [sec] for analysis
+export sim_time=false                                # use simulation time (ROS time) or system time
 export trace_data=~/.ros/tracing/session-yyyymmddhhmmss  # Path to CARET trace data (CTF file)
 sh ${script_path}/make_report.sh
 ```

report/analyze_node/analyze_node.py

@@ -19,6 +19,7 @@
 import os
 from pathlib import Path
 import argparse
+from distutils.util import strtobool
 import logging
 import math
 import yaml
@@ -94,13 +95,13 @@ def set_callback(self, callback: CallbackBase, callback_legend: str, metrics: st
 
 
 def analyze_callback(df_callback: pd.DataFrame, node: Node, callback_name: str,
-                     metrics: str, dest_dir_path: str, method_hist):
+                     metrics: str, dest_dir_path: str, method_hist, xaxis_type: str):
     """Analyze a callback"""
     callback_stats = StatsCallback()
     callback_stats.calculate(df_callback)
     if len(df_callback) > 0:
         callback = node.get_callback(callback_name)
-        fig_hist = method_hist(callback).figure()
+        fig_hist = method_hist(callback).figure(xaxis_type=xaxis_type)
         fig_hist.height = 350
         fig_hist.width = 600
         fig_hist.legend.visible = False
@@ -112,7 +113,7 @@ def analyze_callback(df_callback: pd.DataFrame, node: Node, callback_name: str,
     return callback_stats
 
 
-def analyze_node(node: Node, dest_dir: str, threshold_freq_not_display: int=200) -> dict:
+def analyze_node(node: Node, dest_dir: str, xaxis_type: str, threshold_freq_not_display: int=200) -> dict:
     """Analyze a node"""
     _logger.info(f'Processing {node.node_name}')
     all_metrics_dict = {'Frequency':(Plot.create_frequency_timeseries_plot, Plot.create_frequency_histogram_plot),
@@ -124,7 +125,7 @@ def analyze_node(node: Node, dest_dir: str, threshold_freq_not_display: int=200)
     for metrics, method in all_metrics_dict.items():
         try:
             p_timeseries = method[0](node.callbacks)
-            measurement = p_timeseries.to_dataframe()
+            measurement = p_timeseries.to_dataframe(xaxis_type=xaxis_type)
         except:
             _logger.info(f'This node is not called: {node.node_name}')
             return None
@@ -140,7 +141,7 @@ def analyze_node(node: Node, dest_dir: str, threshold_freq_not_display: int=200)
             df_callback = trail_df(df_callback, end_strip_num=2, start_strip_num=1)
             if len(df_callback) > 0:
                 has_valid_data = True
-            callback_stats = analyze_callback(df_callback, node, callback_name, metrics, dest_dir, method[1])
+            callback_stats = analyze_callback(df_callback, node, callback_name, metrics, dest_dir, method[1], xaxis_type)
             node_stats.set_callback(node.get_callback(callback_name), get_callback_legend(node, callback_name, False),
                                     metrics, callback_stats)
             if metrics == 'Frequency':
@@ -154,7 +155,7 @@ def analyze_node(node: Node, dest_dir: str, threshold_freq_not_display: int=200)
             try:
                 if metrics != 'Frequency':
                     p_timeseries = method[0](callbacks_for_graph)
-                fig_timeseries = p_timeseries.figure()  # note: this API is heavy when callback runs with high frequency
+                fig_timeseries = p_timeseries.figure(xaxis_type=xaxis_type)  # note: this API is heavy when callback runs with high frequency
                 fig_timeseries.y_range.start = 0
                 filename_timeseries = metrics + node.node_name.replace('/', '_')[:250]
                 export_graph(fig_timeseries, dest_dir, filename_timeseries, with_png=False, logger=_logger)
@@ -165,13 +166,13 @@ def analyze_node(node: Node, dest_dir: str, threshold_freq_not_display: int=200)
     return node_stats
 
 
-def analyze_component(node_list: list[Node], dest_dir: str):
+def analyze_component(node_list: list[Node], dest_dir: str, xaxis_type: str):
     """Analyze a component"""
     make_destination_dir(dest_dir, False, _logger)
 
     stats = {}
     for node in node_list:
-        node_stats = analyze_node(node, dest_dir)
+        node_stats = analyze_node(node, dest_dir, xaxis_type)
         if node_stats:
             stats[node.node_name] = vars(node_stats)
 
@@ -209,7 +210,7 @@ def analyze(args, lttng: Lttng, arch: Architecture, app: Application, dest_dir:
 
     for component_name, _ in ComponentManager().component_dict.items():
         node_list = get_node_list(lttng, app, component_name)
-        analyze_component(node_list, f'{dest_dir}/{component_name}')
+        analyze_component(node_list, f'{dest_dir}/{component_name}', 'sim_time' if args.sim_time else 'system_time')
 
     _logger.info('<<< Analyze Nodes: Finish >>>')
 
@@ -225,6 +226,7 @@ def parse_arg():
                         help='Start strip [sec] to load trace data')
     parser.add_argument('--end_strip', type=float, default=0.0,
                         help='End strip [sec] to load trace data')
+    parser.add_argument('--sim_time', type=strtobool, default=False)
     parser.add_argument('-f', '--force', action='store_true', default=False,
                         help='Overwrite report directory')
     parser.add_argument('-v', '--verbose', action='store_true', default=False)
@@ -242,6 +244,7 @@ def main():
     _logger.debug(f'dest_dir: {args.dest_dir[0]}')
     _logger.debug(f'component_list_json: {args.component_list_json}')
     _logger.debug(f'start_strip: {args.start_strip}, end_strip: {args.end_strip}')
+    _logger.debug(f'sim_time: {args.sim_time}')
 
     lttng = read_trace_data(args.trace_data[0], args.start_strip, args.end_strip, False)
     arch = Architecture('lttng', str(args.trace_data[0]))

report/analyze_path/analyze_path.py

@@ -139,7 +139,7 @@ def check_the_first_last_callback_is_valid(records: RecordsInterface):
     return is_first_valid, is_last_valid
 
 
-def analyze_path(args, dest_dir: str, arch: Architecture, app: Application, target_path_name: str, include_first_last_callback: dict):
+def analyze_path(args, dest_dir: str, arch: Architecture, app: Application, target_path_name: str, include_first_last_callback: dict, xaxis_type: str):
     """Analyze a path"""
     _logger.info(f'Processing: {target_path_name}')
     target_path = app.get_path(target_path_name)
@@ -181,9 +181,9 @@ def analyze_path(args, dest_dir: str, arch: Architecture, app: Application, targ
         df_response_time = {}
         for case_str in ['best', 'worst', 'all']:
             plot_timeseries = Plot.create_response_time_timeseries_plot(target_path, case=case_str)
-            fig_timeseries = plot_timeseries.figure(full_legends=False)
-            df_response_time[case_str] = plot_timeseries.to_dataframe()
-            fig_hist = Plot.create_response_time_histogram_plot(target_path, case=case_str).figure(full_legends=False)
+            fig_timeseries = plot_timeseries.figure(full_legends=False, xaxis_type=xaxis_type)
+            df_response_time[case_str] = plot_timeseries.to_dataframe(xaxis_type=xaxis_type)
+            fig_hist = Plot.create_response_time_histogram_plot(target_path, case=case_str).figure(full_legends=False, xaxis_type=xaxis_type)
             fig_timeseries.y_range.start = 0
             fig_timeseries.legend.visible = False
             fig_hist.legend.visible = False
@@ -194,7 +194,7 @@ def analyze_path(args, dest_dir: str, arch: Architecture, app: Application, targ
             export_graph(fig_timeseries, dest_dir, target_path_name + f'_timeseries_{case_str}', target_path_name, with_png=False)
             export_graph(fig_hist, dest_dir, target_path_name + f'_hist_{case_str}', target_path_name, with_png=False)
             try:
-                Plot.create_response_time_stacked_bar_plot(target_path, case=case_str).save(export_path=f'{dest_dir}/{target_path_name}_stacked_bar_{case_str}.html', full_legends=True)
+                Plot.create_response_time_stacked_bar_plot(target_path, case=case_str).save(xaxis_type=xaxis_type, export_path=f'{dest_dir}/{target_path_name}_stacked_bar_{case_str}.html', full_legends=True)
             except Exception as e:
                 _logger.warning(f'    Failed to create stacked bar graph: {target_path_name}, {case_str}')
                 _logger.warning(str(e))
@@ -235,6 +235,7 @@ def analyze(args, lttng: Lttng, arch: Architecture, app: Application, dest_dir:
     if _logger is None:
         _logger = create_logger(__name__, logging.DEBUG if args.verbose else logging.INFO)
     _logger.info('<<< Analyze Paths: Start >>>')
+    xaxis_type =  'sim_time' if args.sim_time else 'system_time'
     make_destination_dir(dest_dir, args.force, _logger)
     shutil.copy(args.architecture_file_path, dest_dir)
 
@@ -254,7 +255,7 @@ def analyze(args, lttng: Lttng, arch: Architecture, app: Application, dest_dir:
     # Analyze each path
     for target_path in arch.paths:
         target_path_name = target_path.path_name
-        stats = analyze_path(args, dest_dir, arch, app, target_path_name, include_first_last_callback)
+        stats = analyze_path(args, dest_dir, arch, app, target_path_name, include_first_last_callback, xaxis_type)
         stats_list.append(vars(stats))
 
     # Save stats file
@@ -280,6 +281,7 @@ def parse_arg():
                         help='Start strip [sec] to load trace data')
     parser.add_argument('--end_strip', type=float, default=0.0,
                         help='End strip [sec] to load trace data')
+    parser.add_argument('--sim_time', type=strtobool, default=False)
     parser.add_argument('-f', '--force', action='store_true', default=False,
                         help='Overwrite report directory')
     parser.add_argument('-v', '--verbose', action='store_true', default=False)
@@ -298,6 +300,7 @@ def main():
     _logger.debug(f'target_path_json: {args.target_path_json}')
     _logger.debug(f'architecture_file_path: {args.architecture_file_path}')
     _logger.debug(f'start_strip: {args.start_strip}, end_strip: {args.end_strip}')
+    _logger.debug(f'sim_time: {args.sim_time}')
     args.message_flow = True if args.message_flow == 1 else False
     _logger.debug(f'message_flow: {args.message_flow}')
 

report/report_analysis/make_report.sh

@@ -20,14 +20,14 @@ cp "${target_path_json}" "${report_dir_name}"/.
 
 # Path analysis
 python3 "${script_path}"/analyze_path/add_path_to_architecture.py "${trace_data}" "${target_path_json}" --architecture_file_path=architecture_path.yaml --max_node_depth="${max_node_depth}" --timeout="${timeout}" -v
-python3 "${script_path}"/analyze_path/analyze_path.py "${trace_data}" "${report_dir_name}" --architecture_file_path=architecture_path.yaml --start_strip "${start_strip}" --end_strip "${end_strip}" -f -v -m "${draw_all_message_flow}"
+python3 "${script_path}"/analyze_path/analyze_path.py "${trace_data}" "${report_dir_name}" --architecture_file_path=architecture_path.yaml --start_strip "${start_strip}" --end_strip "${end_strip}" --sim_time "${sim_time}" -f -v -m "${draw_all_message_flow}"
 python3 "${script_path}"/analyze_path/make_report_analyze_path.py "${report_dir_name}"
 
 # Track of response time
 python3 "${script_path}"/track_path/make_report_track_path.py "${report_dir_name}" "${report_store_dir}" --relpath_from_report_store_dir="${relpath_from_report_store_dir}"
 
 # Node analysis
-python3 "${script_path}"/analyze_node/analyze_node.py "${trace_data}" "${report_dir_name}" --component_list_json="${component_list_json}" --start_strip "${start_strip}" --end_strip "${end_strip}" -f -v
+python3 "${script_path}"/analyze_node/analyze_node.py "${trace_data}" "${report_dir_name}" --component_list_json="${component_list_json}" --start_strip "${start_strip}" --end_strip "${end_strip}" --sim_time "${sim_time}" -f -v
 python3 "${script_path}"/analyze_node/make_report_analyze_node.py "${report_dir_name}"
 
 # # Check callback health

report/report_validation/make_report.sh

@@ -23,11 +23,11 @@ cp "${callback_list_csv}" "${report_dir_name}"/.
 python3 "${script_path}"/validate_topic/generate_expectation_list.py "${trace_data}" --report_directory="${report_dir_name}" --callback_list_filename="${callback_list_csv}" --topic_list_filename=topic_list.csv --expectation_csv_filename=topic_list_pubsub.csv
 
 # Validate Callback
-python3 "${script_path}"/validate_callback/validate_callback.py "${trace_data}" --report_directory="${report_dir_name}" --component_list_json="${component_list_json}" --expectation_csv_filename="${callback_list_csv}" --start_strip "${start_strip}" --end_strip "${end_strip}" -f -v
+python3 "${script_path}"/validate_callback/validate_callback.py "${trace_data}" --report_directory="${report_dir_name}" --component_list_json="${component_list_json}" --expectation_csv_filename="${callback_list_csv}" --start_strip "${start_strip}" --end_strip "${end_strip}" --sim_time "${sim_time}" -f -v
 python3 "${script_path}"/validate_callback/make_report_validate_callback.py "${report_dir_name}" --component_list_json="${component_list_json}"
 
 # Validate Topic
-python3 "${script_path}"/validate_topic/validate_topic.py "${trace_data}" --report_directory="${report_dir_name}" --component_list_json="${component_list_json}" --expectation_csv_filename="${report_dir_name}/topic_list_pubsub.csv" --start_strip "${start_strip}" --end_strip "${end_strip}" -f -v
+python3 "${script_path}"/validate_topic/validate_topic.py "${trace_data}" --report_directory="${report_dir_name}" --component_list_json="${component_list_json}" --expectation_csv_filename="${report_dir_name}/topic_list_pubsub.csv" --start_strip "${start_strip}" --end_strip "${end_strip}" --sim_time "${sim_time}" -f -v
 python3 "${script_path}"/validate_topic/make_report_validate_topic.py "${report_dir_name}" --component_list_json="${component_list_json}"
 
 # Trace Validation failure
@@ -38,7 +38,7 @@ python3 "${script_path}"/validate_callback/make_report_validate_callback.py "${r
 
 # Path analysis
 python3 "${script_path}"/analyze_path/add_path_to_architecture.py "${trace_data}" "${target_path_json}" --architecture_file_path=architecture_path.yaml --max_node_depth="${max_node_depth}" --timeout="${timeout}" -v
-python3 "${script_path}"/analyze_path/analyze_path.py "${trace_data}" "${report_dir_name}" --architecture_file_path=architecture_path.yaml --start_strip "${start_strip}" --end_strip "${end_strip}" -f -v -m "${draw_all_message_flow}"
+python3 "${script_path}"/analyze_path/analyze_path.py "${trace_data}" "${report_dir_name}" --architecture_file_path=architecture_path.yaml --start_strip "${start_strip}" --end_strip "${end_strip}" --sim_time "${sim_time}" -f -v -m "${draw_all_message_flow}"
 python3 "${script_path}"/analyze_path/make_report_analyze_path.py "${report_dir_name}"
 
 # Track of response time

report/trace_validation_failure/make_report_trace_validation_failure.py

@@ -116,7 +116,7 @@ def trace_failure_node(parent: Node, arch: Architecture, node_name: str, callbac
                 _logger.warning(f'{callback_name} is not measured but treated as FAILED')
             if node.depth > 100:
                 _logger.error(f'Too depth: {parent.name} -> {callback_name}')
-                continue
+                raise Exception('Too depth')
             if period_ns != -1:
                 # end
                 pass
@@ -141,7 +141,11 @@ def trace_failure(callback_stats_list: list[dict], arch: Architecture):
                 if period_ns == -1:
                     publisher_list = search_publishers(arch, subscribe_topic_name, node_name)
                     for publisher in publisher_list:
-                        trace_failure_node(tree_new_node, arch, publisher, callback_stats_list)
+                        try:
+                            trace_failure_node(tree_new_node, arch, publisher, callback_stats_list)
+                        except Exception:
+                            _logger.error(f'Stop tracing because too many failures')
+                            return Node('root')
                 for descendant in tree_new_node.descendants:
                     # check if the temp tree contains the callback already added as child. If so, delete the child
                     if tree_check_if_contained_as_children(descendant.name, tree_root):