diff --git a/doc/design_ros_2.md b/doc/design_ros_2.md index 15767cf3..878cbc85 100644 --- a/doc/design_ros_2.md +++ b/doc/design_ros_2.md @@ -151,6 +151,11 @@ The following table summarizes the instrumentation and links to the correspondin | | `rmw_subscription_init` | [*Subscription creation*](#subscription-creation) | | | `rmw_publish` | [*Message publishing*](#message-publishing) | | | `rmw_take` | [*Subscription callbacks*](#subscription-callbacks) | +| | `rmw_client_init` | [*Client creation*](#client-creation) | +| | `rmw_take_request` | [*Service callbacks*](#service-callbacks) | +| | `rmw_send_response` | [*Service callbacks*](#service-callbacks) | +| | `rmw_send_request` | [*Client request/response*](#client-requestresponse) | +| | `rmw_take_response` | [*Client request/response*](#client-requestresponse) | ### General guidelines @@ -438,6 +443,8 @@ For simple messages without loaning, it simply gets deallocated. * Link to handle(s) of subscription being executed * Message being taken * Source timestamp of message being taken + * To link message being taken to the same message being published + * Note: there could be collisions if multiple publishers publish a message on the same topic at the exact same time (depending on clock resolution), but it's unlikely * Link to callback object being dispatched, with start/end timestamps * Whether the callback dispatching is for intra-process or not @@ -575,7 +582,7 @@ The node calls `rclcpp::create_service()` which ends up creating a `rclcpp::Serv In its constructor, it allocates a `rcl_service_t` handle, and then calls `rcl_service_init()`. This processes the handle and validates the service name. It calls `rmw_create_service()` to get the corresponding `rmw_service_t` handle. -`rclcpp::Service` creates an `rclcpp::AnySubscriptionCallback` object and associates it with itself. +`rclcpp::Service` creates an `rclcpp::AnyServiceCallback` object and associates it with itself. **Important information**: * Link between `rcl_service_t` and `rmw_service_t` handles @@ -616,16 +623,17 @@ It then calls `rclcpp::Service::take_type_erased_request()`, which calls `rcl_ta If those are successful and a new request is taken, then the `rclcpp::Executor` calls `rclcpp::Service::handle_request()` with the request. This casts the request to its actual type, allocates a response object, and calls `rclcpp::AnyServiceCallback::dispatch()`, which calls the actual `std::function` with the right signature. +Depending on the service callback signature, a response object could be provided to the callback to be populated, a reference to the service could be used to send a response from inside the callback, or a response could be sent later. If there is a service response for the request, `rclcpp::Service::send_response()` is called, which calls `rcl_send_response()` & `rmw_send_response()`. **Important information**: +* Link to handle(s) of service being executed * Request being taken * Link to callback object being dispatched, with start/end timestamps -* TODO - * Link to handle(s) of service being executed - * Source timestamp of request being taken - * Link between request and response +* Sequence number and client GID of request being taken +* Sequence number and client GID of request that a response is for +* Source timestamp of response being sent ```mermaid sequenceDiagram @@ -644,17 +652,19 @@ sequenceDiagram Executor->>Service: take_type_erased_request(out request *, out request_id): bool Service->>rcl: rcl_take_request(rcl_service *, out request_header *, out request *) rcl->>rmw: rmw_take_request(rmw_service_t *, out request_header *, out request *, out taken) + rmw-->>tracetools: TP(rmw_take_request, rmw_service_t *, request *, client_gid, sequence_number, taken) opt taken Executor->>Service: handle_request(request_header *, request *) Note over Service: casts request to its actual type Note over Service: allocates a response object - Service->>AnyServiceCallback: dispatch(request_header, typed_request): response + Service->>AnyServiceCallback: dispatch(service, request_header, request): response AnyServiceCallback-->>tracetools: TP(callback_start, rclcpp::AnyServiceCallback *) Note over AnyServiceCallback: std::function(...) AnyServiceCallback-->>tracetools: TP(callback_end, rclcpp::AnyServiceCallback *) opt response Service->>rcl: rcl_send_response(rcl_service_t *, request_header *, response *) rcl->>rmw: rmw_send_response(rmw_service_t *, request_header *, response *) + rmw-->>tracetools: TP(rmw_send_response, rmw_service_t *, response *, client_gid, sequence_number, timestamp) end end ``` @@ -666,10 +676,12 @@ The node calls `rclcpp::create_client()` which ends up creating a `rclcpp::Clien In its constructor, it allocates a `rcl_client_t` handle, and then calls `rcl_client_init()`. This validates and processes the handle. It also calls `rmw_create_client()` which creates the `rmw_client_t` handle. +`rmw` creates or associates the `rmw_client_t` handle with *a* GID, since client `rmw` implementations use multiple DDS objects that have GIDs (e.g., request publisher, response subscription). **Important information**: * Link between `rcl_client_t` and `rmw_client_t` handles * Link to corresponding node handle +* Link to corresponding client GID * Service name ```mermaid @@ -689,6 +701,7 @@ sequenceDiagram Note over rcl: validates and processes rcl_client_t handle rcl->>rmw: rmw_create_client(rmw_node_t *, service_name, qos_options): rmw_client_t Note over rmw: creates rmw_client_t handle + rmw-->>tracetools: TP(rmw_client_init, rmw_client_t *, gid) rcl-->>tracetools: TP(rcl_client_init, rcl_client_t *, rcl_node_t *, rmw_client_t *, service_name) ``` @@ -708,13 +721,12 @@ This waits until the future object is ready, or until timeout, and returns. If this last call was successful, then the node can get the result (i.e., response) and do something with it. **Important information**: -* TODO - * Link to handle(s) of client - * Request being sent, with timestamp - * Link to callback object being used, with start/end timestamps - * Response being taken - * Source timestamp of response being taken - * Link to response +* Link to handle(s) of client +* Sequence number of request being sent +* Sequence number of request that a response being taken is for +* Source timestamp of response being taken + * To link response being taken to the same response being sent + * Note: there could be collisions if multiple services replied to the same request at the exact same time (depending on clock resolution), but it's unlikely ```mermaid sequenceDiagram @@ -730,11 +742,11 @@ sequenceDiagram Note over node: creates request node->>Client: async_send_request(request[, callback]): result_future - Client->>rcl: rcl_send_request(rcl_client_t, request, out sequence_number): int64_t + Client->>rcl: rcl_send_request(rcl_client_t, request *, out sequence_number): int64_t Note over rcl: assigns sequence_number %% rcl-->>tracetools: TP(rcl_send_request, rcl_client_t *, sequence_number) - rcl->>rmw: rmw_send_request(rmw_client_t, request, sequence_number) - %% rmw-->>tracetools: TP(rmw_send_request, sequence_number) + rcl->>rmw: rmw_send_request(rmw_client_t, request *, sequence_number) + rmw-->>tracetools: TP(rmw_send_request, rmw_client_t *, request *, sequence_number) Note over Client: puts sequence_number in a 'pending requests' map with promise+callback+future alt without callback @@ -753,7 +765,7 @@ sequenceDiagram Executor->>Client: take_type_erased_response(response *, header *): bool Client->>rcl: rcl_take_response*(rcl_client_t *, out request_header *, out response *) rcl->>rmw: rmw_take_response(rmw_client_t *, out request_header *, out response *, out taken) - %% rmw-->>tracetools: TP(rmw_take_response) + rmw-->>tracetools: TP(rmw_take_response, rmw_client_t *, response *, sequence_number, source_timestamp, taken) %% rcl-->>tracetools: TP(rcl_take_response) opt taken Executor->>Client: handle_response(request_header *, response *) diff --git a/test_tracetools/CMakeLists.txt b/test_tracetools/CMakeLists.txt index 130da424..ff16b9a0 100644 --- a/test_tracetools/CMakeLists.txt +++ b/test_tracetools/CMakeLists.txt @@ -203,13 +203,11 @@ if(BUILD_TESTING) # Tests to run with the default rmw implementation, which should not matter set(_test_tracetools_pytest_tests test/test_buffer.py - test/test_client.py test/test_executor.py test/test_intra.py test/test_intra_pub_sub.py test/test_lifecycle_node.py test/test_node.py - test/test_service.py test/test_timer.py ) foreach(_test_path ${_test_tracetools_pytest_tests}) @@ -223,10 +221,13 @@ if(BUILD_TESTING) # Tests to run with all instrumented/supported rmw implementations set(_test_tracetools_pytest_tests_multi_rmw + test/test_client.py test/test_generic_pub_sub.py test/test_generic_subscription.py test/test_pub_sub.py test/test_publisher.py + test/test_service.py + test/test_service_req_resp.py test/test_subscription.py ) set(_test_tracetools_rmw_implementations diff --git a/test_tracetools/test/test_client.py b/test_tracetools/test/test_client.py index 2a163fa1..b698b464 100644 --- a/test_tracetools/test/test_client.py +++ b/test_tracetools/test/test_client.py @@ -28,7 +28,10 @@ def __init__(self, *args) -> None: session_name_prefix='session-test-client', events_ros=[ tp.rcl_node_init, + tp.rmw_client_init, tp.rcl_client_init, + tp.rmw_send_request, + tp.rmw_take_response, ], package='test_tracetools', nodes=['test_service_ping', 'test_service_pong'], @@ -39,11 +42,25 @@ def test_all(self): self.assertEventsSet(self._events_ros) # Check fields - client_init_events = self.get_events_with_name(tp.rcl_client_init) + rmw_client_init_events = self.get_events_with_name(tp.rmw_client_init) + rcl_client_init_events = self.get_events_with_name(tp.rcl_client_init) + rmw_send_request_events = self.get_events_with_name(tp.rmw_send_request) + rmw_take_response_events = self.get_events_with_name(tp.rmw_take_response) - for event in client_init_events: + for event in rmw_client_init_events: + self.assertValidHandle(event, 'rmw_client_handle') + self.assertValidStaticArray(event, 'gid', int, 16) + for event in rcl_client_init_events: self.assertValidHandle(event, ['client_handle', 'node_handle', 'rmw_client_handle']) self.assertStringFieldNotEmpty(event, 'service_name') + for event in rmw_send_request_events: + self.assertValidHandle(event, 'rmw_client_handle') + self.assertValidPointer(event, 'request') + self.assertFieldType(event, 'sequence_number', int) + for event in rmw_take_response_events: + self.assertValidHandle(event, 'rmw_client_handle') + self.assertValidPointer(event, 'response') + self.assertFieldType(event, ['sequence_number', 'source_timestamp', 'taken'], int) # Find node event node_init_events = self.get_events_with_name(tp.rcl_node_init) @@ -56,19 +73,43 @@ def test_all(self): ) node_handle = self.get_field(test_node_init_event, 'node_handle') - # Find client init event and check that the node handle matches - test_client_init_event = self.get_event_with_field_value_and_assert( + # Find client init events and check that the handles match + test_rcl_client_init_event = self.get_event_with_field_value_and_assert( 'service_name', '/ping', - client_init_events, + rcl_client_init_events, + allow_multiple=False, + ) + self.assertFieldEquals(test_rcl_client_init_event, 'node_handle', node_handle) + rmw_client_handle = self.get_field(test_rcl_client_init_event, 'rmw_client_handle') + test_rmw_client_init_event = self.get_event_with_field_value_and_assert( + 'rmw_client_handle', + rmw_client_handle, + rmw_client_init_events, + allow_multiple=False, + ) + + # Find rmw_send_request and rmw_take_response events + test_rmw_send_request_event = self.get_event_with_field_value_and_assert( + 'rmw_client_handle', + rmw_client_handle, + rmw_send_request_events, + allow_multiple=False, + ) + test_rmw_take_response_event = self.get_event_with_field_value_and_assert( + 'rmw_client_handle', + rmw_client_handle, + rmw_take_response_events, allow_multiple=False, ) - self.assertFieldEquals(test_client_init_event, 'node_handle', node_handle) # Check events order self.assertEventOrder([ test_node_init_event, - test_client_init_event, + test_rmw_client_init_event, + test_rcl_client_init_event, + test_rmw_send_request_event, + test_rmw_take_response_event, ]) diff --git a/test_tracetools/test/test_service.py b/test_tracetools/test/test_service.py index 308052c0..bfe52bac 100644 --- a/test_tracetools/test/test_service.py +++ b/test_tracetools/test/test_service.py @@ -31,7 +31,9 @@ def __init__(self, *args) -> None: tp.rcl_service_init, tp.rclcpp_service_callback_added, tp.rclcpp_callback_register, + tp.rmw_take_request, tp.callback_start, + tp.rmw_send_response, tp.callback_end, ], package='test_tracetools', @@ -43,13 +45,15 @@ def test_all(self): self.assertEventsSet(self._events_ros) # Check fields - srv_init_events = self.get_events_with_name(tp.rcl_service_init) + rcl_srv_init_events = self.get_events_with_name(tp.rcl_service_init) callback_added_events = self.get_events_with_name(tp.rclcpp_service_callback_added) callback_register_events = self.get_events_with_name(tp.rclcpp_callback_register) + rmw_take_request_events = self.get_events_with_name(tp.rmw_take_request) callback_start_events = self.get_events_with_name(tp.callback_start) + rmw_send_response_events = self.get_events_with_name(tp.rmw_send_response) callback_end_events = self.get_events_with_name(tp.callback_end) - for event in srv_init_events: + for event in rcl_srv_init_events: self.assertValidHandle(event, ['service_handle', 'node_handle', 'rmw_service_handle']) self.assertStringFieldNotEmpty(event, 'service_name') for event in callback_added_events: @@ -57,35 +61,46 @@ def test_all(self): for event in callback_register_events: self.assertValidPointer(event, 'callback') self.assertStringFieldNotEmpty(event, 'symbol') + for event in rmw_take_request_events: + self.assertValidHandle(event, 'rmw_service_handle') + self.assertValidPointer(event, 'request') + self.assertValidStaticArray(event, 'client_gid', int, 16) + self.assertFieldType(event, ['sequence_number', 'taken'], int) for event in callback_start_events: self.assertValidHandle(event, 'callback') # Should not be 1 for services (yet) self.assertFieldEquals(event, 'is_intra_process', 0) + for event in rmw_send_response_events: + self.assertValidHandle(event, 'rmw_service_handle') + self.assertValidPointer(event, 'response') + self.assertValidStaticArray(event, 'client_gid', int, 16) + self.assertFieldType(event, ['sequence_number', 'timestamp'], int) for event in callback_end_events: self.assertValidHandle(event, 'callback') # Find node event - node_init_events = self.get_events_with_name(tp.rcl_node_init) + rcl_node_init_events = self.get_events_with_name(tp.rcl_node_init) # The test_service_pong node is the one that has the service (server) - test_node_init_event = self.get_event_with_field_value_and_assert( + test_rcl_node_init_event = self.get_event_with_field_value_and_assert( 'node_name', 'test_service_pong', - node_init_events, + rcl_node_init_events, allow_multiple=False, ) - node_handle = self.get_field(test_node_init_event, 'node_handle') + node_handle = self.get_field(test_rcl_node_init_event, 'node_handle') # Find service init event and check that the node handle matches - test_srv_init_event = self.get_event_with_field_value_and_assert( + test_rcl_srv_init_event = self.get_event_with_field_value_and_assert( 'service_name', '/ping', - srv_init_events, + rcl_srv_init_events, allow_multiple=False, ) - self.assertFieldEquals(test_srv_init_event, 'node_handle', node_handle) + self.assertFieldEquals(test_rcl_srv_init_event, 'node_handle', node_handle) + rmw_service_handle = self.get_field(test_rcl_srv_init_event, 'rmw_service_handle') # Check that there is a matching rclcpp_service_callback_added event - service_handle = self.get_field(test_srv_init_event, 'service_handle') + service_handle = self.get_field(test_rcl_srv_init_event, 'service_handle') test_srv_callback_added_event = self.get_event_with_field_value_and_assert( 'service_handle', service_handle, @@ -116,13 +131,29 @@ def test_all(self): allow_multiple=False, ) + # Find rmw_take_request and rmw_send_response events + test_rmw_take_request_event = self.get_event_with_field_value_and_assert( + 'rmw_service_handle', + rmw_service_handle, + rmw_take_request_events, + allow_multiple=False, + ) + test_rmw_send_response_event = self.get_event_with_field_value_and_assert( + 'rmw_service_handle', + rmw_service_handle, + rmw_send_response_events, + allow_multiple=False, + ) + # Check events order self.assertEventOrder([ - test_node_init_event, - test_srv_init_event, + test_rcl_node_init_event, + test_rcl_srv_init_event, test_srv_callback_added_event, test_callback_register_event, + test_rmw_take_request_event, test_callback_start_event, + test_rmw_send_response_event, test_callback_end_event, ]) diff --git a/test_tracetools/test/test_service_req_resp.py b/test_tracetools/test/test_service_req_resp.py new file mode 100644 index 00000000..023bbf0b --- /dev/null +++ b/test_tracetools/test/test_service_req_resp.py @@ -0,0 +1,163 @@ +# Copyright 2024 Apex.AI, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import unittest + +from tracetools_test.case import TraceTestCase +from tracetools_trace.tools import tracepoints as tp +from tracetools_trace.tools.lttng import is_lttng_installed + + +@unittest.skipIf(not is_lttng_installed(minimum_version='2.9.0'), 'LTTng is required') +class TestServiceReqResp(TraceTestCase): + + def __init__(self, *args) -> None: + super().__init__( + *args, + session_name_prefix='session-test-service-req-resp', + events_ros=[ + tp.rmw_client_init, + tp.rcl_client_init, + tp.rcl_service_init, + tp.rclcpp_service_callback_added, + tp.rmw_send_request, + tp.rmw_take_request, + tp.callback_start, + tp.rmw_send_response, + tp.callback_end, + tp.rmw_take_response, + ], + package='test_tracetools', + nodes=['test_service_ping', 'test_service_pong'], + ) + + def test_all(self): + # Check events as set + self.assertEventsSet(self._events_ros) + + rmw_client_init_events = self.get_events_with_name(tp.rmw_client_init) + rcl_client_init_events = self.get_events_with_name(tp.rcl_client_init) + rcl_service_init_events = self.get_events_with_name(tp.rcl_service_init) + service_callback_added_events = self.get_events_with_name(tp.rclcpp_service_callback_added) + rmw_send_request_events = self.get_events_with_name(tp.rmw_send_request) + rmw_take_request_events = self.get_events_with_name(tp.rmw_take_request) + callback_start_events = self.get_events_with_name(tp.callback_start) + rmw_send_response_events = self.get_events_with_name(tp.rmw_send_response) + callback_end_events = self.get_events_with_name(tp.callback_end) + rmw_take_response_events = self.get_events_with_name(tp.rmw_take_response) + + # Get client + test_client_init_event = self.get_event_with_field_value_and_assert( + 'service_name', + '/ping', + rcl_client_init_events, + allow_multiple=False, + ) + rmw_client_handle = self.get_field(test_client_init_event, 'rmw_client_handle') + test_rmw_client_init = self.get_event_with_field_value_and_assert( + 'rmw_client_handle', + rmw_client_handle, + rmw_client_init_events, + allow_multiple=False, + ) + client_gid = self.get_field(test_rmw_client_init, 'gid') + + # Get service + test_service_init_event = self.get_event_with_field_value_and_assert( + 'service_name', + '/ping', + rcl_service_init_events, + allow_multiple=False, + ) + service_handle = self.get_field(test_service_init_event, 'service_handle') + rmw_service_handle = self.get_field(test_service_init_event, 'rmw_service_handle') + test_service_callback_added_event = self.get_event_with_field_value_and_assert( + 'service_handle', + service_handle, + service_callback_added_events, + allow_multiple=False, + ) + callback_ref = self.get_field(test_service_callback_added_event, 'callback') + + # Get send request + test_rmw_send_request_event = self.get_event_with_field_value_and_assert( + 'rmw_client_handle', + rmw_client_handle, + rmw_send_request_events, + allow_multiple=False, + ) + sequence_number = self.get_field(test_rmw_send_request_event, 'sequence_number') + + # Get take request + test_rmw_take_request_event = self.get_event_with_field_value_and_assert( + 'rmw_service_handle', + rmw_service_handle, + rmw_take_request_events, + allow_multiple=False, + ) + self.assertFieldEquals(test_rmw_take_request_event, 'client_gid', client_gid) + self.assertFieldEquals(test_rmw_take_request_event, 'sequence_number', sequence_number) + self.assertFieldEquals(test_rmw_take_request_event, 'taken', 1) + + # Get request callback start + test_request_callback_start_event = self.get_event_with_field_value_and_assert( + 'callback', + callback_ref, + callback_start_events, + allow_multiple=False, + ) + + # Get send response + test_rmw_send_response_event = self.get_event_with_field_value_and_assert( + 'rmw_service_handle', + rmw_service_handle, + rmw_send_response_events, + allow_multiple=False, + ) + self.assertFieldEquals(test_rmw_send_response_event, 'client_gid', client_gid) + self.assertFieldEquals(test_rmw_send_response_event, 'sequence_number', sequence_number) + source_timestamp = self.get_field(test_rmw_send_response_event, 'timestamp') + + # Get request callback end + test_request_callback_end_event = self.get_event_with_field_value_and_assert( + 'callback', + callback_ref, + callback_end_events, + allow_multiple=False, + ) + + # Get take response + test_rmw_take_response_event = self.get_event_with_field_value_and_assert( + 'rmw_client_handle', + rmw_client_handle, + rmw_take_response_events, + allow_multiple=False, + ) + self.assertFieldEquals(test_rmw_take_response_event, 'sequence_number', sequence_number) + self.assertFieldEquals(test_rmw_take_response_event, 'source_timestamp', source_timestamp) + self.assertFieldEquals(test_rmw_take_response_event, 'taken', 1) + + # Assert request/response order + # We shouldn't necessarily expect the response to be taken after the request callback end + self.assertEventOrder([ + test_rmw_send_request_event, + test_rmw_take_request_event, + test_request_callback_start_event, + test_rmw_send_response_event, + test_request_callback_end_event, + ]) + self.assertEventOrder([ + test_rmw_send_response_event, + test_rmw_take_response_event, + ]) diff --git a/tracetools/include/tracetools/tp_call.h b/tracetools/include/tracetools/tp_call.h index 0b63de14..08da196b 100644 --- a/tracetools/include/tracetools/tp_call.h +++ b/tracetools/include/tracetools/tp_call.h @@ -282,6 +282,57 @@ TRACEPOINT_EVENT( ) ) +TRACEPOINT_EVENT( + TRACEPOINT_PROVIDER, + rmw_take_request, + TP_ARGS( + const void *, rmw_service_handle_arg, + const void *, request_arg, + const uint8_t *, client_gid_arg, + int64_t, sequence_number_arg, + const bool, taken_arg + ), + TP_FIELDS( + ctf_integer_hex(const void *, rmw_service_handle, rmw_service_handle_arg) + ctf_integer_hex(const void *, request, request_arg) + ctf_array(uint8_t, client_gid, client_gid_arg, TRACETOOLS_GID_STORAGE_SIZE) + ctf_integer(int64_t, sequence_number, sequence_number_arg) + ctf_integer(int, taken, (taken_arg ? 1 : 0)) + ) +) + +TRACEPOINT_EVENT( + TRACEPOINT_PROVIDER, + rmw_send_response, + TP_ARGS( + const void *, rmw_service_handle_arg, + const void *, response_arg, + const uint8_t *, client_gid_arg, + int64_t, sequence_number_arg, + int64_t, timestamp_arg + ), + TP_FIELDS( + ctf_integer_hex(const void *, rmw_service_handle, rmw_service_handle_arg) + ctf_integer_hex(const void *, response, response_arg) + ctf_array(uint8_t, client_gid, client_gid_arg, TRACETOOLS_GID_STORAGE_SIZE) + ctf_integer(int64_t, sequence_number, sequence_number_arg) + ctf_integer(int64_t, timestamp, timestamp_arg) + ) +) + +TRACEPOINT_EVENT( + TRACEPOINT_PROVIDER, + rmw_client_init, + TP_ARGS( + const void *, rmw_client_handle_arg, + const uint8_t *, gid_arg + ), + TP_FIELDS( + ctf_integer_hex(const void *, rmw_client_handle, rmw_client_handle_arg) + ctf_array(uint8_t, gid, gid_arg, TRACETOOLS_GID_STORAGE_SIZE) + ) +) + TRACEPOINT_EVENT( TRACEPOINT_PROVIDER, rcl_client_init, @@ -299,6 +350,40 @@ TRACEPOINT_EVENT( ) ) +TRACEPOINT_EVENT( + TRACEPOINT_PROVIDER, + rmw_send_request, + TP_ARGS( + const void *, rmw_client_handle_arg, + const void *, request_arg, + int64_t, sequence_number_arg + ), + TP_FIELDS( + ctf_integer_hex(const void *, rmw_client_handle, rmw_client_handle_arg) + ctf_integer_hex(const void *, request, request_arg) + ctf_integer(int64_t, sequence_number, sequence_number_arg) + ) +) + +TRACEPOINT_EVENT( + TRACEPOINT_PROVIDER, + rmw_take_response, + TP_ARGS( + const void *, rmw_client_handle_arg, + const void *, response_arg, + int64_t, sequence_number_arg, + int64_t, source_timestamp_arg, + const bool, taken_arg + ), + TP_FIELDS( + ctf_integer_hex(const void *, rmw_client_handle, rmw_client_handle_arg) + ctf_integer_hex(const void *, response, response_arg) + ctf_integer(int64_t, sequence_number, sequence_number_arg) + ctf_integer(int64_t, source_timestamp, source_timestamp_arg) + ctf_integer(int, taken, (taken_arg ? 1 : 0)) + ) +) + TRACEPOINT_EVENT( TRACEPOINT_PROVIDER, rcl_timer_init, diff --git a/tracetools/include/tracetools/tracetools.h b/tracetools/include/tracetools/tracetools.h index 66d06917..6622eb95 100644 --- a/tracetools/include/tracetools/tracetools.h +++ b/tracetools/include/tracetools/tracetools.h @@ -226,8 +226,7 @@ _DECLARE_TRACEPOINT( /// `rcl_publish` /** * Message publication. - * Links a `rcl_publisher_t` handle to a pointer to - * a message being published at the `rcl` level. + * Links a `rcl_publisher_t` handle to a pointer to a message being published at the `rcl` level. * * \param[in] publisher_handle pointer to the publisher's `rcl_publisher_t` handle * \param[in] message pointer to the message being published @@ -241,6 +240,7 @@ _DECLARE_TRACEPOINT( /** * Message publication. * Notes the pointer to the message being published at the `rmw` level. + * Also notes the source timestamp of the message. * * \param[in] rmw_publisher_handle pointer to the publisher's `rmw_publisher_t` handle * \param[in] message pointer to the message being published @@ -317,12 +317,12 @@ _DECLARE_TRACEPOINT( /// `rmw_take` /** * Message taking. - * Links a `rmw_subscription_t` handle to a pointer - * to a message being taken at the `rmw` level. + * Links a `rmw_subscription_t` handle to a pointer to a message being taken at the `rmw` level. + * Notes the source timestamp of the message. * * \param[in] rmw_subscription_handle pointer to the subscription's `rmw_subscription_t` handle * \param[in] message pointer to the message being taken - * \param[in] source_timestamp the source timestamp of the received message, + * \param[in] source_timestamp the source timestamp of the message, * or 0 (if no message or no info) * \param[in] taken whether a message was taken */ @@ -386,6 +386,64 @@ _DECLARE_TRACEPOINT( const void * service_handle, const void * callback) +/// `rmw_take_request` +/** + * Request taking. + * Links a `rmw_service_t` handle to a pointer to a request being taken at the `rmw` level. + * Also notes the sequence number of the request and the GID of the requesting client. + * + * \param[in] rmw_service_handle pointer to the service's `rmw_service_t` handle + * \param[in] request pointer to the request being taken + * \param[in] client_gid the GID of the requesting client + * \param[in] sequence_number the sequence number of the received request, + * or 0 (if no request or no info) + * \param[in] taken whether a request was taken + */ +_DECLARE_TRACEPOINT( + rmw_take_request, + const void * rmw_service_handle, + const void * request, + const uint8_t * client_gid, + int64_t sequence_number, + const bool taken) + +/// `rmw_send_response` +/** + * Response publication. + * Notes the pointer to the response being sent at the `rmw` level. + * Also notes the sequence number of the request that this response is for and the GID of the + * requesting client, and notes the source timestamp of the response. + * + * \param[in] rmw_service_handle pointer to the service's `rmw_service_t` handle + * \param[in] response pointer to the request being sent + * \param[in] client_gid the GID of the requesting client + * \param[in] sequence_number the sequence number of the request this response is for + * \param[in] timestamp the source timestamp of the response + */ +_DECLARE_TRACEPOINT( + rmw_send_response, + const void * rmw_service_handle, + const void * response, + const uint8_t * client_gid, + int64_t sequence_number, + int64_t timestamp) + +/// `rmw_client_init` +/** + * RMW client initialisation. + * Links a `rmw_client_t` handle to its DDS/rmw GID. + * This GID should be the same client GID that is collected by the `rmw_take_request` and + * `rmw_send_response` tracepoints for requests made by this client and responses to requests made + * by this client. + * + * \param[in] rmw_client_handle pointer to the client's `rmw_client_t` handle + * \param[in] gid pointer to the client's DDS/rmw GID + */ +_DECLARE_TRACEPOINT( + rmw_client_init, + const void * rmw_client_handle, + const uint8_t * gid) + /// `rcl_client_init` /** * Client initialisation. @@ -404,6 +462,46 @@ _DECLARE_TRACEPOINT( const void * rmw_client_handle, const char * service_name) +/// `rmw_send_request` +/** + * Request publication. + * Notes the pointer to the request being sent at the `rmw` level. + * Also notes the sequence number of the request. + * + * \param[in] rmw_client_handle pointer to the client's `rmw_client_t` handle + * \param[in] request pointer to the request being sent + * \param[in] sequence_number the sequence number of the request + */ +_DECLARE_TRACEPOINT( + rmw_send_request, + const void * rmw_client_handle, + const void * request, + int64_t sequence_number) + +/// `rmw_take_response` +/** + * Response taking. + * Links a `rmw_client_t` handle to a pointer to a response being taken at the `rmw` level. + * Notes the source timestamp of the response. Also notes the sequence number of the request this + * response is for. It does not note the request's client GID, since it is assumed that the matching + * of the response to the original client is performed before this tracepoint. + * + * \param[in] rmw_client_handle pointer to the client's `rmw_client_t` handle + * \param[in] response pointer to the response being taken + * \param[in] sequence_number the sequence number of the request this response is for, + * or 0 (if no response or no info) + * \param[in] source_timestamp the source timestamp of the response, + * or 0 (if no response or no info) + * \param[in] taken whether a response was taken + */ +_DECLARE_TRACEPOINT( + rmw_take_response, + const void * rmw_client_handle, + const void * response, + int64_t sequence_number, + int64_t source_timestamp, + const bool taken) + /// `rcl_timer_init` /** * Timer initialisation. diff --git a/tracetools/src/tracetools.c b/tracetools/src/tracetools.c index 8f35ad07..729234ea 100644 --- a/tracetools/src/tracetools.c +++ b/tracetools/src/tracetools.c @@ -264,6 +264,45 @@ DEFINE_TRACEPOINT( service_handle, callback)) +DEFINE_TRACEPOINT( + rmw_take_request, + TRACEPOINT_PARAMS( + const void * rmw_service_handle, + const void * request, + const uint8_t * client_gid, + int64_t sequence_number, + const bool taken), + TRACEPOINT_ARGS( + rmw_service_handle, + request, + client_gid, + sequence_number, + taken)) + +DEFINE_TRACEPOINT( + rmw_send_response, + TRACEPOINT_PARAMS( + const void * rmw_service_handle, + const void * response, + const uint8_t * client_gid, + int64_t sequence_number, + int64_t timestamp), + TRACEPOINT_ARGS( + rmw_service_handle, + response, + client_gid, + sequence_number, + timestamp)) + +DEFINE_TRACEPOINT( + rmw_client_init, + TRACEPOINT_PARAMS( + const void * rmw_client_handle, + const uint8_t * gid), + TRACEPOINT_ARGS( + rmw_client_handle, + gid)) + DEFINE_TRACEPOINT( rcl_client_init, TRACEPOINT_PARAMS( @@ -277,6 +316,32 @@ DEFINE_TRACEPOINT( rmw_client_handle, service_name)) +DEFINE_TRACEPOINT( + rmw_send_request, + TRACEPOINT_PARAMS( + const void * rmw_client_handle, + const void * request, + int64_t sequence_numer), + TRACEPOINT_ARGS( + rmw_client_handle, + request, + sequence_numer)) + +DEFINE_TRACEPOINT( + rmw_take_response, + TRACEPOINT_PARAMS( + const void * rmw_client_handle, + const void * response, + int64_t sequence_number, + int64_t source_timestamp, + const bool taken), + TRACEPOINT_ARGS( + rmw_client_handle, + response, + sequence_number, + source_timestamp, + taken)) + DEFINE_TRACEPOINT( rcl_timer_init, TRACEPOINT_PARAMS( diff --git a/tracetools_trace/tracetools_trace/tools/names.py b/tracetools_trace/tracetools_trace/tools/names.py index ab5d37af..a0458c5e 100644 --- a/tracetools_trace/tracetools_trace/tools/names.py +++ b/tracetools_trace/tracetools_trace/tools/names.py @@ -79,7 +79,12 @@ tracepoints.rclcpp_take, tracepoints.rcl_service_init, tracepoints.rclcpp_service_callback_added, + tracepoints.rmw_take_request, + tracepoints.rmw_send_response, + tracepoints.rmw_client_init, tracepoints.rcl_client_init, + tracepoints.rmw_send_request, + tracepoints.rmw_take_response, tracepoints.rcl_timer_init, tracepoints.rclcpp_timer_callback_added, tracepoints.rclcpp_timer_link_node, diff --git a/tracetools_trace/tracetools_trace/tools/tracepoints.py b/tracetools_trace/tracetools_trace/tools/tracepoints.py index 1e7b76a8..a5a26f35 100644 --- a/tracetools_trace/tracetools_trace/tools/tracepoints.py +++ b/tracetools_trace/tracetools_trace/tools/tracepoints.py @@ -31,7 +31,12 @@ rclcpp_take = 'ros2:rclcpp_take' rcl_service_init = 'ros2:rcl_service_init' rclcpp_service_callback_added = 'ros2:rclcpp_service_callback_added' +rmw_take_request = 'ros2:rmw_take_request' +rmw_send_response = 'ros2:rmw_send_response' +rmw_client_init = 'ros2:rmw_client_init' rcl_client_init = 'ros2:rcl_client_init' +rmw_send_request = 'ros2:rmw_send_request' +rmw_take_response = 'ros2:rmw_take_response' rcl_timer_init = 'ros2:rcl_timer_init' rclcpp_timer_callback_added = 'ros2:rclcpp_timer_callback_added' rclcpp_timer_link_node = 'ros2:rclcpp_timer_link_node'