Getting started with ROS 2 tracing
Robotic systems can be hard to analyze and debug, and one big reason is that internal processing is always changing in response to sensory input. Therefore, the ability to continuously monitor and record data about the robotic software is important, to make sure it behaves deterministically, stays within resource limits, and also for later analysis.
On modern systems, the operating system and other running software has a big influence on the exact execution of the software. Therefore, we also need information about these aspects.
Tracing is a well-established method that allows to record run-time data, which is already well integrated with operating systems. For example, we can trace when a process is being scheduled, or when I/O occurs. Current tracing systems have minimal overhead and are very configurable to reduce overhead (and data size) even further.
This post aims to introduce our ongoing effort to instrument ROS 2 and provide trace analysis tools. I’ll show how we can use the instrumentation and the current analysis tools to plot callback durations, like the plot shown below.
We’ll assume you’re using Ubuntu 18.04 bionic.
First, let’s install LTTng.
$ sudo apt-add-repository ppa:lttng/stable-2.10 $ sudo apt-get update $ sudo apt-get install lttng-tools lttng-modules-dkms liblttng-ust-dev
We’ll also need these Python packages to read traces and setup a tracing session through ROS.
$ sudo apt-get install python3-babeltrace python3-lttng
If the ROS 2 development tools and dependencies are not installed on your machine, install them by following the System setup section here.
Now we’ll download all the necessary packages. First, create your workspace.
$ mkdir ~/ros2_ws $ cd ros2_ws/
Then clone everything using the following
.repos file. It includes the core ROS 2 packages with instrumented versions of
rclcpp, as well as the tracing tools and tracing analysis repos.
$ wget https://gitlab.com/micro-ROS/ros_tracing/ros2_tracing/raw/master/all.repos $ vcs import src < all.repos
Let’s build everything and source!
$ colcon build --symlink-install --cmake-args " -DWITH_LTTNG=ON" $ source ./install/local_setup.bash
Simple tracing example
Let’s try tracing with a simple ping-pong example.
tracetools_test package contains two nodes we can use. The first node,
test_ping, publishes messages on the
ping topic and waits for a message on the
pong topic before shutting down. The second node,
test_pong, waits for a message on the
ping topic, then sends a message on the
pong topic and shuts down.
To trace these nodes, we can use the
example.launch.py launch file in the
$ ros2 launch tracetools_launch example.launch.py
As shown above, you should see a few output lines, and that’s it.
You can take a look at the trace’s events using
$ cd ~/.ros/tracing/ $ babeltrace my-tracing-session/
If you only want to see the ROS events, you can instead do:
$ babeltrace my-tracing-session/ust/
The last part of the
babeltrace output is shown above. This is a human-readable version of the raw Common Trace Format (CTF) data, which is a list of events. Each event has a timestamp, an event type, some information on the process that generated the event, and the fields corresponding to the event type. The last events of our trace are pairs of
ros2:callback_end events. Each contains a reference to its corresponding callback.
It’s now time to process the trace data! The
tracetools_analysis package provides tools to import and process the results. We can first convert the CTF data to a pickle file. Then we can process it to get
pandas dataframes which we can use later to run analyses.
$ ros2 run tracetools_analysis convert ~/.ros/tracing/my-tracing-session/ust $ ros2 run tracetools_analysis process ~/.ros/tracing/my-tracing-session/ust/pickle
The output of the
process command is shown above. In the last dataframe, named “Callback instances,” you should see three rows. The first one is the timer callback that triggered the ping-pong sequence. The second one is the ping callback, and the third one is the pong callback! Callback function symbols are shown in the previous dataframe.
This is simple, but it isn’t really nice visually. We can use a Jupyter notebook to analyze the data and display the results.
Callback duration analysis
Add the following line to the arguments of each of the two
Node objects in your launch file, which should be under
ros2_ws/src/ros2/tracing/tracetools_launch/launch/. It will stop the nodes from shutting down after 1 exchange.
Delete the previous trace directory, and execute the launch file again. Let it run for some time (e.g. 10-20 seconds), then kill it with
To run an analysis that displays durations of callbacks over time, use this Jupyter notebook, which should be under
The resulting plots for the
/pong subscriptions are shown below. We can see that the durations vary greatly.
Now that the groundwork is done, the next steps are:
- Submit PRs for
rclcppinstrumentation. We are aiming for the instrumentation to be included in ROS 2 Eloquent (November 2019).
- Add more analyses.
- Test on real hardware, and compare analysis results to other tools.
- Release first version of packages.
- Work on providing swappable
tracetoolspackages (a default package with tracing being disabled, and another one with tracing being enabled).
Let us know if you have any questions, or if you’d like to get involved!