Logging is kind of slow, even at levels below the level selected for the node.

I have a minimal reproducible example here.

In that example, I start a timer that only runs once that does a calculation in a for loop, logging as it goes. I measure the time it takes to do the calculation and also log that at the end. I run the process with the logger level for the node set to WARN, so the INFO statements aren't printed to the terminal or published.

I would expect that I would see a minimal slow down compared to not logging at all (ignoring missing optimizations), when in reality I see quite a large impact.

On my laptop, for the scenario described above I'm seeing the process take 0.0149388s to complete, where the equivalent code in ROS1 completed the process in 0.000248744s.

FWIW, its not just that logging is slower in ros2 than ros1. When I set the log levels so I can see the statements, ros1 finishes in 1.04641s compared to ros2 at 0.895799s. If I subscribe to rosout, the time for ros2 doubles to 1.62014s, though.

This seems unfortunate? I discovered this when porting some code from ros1 to ros2 that had log statements in some critical sections of the code, and wound up fixing the issue by using spdlog directly for those sections.

The fact that subscribing to /rosout has such a big effect is even more unfortunate, in my opinion. It is an additional place that people coming from ros1 don't expect counts as making a network call that really is when doing subsystem testing and verification.

Is there a way this can be improved? The ros1 behavior seems much better

Start with the linked ROS 2 reproducer at src/roslog.cpp and compare its WARN-level and /rosout-subscriber timings with the linked ROS 1 example. Done would require an agreed change that reduces the disabled-logging overhead and the additional /rosout cost, with the reported timing difference measured again.