Skip to content

Commit 1ed4d7f

Browse files
authored
Optimize rcutils_logging_get_logger_effective_level() (ros2#381)
* Add in tests for changing ancestor severity level. * Optimize rcutils_logging_get_logger_effective_level(). This function is the most expensive part of rcutils_logging_logger_is_enabled_for(), which is called on every RCUTILS_LOG_* invocation. We notice a couple of things: 1. The current name -> logger level lookup is using a "string map" structure. A "string map" isn't a map at all, but is really a linear array of strings. Thus searching it can be slow when there are a lot of strings in the map. Since this is a global map, this can happen when many ROS 2 nodes are loaded in to the same process. 2. When looking up the severity of a particular name, we need to check the full name, plus any ancestors (separated by '.') to find the severity level. This requires a bunch of work, including copying a string, running strlen on it, searching through it for periods, etc. This can be expensive, and in the common case it isn't needed; the fully-qualified string is usually in the map already. To fix both of these, we switch to a hash map, and look up the current logger level via the hash map. If the full logger name isn't in the hash map, we fall back to the slow path where we do the additional work of finding the severity via the hierarchy. Note that even in this slow path, once we've computed the severity level we place that in the map as well so that subsequent lookups will take the fast path. The benchmarks I ran on this change give very good improvements for most cases. For cases where there are multiple set logger names, and those logger names have ancestors, this change is ~9x faster than the current implementation. For cases where there are multiple set logger names and those logger names have no ancestors (one of the most common cases in ROS 2), this change is ~3x faster than the current implementation. For cases where we have a single logger name (another common case), this change is ~2x faster than the current implementation. Finally, note that rcutils_logging_set_logger_level() is more expensive than before, due to having to traverse the hash map to find other logger names in the hierarchy. Since we don't expect users to change logger levels often, this tradeoff seems worth it to speed up lookups (which are called for every log message). Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
1 parent c49b41c commit 1ed4d7f

3 files changed

Lines changed: 437 additions & 86 deletions

File tree

include/rcutils/logging.h

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -164,6 +164,10 @@ typedef struct rcutils_log_location_s
164164
} rcutils_log_location_t;
165165

166166
/// The severity levels of log messages / loggers.
167+
/**
168+
* Note: all logging levels have their Least Significant Bit as 0, which is used as an
169+
* optimization. If adding new logging levels, ensure that the new levels keep this property.
170+
*/
167171
enum RCUTILS_LOG_SEVERITY
168172
{
169173
RCUTILS_LOG_SEVERITY_UNSET = 0, ///< The unset log level

0 commit comments

Comments
 (0)