Getting started with ROS 2 tracing
Note: While ros2_tracing has been associated with micro-ROS, ros2_tracing does not currently officially support nor target microcontrollers.
Note: For a more up-to-date tutorial, please refer to the ros2_tracing tutorial on the ROS 2 Real-Time Working Group documentation.
Introduction
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.
Setup
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
As part of the installation, a new group tracing is created. Add your user to this group by running
$ sudo usermod -aG tracing $USER
and log off and on to take the new membership effect.
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 -p ~/ros2_ws/src
$ cd ros2_ws/
The rcl and rclcpp instrumentation has been integrated into Eloquent, so we simply need to recompile ros2_tracing & compile tracetools_analysis.
$ wget https://gitlab.com/ros-tracing/ros2_tracing/raw/master/tracing.repos
$ vcs import src < tracing.repos
Now let’s build and source.
$ colcon build --symlink-install
$ source install/local_setup.bash
Simple tracing example
Let’s try tracing with a simple ping-pong example.
The 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 tracetools_launch package.
$ ros2 launch tracetools_launch example.launch.py
As shown above, you should see a few output lines, and that’s it.
By default, traces are written in the ~/.ros/tracing/ directory. You can take a look at the trace’s events using babeltrace.
$ 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_start and ros2:callback_end events. Each one contains a reference to its corresponding callback.
It’s now time to process the trace data! The tracetools_analysis package provides tools to import a trace and process it. Since reading a CTF trace is slow, it first converts it to a file which we can read much faster later on. Then we can process it to get pandas dataframes and use those to run analyses.
$ ros2 trace-analysis process ~/.ros/tracing/my-tracing-session/ust/
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/ros-tracing/ros2_tracing/tracetools_launch/launch/. It will stop the nodes from shutting down after 1 exchange.
arguments=['do_more']
Delete the previous trace directory, rebuild the workspace, and execute the launch file again. Let it run for some time (e.g. 10-20 seconds), then kill it with Ctrl+C.
To run an analysis that displays durations of callbacks over time, use this Jupyter notebook, which should be under ros2_ws/src/tracetools_analysis/tracetools_analysis/analysis/.
The resulting plots for the /ping and /pong subscriptions are shown below. We can see that the durations vary greatly.
Relevant links
The tracing packages can be found in the ros2_tracing repo. The analysis tools can be found in the tracetools_analysis repo.