High logging overhead

[almaslov]

Hello!
I was profiling some nodes in my project recently and noticed an issue in case of high incoming messages rate(~2-3K hz). In this case rcl_wait consumes significant amount of CPU. About 30-50% of rcl_wait execution time is rcutils_logging_logger_is_enabled_for:

It looks like most of overhead can be eliminated by removing rcutils_logging_severity_level_from_string and switching to integral log_level as mentioned in comment here and here

[almaslov]

I would be glad to make a PR, but I'm a little confused with idea of implementing string-to-int map type which is almost complete copy-paste of string-to-string map. Could you suggest, which solution did you have in mind?

[fujitatomoya]

@almaslov thanks for the issue. I think this is all about rcutils_logging_get_logger_effective_level is not well optimized, which includes searching the effective FQN for logger, and copying and checking severity string every single time.

rcutils/resource/logging_macros.h.em

Lines 66 to 75 in 8da2aac

	#define RCUTILS_LOG_COND_NAMED(severity, condition_before, condition_after, name, ...) \
	do { \
	RCUTILS_LOGGING_AUTOINIT; \
	static rcutils_log_location_t __rcutils_logging_location = {__func__, __FILE__, __LINE__}; \
	if (rcutils_logging_logger_is_enabled_for(name, severity)) { \
	condition_before \
	rcutils_log(&__rcutils_logging_location, severity, name, __VA_ARGS__); \
	condition_after \
	} \
	} while (0)

I do not have solid idea for this problem. but i would suggest that we should avoid these checks every time. Probably after the initialization, there should be some mechanism to notify the update to the logger, so that we can avoid these all checks.

any thoughts?

[almaslov]

but i would suggest that we should avoid these checks every time

Sounds interesting. The only thing that comes to mind is saving timestamp when global logging state is updated. Logging macro could look something like this:

#define RCUTILS_LOG_COND_NAMED(severity, condition_before, condition_after, name, ...) \ 
   do { \ 
     RCUTILS_LOGGING_AUTOINIT; \ 
     static rcutils_log_location_t __rcutils_logging_location = {__func__, __FILE__, __LINE__}; \ 
     
     /* New code here */
     static timestamp __last_check_timestamp = 0;
     static bool __cached_check_result = false;
     if (__last_check_timestamp < last_global_logging_update) {
       __last_check_timestamp = get_current_time();
       __cached_check_result = rcutils_logging_logger_is_enabled_for(name, severity)
     }

     if (__cached_check_result) { \ 
       condition_before \ 
       rcutils_log(&__rcutils_logging_location, severity, name, __VA_ARGS__); \ 
       condition_after \ 
     } \ 
   } while (0) 

So rcutils_logging_logger_is_enabled_for result can be cached and recalculated only once global state was updated.
The cons is that solution involves modification of macros so it's kinda dangerous since impacts literally all cpp packages. On the other hand the solution I've suggested in issue description doesn't change API, but obviously less effective.

[clalancette]

I took a quick look at this as well. I think there are several problems in here:

1. rcutils_logging_severity_level_from_string is doing a string copy and toupper on the string every time it is invoked (

   rcutils/src/logging.c

   Lines 320 to 355 in 8da2aac

   	rcutils_ret_t
   	rcutils_logging_severity_level_from_string(
   	const char * severity_string, rcutils_allocator_t allocator, int * severity)
   	{
   	RCUTILS_CHECK_ALLOCATOR_WITH_MSG(
   	&allocator, "invalid allocator", return RCUTILS_RET_INVALID_ARGUMENT);
   	RCUTILS_CHECK_ARGUMENT_FOR_NULL(severity_string, RCUTILS_RET_INVALID_ARGUMENT);
   	RCUTILS_CHECK_ARGUMENT_FOR_NULL(severity, RCUTILS_RET_INVALID_ARGUMENT);
   	rcutils_ret_t ret = RCUTILS_RET_LOGGING_SEVERITY_STRING_INVALID;
   	// Convert the input string to upper case (for case insensitivity).
   	char * severity_string_upper = rcutils_strdup(severity_string, allocator);
   	if (NULL == severity_string_upper) {
   	RCUTILS_SET_ERROR_MSG("failed to allocate memory for uppercase string");
   	return RCUTILS_RET_BAD_ALLOC;
   	}
   	for (int i = 0; severity_string_upper[i]; ++i) {
   	severity_string_upper[i] = (char)toupper(severity_string_upper[i]);
   	}
   	// Determine the severity value matching the severity name.
   	for (size_t i = 0;
   	i < sizeof(g_rcutils_log_severity_names) / sizeof(g_rcutils_log_severity_names[0]);
   	++i)
   	{
   	const char * severity_string_i = g_rcutils_log_severity_names[i];
   	if (severity_string_i && strcmp(severity_string_i, severity_string_upper) == 0) {
   	*severity = (enum RCUTILS_LOG_SEVERITY)i;
   	ret = RCUTILS_RET_OK;
   	break;
   	}
   	}
   	allocator.deallocate(severity_string_upper, allocator.state);
   	return ret;
   	}

   ). While I guess that is nice, I would argue that we can just make this case-sensitive and save a lot of work here. Since this is changing a semantic, we'd want to some research on how widely used it is, but I think that should be straightforward.
2. As @fujitatomoya pointed out, we are doing a lot of work in rcutils_logging_get_logger_effective_level to try to suss out the parts of the logger that we want. We may be able to optimize this by memoizing that result, though we would still incur overhead in checking on the memoization. We could also reconsider whether we really need that functionality. That is more controversial, since I can definitely see uses for the current system, but logging really should be as simple as possible.

I'm not sure I understand your latest proposal. If we had some kind of global logging update timestamp, wouldn't we just be throttling messages? While that certainly would help, we already have the THROTTLE versions of the messages.

[almaslov]

@clalancette Thanks for reply.
I agree, that rcutils_logging_severity_level_from_string has large overhead by copying string and it could be fixed with case-insensitive comparison. But my initial thought was that logging macros shouldn't use (in nested invocations) rcutils_logging_severity_level_from_string at all.

logging.h API uses integer log_level in all functions(except rcutils_logging_severity_level_from_string). As far as I can see, integer log_level is converted to string value only for storage purpose. And this is a detail of implementation, not public API. So storing integer value instead of string value could save CPU from unnecessary conversions.

I'm not sure I understand your latest proposal. If we had some kind of global logging update timestamp, wouldn't we just be throttling messages? While that certainly would help, we already have the THROTTLE versions of the messages.

This global logging update timestamp, say last_global_logging_update, should be updated on logging configuration change, e.g. when rcutils_logging_set_default_logger_level or rcutils_logging_set_logger_level called. If logging configuration changes, rcutils_logging_logger_is_enabled_for can be recalculated only one time, until next configuration update. The idea is last_global_logging_update affects only rcutils_logging_logger_is_enabled_for calls, not logging handler calls. So, as you can see in my code snippet I added condition that checks if last_global_logging_update changed since last macro call.

Actually now I see that there is no way to handle global log level change trough g_rcutils_logging_default_logger_level global variable which is exposed in logging.h. So I'm not sure this proposal can be implemented correctly.