Add tracing instrumentation for intra-process

[ymski]

Overview

Hi, I'm a member of CARET development team. We would like to officially support some tracepoints added by caret in the rclcpp fork and LD_PRELOAD.
The current tracetools do not support intra-process communication. This Pull Request adds tracing instrumentation to calculate the processing time from publish to subscription callback. These trace points are important in performance analysis. Processing that may become a bottleneck, such as strict time constraints or handling large data, often uses intra-process communication.

[ymski]

Tracepoints

We propose to add the following tracepoints mainly targeting ring buffers.
Tracepoint details:

• rclcpp_intra_publish

  • Tracepoint for intra-process communication. Unlike inter-process communication, intra-process communication may result in data copying. For this reason, rclcpp_intra_publish is defined separately from rclcpp_publish, which has similar arguments.
  • args
    • publisher_handle: publisher handle address.
    • message: message address.

• construct_ring_buffer

  • Tracepoint for construction.
  • args
    • buffer: buffer address.
    • capacity: buffer capacity.

• ring_buffer_enqueue

  • Tracepoint for enqueuing. Used for binding of published and subscribed messages by index.
  • args
    • buffer: buffer address.
    • index: Index to which messages are written
    • overwriting_occurred: Indicates whether Lost has occurred.

• ring_buffer_dequeue

  • Tracepoint for dequeuing. Used for binding of published and subscribed messages by index.
  • args
    • buffer: buffer address.
    • index: Index to which messages are read.

• ring_buffer_clear

  • Not used, but only API is provided
  • args
    • buffer: buffer address.

[ymski]

Sequence diagram

The following may be helpful as a sequence of processing related to the trace points we have added.

enqueue:

dequeue:

dispatch:

[ymski]

The relationship between each tracepoint is summarized in the following ER diagram.

We are now able to track messages communicated using intra-process as below.

---

The above method of tracking messages using thread id can be used based on the following condition

• the thread id does not change during publish, subscription, etc.

We are concerned that changes in specifications due to future ROS2 development may make the above methods unavailable.

[ymski]

Notes

Since this PR has multiple repositories in scope, it is necessary to make changes to multiple repositories at the same time.

See also:

• Add intra process tracepoint ros2_tracing#30

[fujitatomoya]

@christophebedard

The current tracetools do not support intra-process communication.

Is this intention? i do not really know the history, but adding intra-process communication tracepoint could be useful?

@ymski once it is ready to review, we are happy to review. and probably it would be nice to talk about this Client WG as well.

[christophebedard]

Happy to see this PR @ymski!

The current tracetools do not support intra-process communication.

Is this intention? i do not really know the history, but adding intra-process communication tracepoint could be useful?

@fujitatomoya we indeed never instrumented intra-process communications in a way that allows tracking messages from publication to callback, because supporting the default use-case (i.e., network) was enough. If you search for "intra" in the ros2_tracing design document, you'll see that intra-process subscriptions/callbacks are supported/instrumented, but that's not enough to track messages from publication to callback: https://github.com/ros2/ros2_tracing/blob/rolling/doc/design_ros_2.md. This is definitely useful.

[christophebedard]

The above method of tracking messages using thread id can be used based on the following condition

• the thread id does not change during publish, subscription, etc.

We are concerned that changes in specifications due to future ROS2 development may make the above methods unavailable.

I understand that this works currently, but yeah it might stop working in the future.

Instead of relying on the TID to link an rclcpp_intra_publish event to its corresponding ring_buffer_enqueue event and link a ring_buffer_dequeue event to its corresponding callback_start, is there a way to link the publisher handle to the ring buffer address and link the subscription handle to the ring buffer address?

I've taken a quick look at the intra-process code, and this seems a bit hard to do due to all the layers (RingBufferImplementation/TypedIntraProcessBuffer) and the fact that the ring buffer seems to be owned by the subscription. It might require a new tracepoint before/after construct_ring_buffer.

This would allow linking publisher handle/message -> buffer address -> index -> callback, which would be more robust and would probably not break in the future.

Note that tracepoints are part of the tracetools ABI (even if it's not a public API/ABI like rclcpp is), so having to change the tracepoints (e.g., removing some of them or modifying their arguments) in the future would lead to a bit of a headache.

[ymski]

Thank you for your reply. The draft PR was used to confirm the error in the GitHub Actions, but it does not seem to be resolved without merging the relevant PR. I have now changed from draft PR to PR. I think we should continue this discussion on the issues mentioned above.

[ymski]

Thank you for your comment. @fujitatomoya

probably it would be nice to talk about this Client WG as well.

I am glad you said this.
But I am sorry, I am not a good English speaker, so it would be helpful if we could talk on a text.

---

Thank you for your comment. @christophebedard
As we were concerned, the method of using TID may not work in the future.
We will reconsider the trace points, including linking publisher_handle to buffer_address.
Incidentally, I believe you are considering linking using message addresses. To do this, I think we need to add a tracepoint for each copy of the message.
Since we have copies everywhere in rclcpp, we are concerned that adding tracepoints for all of them would have a large scope.
For reference, here is what we did with CARET to add tracepoints to the copies. message_construct is the tracepoint for copy.

• tier4@f771072

[fujitatomoya]

@ymski thanks for iterating, i am happy to do review on this 👍

[fujitatomoya]

waiting for another review, and after that i will start CI.

[ymski]

waiting for another review, and after that i will start CI.

@fujitatomoya
Thank you for approving. However, after discussion with @christophebedard, it looks like the trace points will need to be changed. Sorry, but it would be helpful if you could wait a bit longer to start the CI.

[ymski]

@christophebedard
I understand that for robustness reasons it is preferable to link by address.I have been thinking about how to link tracepoints using message addresses. It would be possible to link everything from rclpp_intra_publish to ring_buffer_dequeue by address if a tracepoint (construcrt_message((original_message_address, new_message_address))is added for each copy of the message.

By changing the index argument of the trace point of ring_buffer to message address, the following link can be created.
rclcpp_intra_publish -(original_message_address)-> copy_message -(new_message_address)-> ring_buffer_enqueue
The pubsiher_handle and buffer links may no longer be necessary if tracepoints are added for copies of messages.

I think the link on the enqueue side is now OK, but the link without TID on the dequeue side is still unresolved. I think this is the same problem as the way rclcpp_take and callback_start are linked in ros2_tracing, but I couldn't find in the documentation how this is achieved. How does ros2_tracing solve this?

I think if there is a trace point like rclcpp_dipatch_subscription(&callback, &message) during dispatch, it would be possible to link them by address.

[ymski]

Hi, @christophebedard !
I thought I was missing an explanation of the method proposed above, so I will capture it. Suppose we have a link between publisher_handle and buffer_address. However, this assumption alone may not work when publishing is done in asynchronous multi-threaded mode, as in the example below.

The following is an extract from the trace data, showing only the trace points of rclcpp_intra_pub and callback_start, the events for which the processing time is to be measured. Here we consider matching rclcpp_intra_publish and callabck_start.

rclcpp_intra_publish(@publisher_handler1, @msg1)    #1
rclcpp_intra_publish(@publisher_handler2, @msg2)    #2
callback_start(@callback)    #???
callback_start(@callback)    #???

In this case, the matching between rclcpp_intra_publish and callback_start is not determined as shown in case1, case2.

case1

rclcpp_intra_publish(@publisher_handler1, @msg1)    #1
rclcpp_intra_publish(@publisher_handler2, @msg2)    #2
enqueue(msg1)
enqueue(msg2)
dequeue(msg1)
callback_start(@callback)    #1
dequeue(msg2)
callback_start(@callback)    #2

case2

rclcpp_intra_publish(@publisher_handler1, @msg1)    #1
rclcpp_intra_publish(@publisher_handler2, @msg2)    #2
enqueue(msg2)
dequeue(msg2)
callback_start(@callback)    #2
enqueue(msg1)
dequeue(msg1)
callback_start(@callback)    #1

The same problem can occur when copying messages. This is due to the lack of information about where the messages used to execute the callback came from. Therefore, the method described above is proposed to trace the messages.

case1 with message track:

rclcpp_intra_publish(@publisher_handler1, @msg1)    #1
rclcpp_intra_publish(@publisher_handler2, @msg2)    #2
enqueue(msg1)
enqueue(msg2)
dequeue(msg1)
dispatch_callback(@msg1, @callback)
callback_start(@callback)    #1
dequeue(msg2)
dispatch_callback(@msg2, @callback)
callback_start(@callback)    #2

(note: It might be more ideal if callback_start had a message address)

What do you think of the robustness of this approach?

[christophebedard]

@ymski thank you for the example.

Just to take a step back:

On the publisher side, I think we might be able to assume that rclcpp_intra_publish and ring_buffer_enqueue always happen on the same thread. Therefore, we could use the TID to link the events. We would then avoid needing the "message copy" tracepoint. However, if there are N intraprocess subscriptions with the same topic, I think we'll get N ring_buffer_enqueue events after a single rclcpp_intra_publish event, correct? Then we just have to make sure we can link the rclcpp_intra_publish event to all N ring_buffer_enqueue events (e.g., all consecutive ring_buffer_enqueue events after a rclcpp_intra_publish event on the same thread).

On the subscription side, we shouldn't assume that ring_buffer_dequeue and callback_start happen on the same thread. Then I think your solution makes sense.

@wjwwood what do you think?

[christophebedard]

I think this is the same problem as the way rclcpp_take and callback_start are linked in ros2_tracing, but I couldn't find in the documentation how this is achieved. How does ros2_tracing solve this?

rclcpp_take is linked to the rcl_take and rmw_take events by expecting the events to happen in the following order with the same message value: rmw_take, rcl_take, and rclcpp_take. Note that rcl_take isn't really useful here, and we don't need to assume that the events happen on the same thread.

rclcpp_take's rmw_subscription_handle field is linked to the subscription handle (rcl) using information collected during initialization: rcl_subscription_init contains both the subscription handle and the rmw_subscription_handle.

Then the callback field of the callback_start/callback_end tracepoints is mapped to the subscription handle using information collected during initialization: rclcpp_subscription_callback_added contains both the subscription handle and the callback.

So the callback_start/callback_end events can be linked to the *_take events and the message and source_timestamp values. And, as you probably know, this source_timestamp value then allows us to link this message to the original message on the publisher's side.

[ymski]

@christophebedard thanks for sharing how to link in ros2 tracing. I also understand the method you suggested.

However, if there are N intraprocess subscriptions with the same topic, I think we'll get N ring_buffer_enqueue events after a single rclcpp_intra_publish event, correct?

I think the same. Here is an extract of the trace data when the subscription of the cyclic_pipeline demo is simply increased to two. They have the same TID and can be linked.
(Please note that there are differences in variable names and additional trace points)

[18:04:10.875980976] (+0.000000866) docker ros2:callback_start: { cpu_id = 3 }, { vpid = 12595, vtid = 12595, procname = "cyclic_pipeline" }, { callback = 0x556C47321A20, is_intra_process = 1 }
[18:04:11.876125164] (+1.000144188) docker ros2:rclcpp_intra_publish: { cpu_id = 3 }, { vpid = 12595, vtid = 12595, procname = "cyclic_pipeline" }, { publisher_handle = 0x556C472E8510, message = 0x556C47470620 }
[18:04:11.876133342] (+0.000008178) docker ros2:message_construct: { cpu_id = 3 }, { vpid = 12595, vtid = 12595, procname = "cyclic_pipeline" }, { original_message = 0x556C47470620, constructed_message = 0x556C47470660 }
[18:04:11.876136013] (+0.000002671) docker ros2:ring_buffer_enqueue: { cpu_id = 3 }, { vpid = 12595, vtid = 12595, procname = "cyclic_pipeline" }, { buffer = 0x556C47458100, index = 4, is_full = 0 }
[18:04:11.876139450] (+0.000003437) docker ros2:ring_buffer_enqueue: { cpu_id = 3 }, { vpid = 12595, vtid = 12595, procname = "cyclic_pipeline" }, { buffer = 0x556C4746CDC0, index = 4, is_full = 0 }
[18:04:11.876142329] (+0.000002879) docker ros2:callback_end: { cpu_id = 3 }, { vpid = 12595, vtid = 12595, procname = "cyclic_pipeline" }, { callback = 0x556C47321A20 }

I understand the linking method of the publisher's side as follows.

The linking method by TID can be used to obtain a list of enqueued addresses.

On the other hand, the linking method using the publisher_handle and buffer address can obtain a list of addresses that may be enqueued. (although this can be a bit of a pain if subscriptions are added later). This requires using the information at initialization (e.g. rcl_publisher_init, rcl_subscription_init, rclcpp_buffer_init(exactly what we want right now.)).

Is this understanding correct?

[christophebedard]

I'm not sure I understand what the constructed_message value in the ros2:message_construct tracepoint is for. Could you share the complete trace, or a portion of the trace that contains all relevant tracepoints (i.e., all init tracepoints, all publisher and subscription tracepoints)?

[ymski]

I am sorry @christophebedard
I thought I had to respond quickly and gave you data with unnecessary trace point logs. Sorry for the confusion. (construct_message was an experimental trace point I added to track a copy of the message. It is not yet included in this PR).

I thought we wanted to make sure the tid matched for successive enqueues. In that case, the following repository, which contains examples of measured applications and trace data, would be helpful.

• https://github.com/ymski/intra_process_demo

By the way, I am not going to stick to the tid linking method. My concern was the magnitude of the impact of adding trace points to track copies, and I think a linking method that does not use tid is a healthier and preferable implementation for the ros2 project.

[christophebedard]

Thank you, that repository and example traces are helpful. Let me know once you implement the solution to avoid linking using TIDs for both pub and sub.

Also, how do you plan on linking the ring buffer to its subscription, i.e., rcl_subscription_init to construct_ring_buffer? Do you simply assume that the construct_ring_buffer event always comes after the rcl_subscription_init event on the same thread? Example from the 1pub-2sub-two-thread trace in your repository:

ros2:rcl_subscription_init: { cpu_id = 10 }, { vpid = 3862, procname = "cyclic_pipeline", vtid = 3862 }, { subscription_handle = 0x5582898F8160, node_handle = 0x558289624560, rmw_subscription_handle = 0x5582899099A0, topic_name = "/topic1", queue_depth = 10 }
ros2:construct_ring_buffer: { cpu_id = 10 }, { vpid = 3862, procname = "cyclic_pipeline", vtid = 3862 }, { buffer = 0x558289909F00, capacity = 10 }

[ymski]

Do you simply assume that the construct_ring_buffer event always comes after the rcl_subscription_init event on the same thread?

No. It would not be a good idea to make the above assumption if we do not use TIDs for links. As you know, the tracepoints added in the current PR are not enough to link subscriptions and buffers. Therefore, I am considering adding a tracepoint called rclcpp_buffer_init(topic_name, buffer) to subscription_intra_process_buffer.hpp. The relationship between each trace point is shown in the diagram below.

• Red node is the run-phase tracepoint.
• Yellow node is the init-phase tracepoint.
• Solid lines are combinations of nodes that can be directly linked.
• Dotted lines represent combinations that can be linked via tracepoints during initialization. It is the relationship between trace points that were linked using TID.

[christophebedard]

Therefore, I am considering adding a tracepoint called rclcpp_buffer_init(topic_name, buffer) to subscription_intra_process_buffer.hpp.

I'm guessing your diagram should link rclcpp_buffer_init to rclcpp_subscription_init/rcl_subscription_init instead of rcl_publisher_init, since the buffer belongs to the subscription?

Also, what if you have 2 subscription with the same topic name? You wouldn't be able to know which buffer corresponds to which subscription. Or do you assume that a publisher with a given topic name will always put the message in the ring buffers of subscriptions with the same topic name?

[ymski]

Thanks fou your comment @christophebedard
The above post was a bad idea. Please forget about it. (There are a few things wrong with the diagram too)

I will rethink it, including your advice. This may take some time.

[ymski]

@christophebedard
Sorry for the delay in responding.
I have considered how to link them without using TID. The conclusion is that on the dequeue side you can link without using a TID, but on the enqueue side it appears that we need to use a TID. The details are as follows.

• link publish and enqueue
  Unfortunately, it does not seem to be possible to add a trace point to find out which publisher enqueued to which buffer. It is preferable to use the TID method here.

• link dequeue and callback_start
  It appears that subscriptions and buffers can be linked as follows.
  A test implementation can be found below.

  • 55cbbd6

  • ros2/ros2_tracing@4f5dda9

This shows the relationship between trace points, including newly added.

[christophebedard]

@ymski looking at it quickly, that looks good. I'll try generating a trace using your intra_process_demo and look at the output to properly validate.

One question: do you link the dispatched message to the callback (buffer dequeue -> callback start/end) by simply taking the next callback start event for the subscription corresponding to the buffer? Or do you want to add another tracepoint to link the dispatched message to the callback start event (as you suggested), or possibly add a new message field to the callback_start tracepoint?

[ymski]

@christophebedard thank you for your review.

One question: do you link the dispatched message to the callback (buffer dequeue -> callback start/end) by simply taking the next callback start event for the subscription corresponding to the buffer? Or do you want to add another tracepoint to link the dispatched message to the callback start event (as you suggested), or possibly add a new message field to the callback_start tracepoint?

Thank you for your question about dispatched message to the callback. I was just about to discuss that as well. I think from a robustness point of view it would be desirable to add trace points using message addresses. As for how to add information about the message address, I think it should be convenient for future development of ros2_tracing. As a maintainer, what do you think is better?

[christophebedard]

In general, I would prefer adding a message address field to the existing callback_start event instead of creating a new tracepoint just for this. The callback_start tracepoint is used for subscription, service, and timer callbacks, so the message address value could be nullptr for timer callbacks, since there are no messages for timer callbacks.

However, I think we don't strictly need it for the moment: it currently works fine in ROS 2 (as I explained in #2091 (comment)) and it should work fine for this (as I mentioned above). Since the message address can be re-used anyway (so you could get multiple calback_start events for the same callback and with the same message address value), you must still match the message to the callback using the order of the events, so it doesn't make the process that much more robust. Therefore, I would prefer not to do that until we think we really need it.

[ymski]

@christophebedard
Thanks for the discussion and confirmation of the trace points. I have implemented what you have summarised in the discussion so far and updated the PR.

By the way, we use the buffer index to trace messages, but now that I think about it, it seems more appropriate to use addresses. Is it OK to switch to tracepoints using addresses?

Also, as I mentioned in the discussion above, it would be useful to be able to see how much data has accumulated in the buffer. If there is demand, the number of data could be included in ring_buffer_enqueue and ring_buffer_dequeue. (However, this can still be done with the current trace points by counting the trace data to check the number of pieces of data in the queue. This suggestion is not essential for knowing the number of data in the queue, so this may be an inappropriate suggestion from the point of view of the minimum configuration of tracepoints.)

[mjcarroll]

By the way, we use the buffer index to trace messages, but now that I think about it, it seems more appropriate to use addresses. Is it OK to switch to tracepoints using addresses?

I think addresses make sense for consistency.

Also, as I mentioned in #2091 (comment), it would be useful to be able to see how much data has accumulated in the buffer. If there is demand, the number of data could be included in ring_buffer_enqueue and ring_buffer_dequeue.

In my mind, while the value can be reconstructed, this seems like a relatively cheap thing to trace to avoid having going through that exercise.

[ymski]

@mjcarroll I am glad to hear that comment. Unfortunately though, when I thought about the implementation, it turned out that replacing the index with a message address might be a bit difficult. This is due to the template implementation of the ring buffer. As the results of the analysis are not affected by either index or message address, I will adopt the index. I have also added accumulated data to record the number of data stored internally in the enqueue and dequeue of the ring buffer.

If there are no problems with the trace points to be added, we can proceed to code review. What do you think @christophebedard ?

[christophebedard]

Sorry for the delay, I've been pretty busy. I'll take a look tomorrow.

Unfortunately though, when I thought about the implementation, it turned out that replacing the index with a message address might be a bit difficult. This is due to the template implementation of the ring buffer.

Makes sense. Indexes are fine then.

[christophebedard]

Some of these suggestions correspond to my suggestions in the ros2_tracing PR.

Sorry again for the delay.

[christophebedard]

This looks good from my side (see ros2/ros2_tracing#30). I'll let @fujitatomoya rebase the branch on rolling and review, then I'll run CI. Then we can squash and merge this eventually.

[fujitatomoya]

Unfortunately though, when I thought about the implementation, it turned out that replacing the index with a message address might be a bit difficult. This is due to the template implementation of the ring buffer.

Makes sense. Indexes are fine then.

i think that in design, this information is better to be cached in the data object (in this particular case, ring buffer), not handlers nor users.
and indexes are just fine to use for these cases, i believe.

[christophebedard]

@ymski can you squash the commits into a single commit and rebase on the latest version of the rolling branch?

[ymski]

@fujitatomoya
Thank you very much for reviewing this PR. I apologize for the delay in responding after submitting the PR. Thanks to your feedback, we have been able to make it this far.

@christophebedard
Thank you for providing additional details about the code. It was very helpful. I have completed the squash and rebase.

[christophebedard]

CI for this PR and ros2/ros2_tracing#30 is over at ros2/ros2_tracing#30 (comment)

[christophebedard]

CI looks good. I merged the ros2_tracing PR. @fujitatomoya can you merge this one?