From f8cd42a01b03274cbd362f9ae6e79ab952316e8d Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Wed, 9 Mar 2022 08:59:42 -0500 Subject: [PATCH 1/3] Only check wait_set->impl for NULL pointer. The previous line already checked wait_set for NULL pointer, so there is no reason to call rcl_wait_set_is_valid and recheck that pointer. Signed-off-by: Chris Lalancette --- rcl/src/rcl/wait.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rcl/src/rcl/wait.c b/rcl/src/rcl/wait.c index 8d97c141d..156a94872 100644 --- a/rcl/src/rcl/wait.c +++ b/rcl/src/rcl/wait.c @@ -217,7 +217,7 @@ rcl_wait_set_get_allocator(const rcl_wait_set_t * wait_set, rcl_allocator_t * al #define SET_ADD(Type) \ RCL_CHECK_ARGUMENT_FOR_NULL(wait_set, RCL_RET_INVALID_ARGUMENT); \ - if (!rcl_wait_set_is_valid(wait_set)) { \ + if (!wait_set->impl) { \ RCL_SET_ERROR_MSG("wait set is invalid"); \ return RCL_RET_WAIT_SET_INVALID; \ } \ From bba931fca5b92d243877b4d7a821f78ce7b0ad0a Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Wed, 9 Mar 2022 09:00:52 -0500 Subject: [PATCH 2/3] Refactor the debug messages in rcl_wait(). This should slightly improve their performance by only calling them when necessary, and combining the output of the various outputs to effectively "batch" them together. Signed-off-by: Chris Lalancette --- rcl/src/rcl/wait.c | 22 +++++++++++++--------- 1 file changed, 13 insertions(+), 9 deletions(-) diff --git a/rcl/src/rcl/wait.c b/rcl/src/rcl/wait.c index 156a94872..01fbc2d6f 100644 --- a/rcl/src/rcl/wait.c +++ b/rcl/src/rcl/wait.c @@ -586,6 +586,10 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) temporary_timeout_storage.sec = 0; temporary_timeout_storage.nsec = 0; timeout_argument = &temporary_timeout_storage; + RCUTILS_LOG_DEBUG_NAMED( + ROS_PACKAGE_NAME, + "Waiting with timeout: %" PRIu64 "s + %" PRIu64 "ns, based on next scheduled timer: %d", + temporary_timeout_storage.sec, temporary_timeout_storage.nsec, is_timer_timeout); } else if (timeout > 0 || is_timer_timeout) { // If min_timeout was negative, we need to wake up immediately. if (min_timeout < 0) { @@ -594,16 +598,16 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) temporary_timeout_storage.sec = RCL_NS_TO_S(min_timeout); temporary_timeout_storage.nsec = min_timeout % 1000000000; timeout_argument = &temporary_timeout_storage; + RCUTILS_LOG_DEBUG_NAMED( + ROS_PACKAGE_NAME, + "Waiting with timeout: %" PRIu64 "s + %" PRIu64 "ns, based on next scheduled timer: %d", + temporary_timeout_storage.sec, temporary_timeout_storage.nsec, is_timer_timeout); + } else { + RCUTILS_LOG_DEBUG_NAMED( + ROS_PACKAGE_NAME, + "Waiting without timeout, based on next scheduled timer: %d", + is_timer_timeout); } - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED( - !timeout_argument, ROS_PACKAGE_NAME, "Waiting without timeout"); - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED( - timeout_argument, ROS_PACKAGE_NAME, - "Waiting with timeout: %" PRIu64 "s + %" PRIu64 "ns", - temporary_timeout_storage.sec, temporary_timeout_storage.nsec); - RCUTILS_LOG_DEBUG_NAMED( - ROS_PACKAGE_NAME, "Timeout calculated based on next scheduled timer: %s", - is_timer_timeout ? "true" : "false"); // Wait. rmw_ret_t ret = rmw_wait( From 953de4402d9c3eb9adf4d0a25296e22356a16acf Mon Sep 17 00:00:00 2001 From: Chris Lalancette Date: Wed, 9 Mar 2022 09:02:29 -0500 Subject: [PATCH 3/3] Remove some debug statements from rcl_wait. While profiling an application, I found that a lot of time was spent just checking whether a log message should be output or not based on the current debug level. None of the individual calls are expensive, but since rcl_wait is called so often, it ends up showing up in the profile. This patch somewhat controversially removes the debug statements from rcl_wait(). My view on it is that the utility of these is fairly low (if you ever turned them on, you would be flooded with information), and the cost is relatively high. If you are really debugging this stuff, you can add in your own, more targeted debug statements or use a debugger. Signed-off-by: Chris Lalancette --- rcl/src/rcl/wait.c | 21 --------------------- 1 file changed, 21 deletions(-) diff --git a/rcl/src/rcl/wait.c b/rcl/src/rcl/wait.c index 01fbc2d6f..7bcdedb47 100644 --- a/rcl/src/rcl/wait.c +++ b/rcl/src/rcl/wait.c @@ -586,10 +586,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) temporary_timeout_storage.sec = 0; temporary_timeout_storage.nsec = 0; timeout_argument = &temporary_timeout_storage; - RCUTILS_LOG_DEBUG_NAMED( - ROS_PACKAGE_NAME, - "Waiting with timeout: %" PRIu64 "s + %" PRIu64 "ns, based on next scheduled timer: %d", - temporary_timeout_storage.sec, temporary_timeout_storage.nsec, is_timer_timeout); } else if (timeout > 0 || is_timer_timeout) { // If min_timeout was negative, we need to wake up immediately. if (min_timeout < 0) { @@ -598,15 +594,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) temporary_timeout_storage.sec = RCL_NS_TO_S(min_timeout); temporary_timeout_storage.nsec = min_timeout % 1000000000; timeout_argument = &temporary_timeout_storage; - RCUTILS_LOG_DEBUG_NAMED( - ROS_PACKAGE_NAME, - "Waiting with timeout: %" PRIu64 "s + %" PRIu64 "ns, based on next scheduled timer: %d", - temporary_timeout_storage.sec, temporary_timeout_storage.nsec, is_timer_timeout); - } else { - RCUTILS_LOG_DEBUG_NAMED( - ROS_PACKAGE_NAME, - "Waiting without timeout, based on next scheduled timer: %d", - is_timer_timeout); } // Wait. @@ -634,7 +621,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) if (ret != RCL_RET_OK) { return ret; // The rcl error state should already be set. } - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED(is_ready, ROS_PACKAGE_NAME, "Timer in wait set is ready"); if (!is_ready) { wait_set->timers[i] = NULL; } @@ -647,8 +633,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) // Set corresponding rcl subscription handles NULL. for (i = 0; i < wait_set->size_of_subscriptions; ++i) { bool is_ready = wait_set->impl->rmw_subscriptions.subscribers[i] != NULL; - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED( - is_ready, ROS_PACKAGE_NAME, "Subscription in wait set is ready"); if (!is_ready) { wait_set->subscriptions[i] = NULL; } @@ -656,8 +640,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) // Set corresponding rcl guard_condition handles NULL. for (i = 0; i < wait_set->size_of_guard_conditions; ++i) { bool is_ready = wait_set->impl->rmw_guard_conditions.guard_conditions[i] != NULL; - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED( - is_ready, ROS_PACKAGE_NAME, "Guard condition in wait set is ready"); if (!is_ready) { wait_set->guard_conditions[i] = NULL; } @@ -665,7 +647,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) // Set corresponding rcl client handles NULL. for (i = 0; i < wait_set->size_of_clients; ++i) { bool is_ready = wait_set->impl->rmw_clients.clients[i] != NULL; - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED(is_ready, ROS_PACKAGE_NAME, "Client in wait set is ready"); if (!is_ready) { wait_set->clients[i] = NULL; } @@ -673,7 +654,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) // Set corresponding rcl service handles NULL. for (i = 0; i < wait_set->size_of_services; ++i) { bool is_ready = wait_set->impl->rmw_services.services[i] != NULL; - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED(is_ready, ROS_PACKAGE_NAME, "Service in wait set is ready"); if (!is_ready) { wait_set->services[i] = NULL; } @@ -681,7 +661,6 @@ rcl_wait(rcl_wait_set_t * wait_set, int64_t timeout) // Set corresponding rcl event handles NULL. for (i = 0; i < wait_set->size_of_events; ++i) { bool is_ready = wait_set->impl->rmw_events.events[i] != NULL; - RCUTILS_LOG_DEBUG_EXPRESSION_NAMED(is_ready, ROS_PACKAGE_NAME, "Event in wait set is ready"); if (!is_ready) { wait_set->events[i] = NULL; }