Improve the performance of rcutils_logging_format_message.#372
Improve the performance of rcutils_logging_format_message.#372clalancette merged 1 commit intorollingfrom
Conversation
In particular, the g_rcutils_logging_output_format_string can't really change after initialization time, so we don't need to reparse it every time. Instead, parse it once at the beginning and just maintain an array of callbacks to call to fill in the information as each log message comes in. In my testing, this reduces the cost of calling rcutils_logging_format_message by about 50% in all cases, from very short format strings to very long ones. Format strings with many, many token substitutions are still very inefficient. That's because once we go beyond the fixed 2048 buffer limit and start allocating memory, we only allocate small chunks of memory at a time. However, this won't come up in most normal situations (including the default format message), so we ignore this performance problem for now. Signed-off-by: Chris Lalancette <clalancette@openrobotics.org>
ivanpauno
left a comment
There was a problem hiding this comment.
The changes makes sense conceptually.
It's a bit hard to follow the code, so I will take another look later to provide more feedback.
Are there any tests currently testing log formatting is correct?
👍
Yeah, agreed, the diff is especially hard to read. I think it is easier to follow if you look at the complete implementation, but do let me know if there is something I can do to make it easier to read.
Yeah, there are existing tests in https://github.com/ros2/rcutils/blob/rolling/test/test_logging.cpp , https://github.com/ros2/rcutils/blob/rolling/test/test_logging_macros.cpp , https://github.com/ros2/rcutils/blob/rolling/test/test_logging_long_messages.py , and https://github.com/ros2/rcutils/blob/rolling/test/test_logging_output_format.py . They seemed comprehensive enough, so I didn't add any new ones. |
|
CI:
|
Where's that buffer limit set and where are those small allocations happening? |
Ah, I see that happens inside |
Ah simple way to improve that is to modify rcutils_char_array_expand_as_needed to use a reallocation factor of |
Yeah, I considered that. I have a couple more minor optimizations that I'll look at doing separately, I'll probably include that as part of it. |
|
CI is green, and approved, so going ahead and merging this. Thanks for the review! |
In particular, the g_rcutils_logging_output_format_string
can't really change after initialization time, so we don't
need to reparse it every time. Instead, parse it once at
the beginning and just maintain an array of callbacks to
call to fill in the information as each log message comes in.
In my testing, this reduces the cost of calling
rcutils_logging_format_message by about 50% in all cases, from
very short format strings to very long ones.
Format strings with many, many token substitutions are still
very inefficient. That's because once we go beyond the
fixed 2048 buffer limit and start allocating memory, we only
allocate small chunks of memory at a time. However, this
won't come up in most normal situations (including the default
format message), so we ignore this performance problem for now.
Signed-off-by: Chris Lalancette clalancette@openrobotics.org