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
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/
rclcpp instrumentation has been integrated into Eloquent, so we simply need to recompile
ros2_tracing & compile
$ 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.
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.
By default, traces are written in the
~/.ros/tracing/ directory. 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 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.
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
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.