End-to-End Latency Analysis per Message

[0xB4demeister]

Hey,
First I wanted to say thanks for your nice tracing framework and analysis library.
I am currently adjusting it a bit to evaluate the impact of hardware acceleration in ROS 2.
I wanted to evaluate memory, cpu usages,.. but also ros-related overhead.
As far as I can tell, your library provides the callback duration out of the box, which is most likely the time RCLCPP_HANDLE takes to handle a callback (using the term from this paper Latency Analysis of ROS2 Multi-Node Systems - https://arxiv.org/pdf/2101.02074)

The callback is a nice way to inspect the execution time of a kernel, but I wish to further investigate the latency per topic and end-to-end latency of the system to approximate the "communication overhead".
(my communication system is rather trivial and is a basically a chain of publications/callbacks with only minor topics being consumed even multiple times)

My question was if the current data structure already supports the linking of publish_handle and subscription_handle based on a topic such that once can unambiguously link a published message start time to a taken message start time.
The second link I wanted to get by connecting a subscription to a callback which gives me a rough time when the publication should start.
This second link I have also still not fully figured out, as I cannot get something other than None being returned from get_subscription_reference_info .

Could you perhaps give me some insights into the data structure and if I need to create/append further information to the traces or simply expose further information from the internal data structures?

[christophebedard]

Hey,
First I wanted to say thanks for your nice tracing framework and analysis library.

Happy to hear you like it!

As far as I can tell, your library provides the callback duration out of the box, which is most likely the time RCLCPP_HANDLE takes to handle a callback (using the term from this paper Latency Analysis of ROS2 Multi-Node Systems - https://arxiv.org/pdf/2101.02074)

Yeah, the callback duration is simply the time difference between just before the user callback is called and just after it returns. It's not quite straightforward looking at the code, but it's the difference between the ros2:callback_start and ros2:callback_end tracepoints: https://github.com/ros2/rclcpp/blob/e7afaa636a97dc3908d25d367652b58ecda95273/rclcpp/include/rclcpp/any_subscription_callback.hpp#L472-L563.

My question was if the current data structure already supports the linking of publish_handle and subscription_handle based on a topic such that once can unambiguously link a published message start time to a taken message start time.

This is indeed possible using the tracing instrumentation. See Section IV-A (Transport Links) in this paper: https://arxiv.org/pdf/2204.10208.

The second link I wanted to get by connecting a subscription to a callback which gives me a rough time when the publication should start.
This second link I have also still not fully figured out, as I cannot get something other than None being returned from get_subscription_reference_info .

You're talking about linking a message being received (and handled by a callback) to a message being published by that callback? See Section IV-B (Causal Message Links), specifically the "direct case," in the paper I linked to above.

All of this allows you to get the end-to-end latency of a processing pipeline and visualize it. I'd recommend reading the full paper! This is all implemented in the Eclipse Trace Compass Incubator (not in tracetools_analysis), see these instructions: https://github.com/christophebedard/ros2-message-flow-analysis#analysis.

Using this information, you can split the end-to-end latency time into ROS 2 internal latency, network latency, etc. However, it could be broken down further (see Section VIII in the paper, for example). One latency component that's especially interesting and which I haven't looked into yet is the delay between the message reception inside the middleware and the start of the callback execution, because this depends on the executor. The executor of course has a big influence of the performance of a ROS 2 application.

Let me know if you have any questions.

[0xB4demeister]

Hi, thanks for the extensive explanations!

Yeah, the callback duration is simply the time difference between just before the user callback is called and just after it returns. It's not quite straightforward looking at the code, but it's the difference between the ros2:callback_start and ros2:callback_end tracepoints: https://github.com/ros2/rclcpp/blob/e7afaa636a97dc3908d25d367652b58ecda95273/rclcpp/include/rclcpp/any_subscription_callback.hpp#L472-L563.

Ah great, yeah I was lacking a bit the information about what each of the attributes inside the python library really represent.
I was also wondering a bit about the rmw_handle's and subcription_handle's as some tables I was able to connect but others not. Why is the subscription_id (index) of the callback objects not related to the subscription id of take_instances['rmw_subscription_handle']? I was able to relate callback objects to take_instances via the node_id but it felt a bit strange..
As I want to measure basically the same as Victor in the HAWG,
I want to collect as accurate as possible with minor effort the overhead of ROS 2 and relate that to the execution time of the kernels.
For this, my current plan was to combine the (take_timestamp - callback_start) + message transfer duration (DDS) + (callback_end - Publish_timestamp) as approximation - do you think this works?

Yes, I saw this paper as well and just recognized that it explains what the gid and source_timestamp represent.
But I think I will try for now to implement a "hacky" solution simply based on matching source_timestamp to callback_end and topics as my frequency will not exceed 30Hz because I would need to patch otherwise the DDS layers FastDDS and CyclonDDS myself, right? or was this upstreamed in humble?

All of this allows you to get the end-to-end latency of a processing pipeline and visualize it. I'd recommend reading the full paper! This is all implemented in the Eclipse Trace Compass Incubator (not in tracetools_analysis), see these instructions: https://github.com/christophebedard/ros2-message-flow-analysis#analysis.

I tried also the tool but had a bit problems understanding what I actually see 😁 As I was unable to find instructions/explanations about the different views and how to tune it (e.g. which exact timestamps are visualized, how to visualize callback duration,..) and had the feeling using this library might be better in the long run, especially when I want to add custom trace points for the kernel execution time

[christophebedard]

I was also wondering a bit about the rmw_handle's and subcription_handle's as some tables I was able to connect but others not. Why is the subscription_id (index) of the callback objects not related to the subscription id of take_instances['rmw_subscription_handle']? I was able to relate callback objects to take_instances via the node_id but it felt a bit strange..

There's multiple kinds of "subscription" values. The "subscription handle" (without mention of rmw/rcl) is usually the rcl_subscription_t pointer, while the "subscription" is the rclcpp::*Subscription object's address. It's a bit tricky, but:

• Ros2DataModel._callback_objects
  • reference: address of the rclcpp::*Subscription object
  • callback_object: address of the callback object (e.g., rclcpp::AnySubscriptionCallback)
• Ros2DataModel._subscription_objects
  • subscription: address of the rclcpp::*Subscription object
  • subscription_handle: rcl_subscription_t pointer address
• Ros2DataModel._callback_instances
  • callback_object: address of the callback object (e.g., rclcpp::AnySubscriptionCallback), which can thus be linked back to the subscription (e.g., rcl_subscription_t) using the info above
• Ros2DataModel._rmw_take_instances
  • subscription_handle: rmw_subscription_t pointer address, which can be linked back to the rcl_subscription_t pointer address

It's definitely not straightforward, but you can see this if you go backwards from the Ros2DataModel.add_*() methods (to see what tracepoint field each dataframe column corresponds to) and look at where the tracepoints are triggered in the ROS 2 source code. Also, this explains why we have to use two different "subscription" values: https://github.com/ros2/ros2_tracing/blob/03ccd0bb4aa679181411d15d4cf0f34edf7968cf/tracetools/include/tracetools/tracetools.h#L292-L298.

Does this help explain how everything is linked together?

I want to collect as accurate as possible with minor effort the overhead of ROS 2 and relate that to the execution time of the kernels.
For this, my current plan was to combine the (take_timestamp - callback_start) + message transfer duration (DDS) + (callback_end - Publish_timestamp) as approximation - do you think this works?

What is the (callback_end - Publish_timestamp) component supposed to represent?

But I think I will try for now to implement a "hacky" solution simply based on matching source_timestamp to callback_end and topics as my frequency will not exceed 30Hz because I would need to patch otherwise the DDS layers FastDDS and CyclonDDS myself, right? or was this upstreamed in humble?

No, unfortunately. But building the DDS implementation is usually not too bad, so you could try patching them. Or you could try backporting this PR and the relevant rmw_* PRs to Humble so that you don't need to get the source_timestamp from the DDS implementation: ros2/ros2_tracing#74.

I tried also the tool but had a bit problems understanding what I actually see 😁 As I was unable to find instructions/explanations about the different views and how to tune it (e.g. which exact timestamps are visualized, how to visualize callback duration,..) and had the feeling using this library might be better in the long run, especially when I want to add custom trace points for the kernel execution time

Feel free to ask questions. The paper explains the views a bit, but, yes, I do indeed need to properly document everything. See ros2/ros2_tracing#148.

However, tracetools_analysis is definitely better if you want to implement some custom trace data analysis/processing logic. It's a lot easier, especially if your analysis isn't that complex.

[0xB4demeister]

Does this help explain how everything is linked together?
Yes, thanks. I was able to derive the same connection, but wasn't sure if this was the "correct way" of linking, thanks for the explanations.

What is the (callback_end - Publish_timestamp) component supposed to represent?
My nodes follow a relatively strict pattern (subscribe: one or multiple, preprocess, compute, postprocess, publish)
So the call to .publish() is often the last line in my callback.
I therefore assume any duration as some potential overhead in the cleanup of publish/callback end.
Right now it is a measurable overhead, especially for larger arrays but I would need to investigate further later.
To answer it short - it doesn't really represent something interpretable for me so far, but its still helpful to debug cleanup overhead/ badly designed message data types

No, unfortunately. But building the DDS implementation is usually not too bad, so you could try patching them. Or you could try backporting this PR and the relevant rmw_* PRs to Humble so that you don't need to get the source_timestamp from the DDS implementation: ros2/ros2_tracing#74.

I might try that in the future, for now are adjusted the application to forward the same header timestamp from the subscribed message which allows easy tracking.

Yes, I was able to integrate my custom tracepoints and get some nice data extracted, thanks for the help