# Consideration of performance measurement methods

**URL:** <https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453>\
**Category:** Projects\
**Tags:** ros2, real-time\
**Created:** [September 28, 2021, 5:55am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453 "2021-09-28T05:55:42Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![hsgwa](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/hsgwa/32/8753_2.png) [@hsgwa](https://discourse.openrobotics.org/u/hsgwa)\
**Post date:** [September 28, 2021, 5:55am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/1 "2021-09-28T05:55:43Z")

</div>

I’m considering how to measure the performance of ROS2 applications.  
I’m still in the middle of this project, but I would appreciate any comments.

## Goal

measuring latency and identifying the cause.

### Latency measurement

I’d like to measure

- callback duration
- communication latency
- node-latency
- end-to-end latency

in a real application.

For example, I’d like to create the following diagram.

 ![callback_latency](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/9/9613045782443e217ba3c202fd0164879806d531.png)

 ![node_latency](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/5/5c39c99d177b084fe5d9375c2e03b172320d7712.png)

### Visualizing Behavior

ROS2 includes communication and scheduling, and I think it may behave differently from the developer’s intention, resulting in poor performance.  
For example, communication QoS, callback group, callback priority.

So, I’d like to create the following diagram.

 ![executor_scheduling](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/a/aabd59b405388b57b02f31f0765a09988701a78f.png)

 ![message_flow](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/2/227fa8c5aca1f7b59a8c243dc51c03c81e798e02.png)

In terms of content, the following article does something similar.

> **[Message Flow Analysis for ROS Through Tracing](https://discourse.openrobotics.org/t/message-flow-analysis-for-ros-through-tracing/9437)**
>
> As part of an undergraduate research project, I used Trace Compass, a trace viewer and analysis framework, to leverage existing ROS instrumentation and create an analysis that can draw the path of a message through ROS nodes. It can show how much...

## WIP

I think the following trace points are mainly necessary for measurement.

 ![major_tracepoints](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/5/5193a1cb6b617976492581b3af837030de82118c.png)

Since I’m still experimenting, I’m mainly using LD\_PRELOAD hooks to add trace points.  
However, ROS2 has some header implementations that cannot be hooked.  
To add trace points to headers, I also add trace points on the forked rclcpp and ros2\_tracing.

> <https://github.com/tier4/rclcpp/commit/3d050be42e3e7ab6a8f84dce598a19df537f8246>
>
> Signed-off-by: hsgwa \<hasegawa.ats@gmail.com\>

In the future, I’m considering proposing new trace points to ROS if the measurements seem useful.

### problem

I’m currently trying to use FastDDS and CycloneDDS for measurements, but on\_data\_available is not working as expected.  
on\_data\_available is not used in rmw\_cyclonedds, and there may be other better places to insert tracepoints.  
I think it’s necessary if we want to evaluate pure (not dependent on scheduling communication latency though.  
I don’t know much about the DDS and rmw, so I would be glad if you could comment on this as well.

---

<div class="post-metadata">

**Author:** ![tomoyafujita](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/tomoyafujita/32/6097_2.png) [@tomoyafujita](https://discourse.openrobotics.org/u/tomoyafujita)\
**Post date:** [September 28, 2021, 10:44pm UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/2 "2021-09-28T22:44:04Z")

</div>

@hsgwa thanks for sharing your thought. this looks nice 👍

I got a question about `message flow`.

Can we trace the specific message flow? for me, this looks more like statistics from each independent endpoint?  
I was thinking about this kind of traceability before, i think for doing that we need to integrate unique identification in the message to trace. because we have no idea how many frames delayed in application or data process rate/frequency might be different from each application.

anyway, it would be really nice to trace the message flow 🙂

---

<div class="post-metadata">

**Author:** ![hsgwa](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/hsgwa/32/8753_2.png) [@hsgwa](https://discourse.openrobotics.org/u/hsgwa)\
**Post date:** [September 29, 2021, 5:28am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/3 "2021-09-29T05:28:04Z")

</div>

@tomoyafujita

Thanks for the comment!

I thought that latency statistics for each component are also needed to understand the overall performance, I included them as an example.  
Measurements are tracked for each message and can be used for more detailed analysis.

Specifically, the following steps are used to track message flow.

## Communication

In order to link publish to subscription, I use the information of source\_timestamp that dds sends with the message as a unique message ID.

 ![message_track](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/d/d696da7ae5bd801da24eb71e767381b35d3f97c8.png)  
I thought using header.stamp, like the topic\_statistics built into rclcpp, but I gave up because I was concerned it would restrict the message type and destroy the stamp value.

The source\_timestamp is a value generated by the dds layer, so on the publisher side, we have to add a process to bind the message address to the source\_timestamp.  
The concern is I have also added the LDPRELOAD hook inside DDS, and the implementation depends on the DDS version as well 🤔

Source code in the development stage used for the hooks in LD\_PRELOAD can be found here.  
[https://github.com/tier4/CARET\_trace/blob/main/src/hooked\_trace\_points.cpp](https://github.com/tier4/CARET_trace/blob/main/src/hooked_trace_points.cpp)

## Callback

Messages entering and leaving the callback are different types, and it is difficult to bind them by IDs such as source\_timestamp.  
Therefore, I thought binding callback\_start with the next message, rclcpp\_publish.  
This way, We can bind the source\_timestamp of the input message with the source\_timetamp of the output message.

 ![bind_source_timestamps](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/b/b3b792e0ad49e1011f5943a70acbff2109f5048b.png)

At the current stage, I’m trying to give the graph information of the callback in advance.

The actual trace log also records information from other callbacks and publishes, so I use callback addresses and publisher\_handler to bind them together in pairs that make sense.

---

<div class="post-metadata">

**Author:** ![tomoyafujita](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/tomoyafujita/32/6097_2.png) [@tomoyafujita](https://discourse.openrobotics.org/u/tomoyafujita)\
**Post date:** [September 29, 2021, 5:16pm UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/4 "2021-09-29T17:16:27Z")

</div>

@hsgwa

thanks for the explanation, that helps me understand 👍

> The source\_timestamp is a value generated by the dds layer

(nit) precisely rmw implementation, not DDS.

So this is required and responsibility for rmw implementation, as far as i see all tier-1 implementation does that.

> In order to link publish to subscription, I use the information of source\_timestamp that dds sends with the message as a unique message ID.

i think there ia a couple of concerns,

- timestamp is not unique id. could be the same, also depends on accuracy.
- what if system time is adjusted? i am not sure if only monotonic clock is used to fill in this field?

> Source code in the development stage used for the hooks in LD\_PRELOAD can be found here.

i see, that is `hot-patch`.

> Messages entering and leaving the callback are different types

not only for types but also rate/frequency would be different. assuming subscription takes 3 messages and publisher publishes 1 message. in this case, we can still trace the message?

btw, this is on-target(localhost) traceability or distributed system?

sorry for coming up with many questions, i am interested in this feature 😃

best,

---

<div class="post-metadata">

**Author:** ![christophebedard](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/christophebedard/32/1514_2.png) [@christophebedard](https://discourse.openrobotics.org/u/christophebedard)\
**Post date:** [September 29, 2021, 6:46pm UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/5 "2021-09-29T18:46:05Z")

</div>

This is great, thanks for sharing @hsgwa! I also think having this kind of information is important, and I’ve been working in this direction as well. Those callback diagrams are very nice!

> [@hsgwa](#):
>
> In the future, I’m considering proposing new trace points to ROS if the measurements seem useful.

please do! You can open an issue first to start a discussion, or we can just discuss in a PR.

It looks like you’re mostly using LD\_PRELOAD to instrument DDS implementations, but just in case it might be useful, I’ve started instrumenting Cyclone DDS directly: [Add read/write instrumentation with LTTng by christophebedard · Pull Request #898 · eclipse-cyclonedds/cyclonedds · GitHub](https://github.com/eclipse-cyclonedds/cyclonedds/pull/898). It’s way more basic (currently at least) than your current LD\_PRELOADed instrumentation though.

> [@hsgwa](#):
>
> I thought using header.stamp, like the topic\_statistics built into rclcpp, but I gave up because I was concerned it would restrict the message type and destroy the stamp value.

In the message flow proof of concept for ROS 1, I tried to use network packets to match published-\>received messages, but to get it to work and be reliable, it would require a lot of work (see my “future work” notes in the blog post).

> [@tomoyafujita](#):
>
> - timestamp is not unique id. could be the same, also depends on accuracy.
> - what if system time is adjusted? i am not sure if only monotonic clock is used to fill in this field?

I’ve also been relying on the source timestamp. Personally, I’m not looking to cover all edge cases, so I think combining source timestamp + topic name (implicitly) is good enough to start. Putting aside clock adjustment (not sure what type of clock is used either), I think the probability of having messages published on the same topic with the same exact source timestamp is quite low. At the very least, you can detect situations like that when a subscription receives two messages with the same source timestamp.

> [@hsgwa](#):
>
> I’m currently trying to use FastDDS and CycloneDDS for measurements, but on\_data\_available is not working as expected.  
> on\_data\_available is not used in rmw\_cyclonedds, and there may be other better places to insert tracepoints.  
> I think it’s necessary if we want to evaluate pure (not dependent on scheduling communication latency though.  
> I don’t know much about the DDS and rmw, so I would be glad if you could comment on this as well.

@eboasson has given me some great tips about the internals of Cyclone DDS (+ I found [some cool docs](https://github.com/eclipse-cyclonedds/cyclonedds/tree/master/docs/dev)). Perhaps he and eProsima people could comment on this (or under an issue) and give some pointers for their respective DDS implementations?

> [@tomoyafujita](#):
>
> not only for types but also rate/frequency would be different. assuming subscription takes 3 messages and publisher publishes 1 message. in this case, we can still trace the message?

I’ve also been thinking about this ever since I worked on the message flow thing for ROS 1. Could you provide/link to an example where this happens? I think taking a specific use-case/example and applying some sort of heuristic based on knowledge of the implementation could work. Then for the trace data analysis part, the user (i.e., person running the analysis) has to provide information about the sub-\>pub type/behaviour for the data to be correctly interpreted. Another option is to provide an application-level tracepoint so that developers can provide this “link” themselves. Personally I’m always aiming for all of this instrumentation to be hidden from developers, but for these special use-cases it might be the best solution.

---

<div class="post-metadata">

**Author:** ![hsgwa](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/hsgwa/32/8753_2.png) [@hsgwa](https://discourse.openrobotics.org/u/hsgwa)\
**Post date:** [October 1, 2021, 3:43am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/6 "2021-10-01T03:43:34Z")

</div>

@tomoyafujita

Thanks for the questions!  
I’m trying to organize my thoughts as I answer them, so it’s much appreciated 😄

> - timestamp is not unique id. could be the same, also depends on accuracy.

If the timestamps are the same, the measurement results will be out of whack.  
However, as cristophe said, I think we can reduce the possibility by adding other information.

If we use source timestamp, topic name, and publisher GID, I think we can reduce the possibility even more.

> - what if system time is adjusted? i am not sure if only monotonic clock is used to fill in this field?

If source timestamp returned, results aren’t effected what clock is used to get the source\_timestamp as long as the value is not duplicated.  
However, returning time raises the possibility of duplicated source timestamp.

I also did some search on the clocks used by lttng. ([[lttng-dev] LTTng Time Stamp Issue](https://lists.lttng.org/pipermail/lttng-dev/2018-April/027993.html))  
lttng outputs monotonic and realtime values at initialization, and uses motoconic clock to measure the trace points.  
Since trace points use monotonic clock, the measurement results should not be affected.

> not only for types but also rate/frequency would be different. assuming subscription takes 3 messages and publisher publishes 1 message. in this case, we can still trace the message?

I think complete tracking is difficult when there are multiple inputs and outputs or different frequency, but there are several ways to do it.

One is to track with the assumption that the most recent message received will be used.  
The source code looks something like this.

```auto
class Node {
 void timer_callback(void){
   pub_->publish(msg);
 }
 void subscription_callback(msg_){
   msg = msg_;
 }
}

```

This is the case where the member variable is always overwritten with the latest message.  
Messages that are not used due to overwriting are counted as lost.

Not all implementations are covered by the first method.  
Specifically, there is a case where a message is put into a buffer and used based on its timestamp.  
For example: fusion using message\_filter’s synchronizer and tf listener.  
I’m thinking of tracking these by matching the timestamp value in the callback input/output.

> btw, this is on-target(localhost) traceability or distributed system?

I’m thinking of limiting it to localhost for now.  
LTTng uses monotonic as described above.  
If multiple monotonic units go at different speeds, the analysis results will be out of whack.  
When I compared clock\_monotonic and real-time on a Raspberry Pi, there was a discrepancy of 4ms in 2 minutes.  
For example, if the measurement is for a short period of time, say 1 minute, it may be possible to use it without deviating from the analysis results.

Just an idea, the two monotonic clocks simply are linearly misaligned.  
So, if we include a process to adjust the time to a single clock, it may be applied to distributed systems.

---

<div class="post-metadata">

**Author:** ![hsgwa](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/hsgwa/32/8753_2.png) [@hsgwa](https://discourse.openrobotics.org/u/hsgwa)\
**Post date:** [October 1, 2021, 4:37am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/7 "2021-10-01T04:37:47Z")

</div>

@christophebedard  
Thanks for the comment!

> please do! You can open an issue first to start a discussion, or we can just discuss in a PR.  
> I’ve started instrumenting Cyclone DDS directly:

I’m currently thinking about the goal of measuring against Autoware, and I haven’t even settled on the trace points I want to add yet.  
I will make a proposal after some more verification.  
Since there are multiple implementations of DDS, I thought it would be difficult to add tracepoints to DDS.  
Right now I’m adding trace points by LD\_PRELOAD, but I am in favor of it being officially adopted 😉

> Could you provide/link to an example where this happens?

The message\_synchronizer is difficult in the following ways

- Having messages buffered and selecting messages from the buffer based on the timestamp value.
- The other is the complexity of the graph of multiple callbacks.

Ths source code can be found here.

> <https://github.com/tier4/AutowareArchitectureProposal.iv/blob/main/sensing/preprocessor/pointcloud/pointcloud_preprocessor/src/concatenate_data/concatenate_data_nodelet.cpp#L311>

The general flow of the process is as follows

1. receive each LiDAR data
2. as soon as the three LiDAR data are available, combine the most recent values and publish
3. If the third LiDAR message is not received (in case of failure), the timer callback will combine the two LiDAR data and publish.  
[Each message will be published only once.]

The autoware doesn’t use the message filter, but uses similar implements on its own, in order to publish with two messages even if the third LiDAR message is not delivered.

In such nodes, message passing by member variables occur, and the callback graph becomes more complex.

For example, if we write a callback graph, it would look like this.

Implementation Intent

 ![g11529](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/1/16ef767a443eb0166ace0a623501c09c8ddc0926.png)

Draw each callback separately

 ![g11578](https://us1.discourse-cdn.com/flex022/uploads/ros/original/2X/8/843ebd40e9ce36b20e0c9a4a90b97d80c94c6d01.png)

Since the callback graphs of these nodes are too complex, I think developers need to give the necessary information to create the callback graphs.

---

<div class="post-metadata">

**Author:** ![Paulinho](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/paulinho/32/9605_2.png) [@Paulinho](https://discourse.openrobotics.org/u/Paulinho)\
**Post date:** [October 5, 2021, 8:55am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/8 "2021-10-05T08:55:55Z")

</div>

> [@hsgwa](#):
>
> [add: tracepoint definitions · tier4/rclcpp@3d050be · GitHub](https://github.com/tier4/rclcpp/commit/3d050be42e3e7ab6a8f84dce598a19df537f8246)

I am involved in standardisation and safety assessment/testing.  
So far your work is highly interesting to me as a possibly way to perform verification of performance of safety related ROS nodes part of safety control loops and systems.

Most interesting would be to couple this checks with the actual performance of a robot for example tested for performance or for safety.  
Any idea on this?

---

<div class="post-metadata">

**Author:** ![hsgwa](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/hsgwa/32/8753_2.png) [@hsgwa](https://discourse.openrobotics.org/u/hsgwa)\
**Post date:** [October 7, 2021, 4:57am UTC](https://discourse.openrobotics.org/t/consideration-of-performance-measurement-methods/22453/9 "2021-10-07T04:57:31Z")

</div>

If we can produce a message flow, we can evaluate the performance of across multiple nodes.  
For example, it would be nice to measure the time it takes for a message to enter the sensor node and be reflected in the actuator node.  
However, I think it is important to note we can only track the message flow, not the actual movement of the actuator.

I don’t know much about the safety aspect, and this is just an idea, but by using hooks, it may be possible to test the deadline missed behavior.  
For example, hook callback\_start and callback\_end with LD\_PRELOAD and intentionally insert a wait.  
This will have the same effect as increasing the callback duration.  
we can test to make the process exceed the deadline without having to prepare sensor data that requires more processing time.