Skip to content

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

@jpace121

Description

@jpace121

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions