Speed up rclpy loggers

[mhidalgo-bdai]

This patch introduces an alternative implementation of the rclpy.logging.RcutilsLogger that will cache log call configurations. This has been observed to reduce the average logging time significantly.

As to why this is the case, other than the obvious advantage of executing code on first call rather than on every call, I suspect stack frame inspection in Python may be taking some amount of time (as it fetches code from source files by default when populating frame info and traceback objects, see here).

[robodreamer]

Thanks for proposing a quick alternative solution! Would you mind elaborating on what the issues in the original code were and how the new change addresses them?

[mhidalgo-bdai]

Thanks for proposing a quick alternative solution! Would you mind elaborating on what the issues in the original code were and how the new change addresses them?

I updated the PR description. I think it's a combination of factors that can be summarized as "too much work on every log call". This patch addresses this issue by "doing less work and only on first log call".

[amessing-bdai]

What is the difference between None and False?

[mhidalgo-bdai]

In this context, none. I annotate optional arguments as optional purely out of habit (and for the sake of readability).

[amessing-bdai]

Ok, not going to block on this.

I think whether bool = False or Optional[bool] = None is more readable is another discussion lol. I do think there is a difference between Optional and has a default value.

[robodreamer]

Thanks for putting a quick workaround! I wonder if we would like to contribute this change back to ROS2 as well?

[robodreamer]

I am looking forward to seeing this change live from the bdai container soon! I had to suppress a lot of log messages currently to get around the performance issue.

[robodreamer]

This this class name a standard one? The name (memoizing) sounds a bit new to me.

[mhidalgo-bdai]

Hmm, not standard, no. Memoizing is me adjectivizing memoization.

[mhidalgo-bdai]

I wonder if we would like to contribute this change back to ROS2 as well?

I'm onboard.

I am looking forward to seeing this change live from the bdai container soon! I had to suppress a lot of log messages currently to get around the performance issue.

Note you will have to wrap your logger, like logger = as_memoizing_logger(node.get_logger()). We could inject it for our bdai_ros2_wrappers.node.Node subclass, but I suspect that may create some confusion when people start mixing up our nodes with regular nodes (and ask why the logger in their regular node has awful performance).