Skip to content

Commit

Permalink
Optimize rcutils_logging_get_logger_effective_level() (#381)
Browse files Browse the repository at this point in the history
* 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>
  • Loading branch information
clalancette authored Sep 7, 2022
1 parent c49b41c commit 1ed4d7f
Show file tree
Hide file tree
Showing 3 changed files with 437 additions and 86 deletions.
4 changes: 4 additions & 0 deletions include/rcutils/logging.h
Original file line number Diff line number Diff line change
Expand Up @@ -164,6 +164,10 @@ typedef struct rcutils_log_location_s
} rcutils_log_location_t;

/// The severity levels of log messages / loggers.
/**
* Note: all logging levels have their Least Significant Bit as 0, which is used as an
* optimization. If adding new logging levels, ensure that the new levels keep this property.
*/
enum RCUTILS_LOG_SEVERITY
{
RCUTILS_LOG_SEVERITY_UNSET = 0, ///< The unset log level
Expand Down
Loading

0 comments on commit 1ed4d7f

Please sign in to comment.