Improve the performance of rcutils_logging_format_message.

[clalancette]

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]

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?

[clalancette]

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.

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.

Are there any tests currently testing log formatting is correct?

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.

[clalancette]

CI:

• Linux
• Linux-aarch64
• Windows

[ivanpauno]

LGTM!

[ivanpauno]

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.

Where's that buffer limit set and where are those small allocations happening?

[ivanpauno]

Where's that buffer limit set and where are those small allocations happening?

Ah, I see that happens inside rcutils_char_array_t now ...

[ivanpauno]

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.

Ah simple way to improve that is to modify rcutils_char_array_expand_as_needed to use a reallocation factor of 1.5.
So the new size is max(1.5*old_size, required_size).
That straregy is widely used AFAIK.

[clalancette]

Ah simple way to improve that is to modify rcutils_char_array_expand_as_needed to use a reallocation factor of 1.5. So the new size is max(1.5*old_size, required_size). That straregy is widely used AFAIK.

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.

[clalancette]

CI is green, and approved, so going ahead and merging this. Thanks for the review!