ROS2 logging using FMT

Hi,

yesterday I quickly hacked a super tiny (single header file, less than 100 lines of code) project to use the all mighty fmt library with RCLCPP logging.

As an example, user will write:

// create this object once
ros2_logging_fmt::Logger logger(node->get_logger()); 

logger.info("Hello {} number {}", world_string, 42);

Instead of:

RCLCPP_INFO(node->get_logger(), "Hello %s number %d", world_string.c_str(), 42);

The resulting code is:

  • more efficient, in terms of execution time, when the logging is enabled.
  • less verbose, nicer to use.
  • type safe (definitively more than printf-like formatting)
  • thread safe.
  • 99.9% of the times it wonā€™t allocate any memory.

Honorable mention to rosfmt, even if thanks to variadic templates, there is no reason to use macros, in my opinion.

I am sharing this in the hope that other people find this useful and to start a conversation with mainstream developers of ROS2.

I see no reason why this single file (improved and corrected) canā€™t be included as an optional logging API in the rclcpp library.

15 Likes

Thisā€¦ is awesome!

I was literally looking for an rosfmt replacement day before yesterday. Good thing I didnā€™t get around to it yet.
Integrating this as (optional) logger for ROS2 would be amazing!

Not only so developers can use this superior format, but also that other developers are not held back by the ā€˜ow no, an extra dependency/header-fileā€™.

You can literally copy and paste this file in your project :smile:

Well, it would also introduce a dependency on fmt right? That would be my hesitation, but given its value it might be worth doing.

Maybe weā€™re using different meanings for these terms, so what does ā€œnegative overheadā€ mean in this case? Maybe ā€œnegligible overheadā€?

Also, perhaps a technical question, but how does fmt achieve zero-overhead when not using macros. The reason we use macros in our API is so that they can be completely compiled out by defining an empty macro when configured to build that way.

Finally, does anyone have insight on how complete a replacement for fmt the new C++20 std::format is? We cannot use it yet, but it will hopefully be in reach of the core library soon.

I would love to see changes to rclcpp which let you use fmt with it, but without depending on fmt, and then later use it with std::format when that is available. Maybe thatā€™s not a reasonable path forward for technical reasons, but just thinking out loud.

That all being said, putting a feature like this into a separate package and letting it get use/polish before trying to include it in a core package like rclcpp, is definitely the right way to go, so thanks for doing that, it looks cool. :slight_smile:

1 Like

@wjwwood, no, you understood correctly:

ā€œnegative overheadā€ means exactly what you think it means: using this wrapper will use LESS CPU than not using it. See here: GitHub - fmtlib/fmt: A modern formatting library

perhaps a technical question, but how does fmt achieve zero-overhead when not using macros.

I donā€™t know if you looked at the code, but I do use the RCLCPP macros (see here). When the log level is disabled, the fmt function is not called.

Finally, does anyone have insight on how complete a replacement for fmt the new C++20 std::format is?

I personally think both will do. But adding the latest, cutting edge, fmt library version, seems to me like the most appealing option. We donā€™t need to agree :smile:

I would love to see changes to rclcpp which let you use fmt with it, but without depending on fmt,

Correct me if I am wrong, but rclcpp depends already on spdlog_vendor that has its own version of fmt.

Summarizing, I agree with you: let people play with this simple wrapper and, later, discuss if it makes sense to include it in rclcpp.

I think the overhead here is related to the arguments of the logging call. With a logging library, you want to completely skip argument evaluation if a log level is disabled. Can templates achieve that?

1 Like

That ^

Consider:

RCLCPP_DEBUG(node->get_logger(), "%s", very_expensive_func_to_summarize_a_point_cloud(point_cloud));

// vs

Logger logger(node->get_logger());
logger.debug("{}", very_expensive_func_to_summarize_a_point_cloud(point_cloud));

In the first case if you decide to compile out debug log statements then neither the get_logger() function (could incur a string copy) nor the summarize function are called. In the second case, though the fmt function is not called, the other two functions are called.

Yes, but itā€™s behind the rcl_logging abstraction, so you could configure your system to instead use the rcl_logging_noop that does nothing and then you donā€™t need spdlog. If we expose this to the user API, then you have a hard dependency on either fmt or something like std::format. Iā€™m not saying thatā€™s a bad thing, just that itā€™s different then the logging backend which is swappable.

2 Likes

I must concede that you are technically right!

But I think I have never seen functions called inside a logging macro like that.
Additionally, I think that it is more common for me to change the log level at runtime, rather than compilation time.

Said that, I need to document this drawback to make users aware of this difference. Thanks :slight_smile:

UPDATE: I corrected my claims about ā€œzero overheadā€. I might eventually use macros too.

3 Likes

Maybe you could verify if templates donā€™t have a way to achieve the same zero-cost when a debug level is disabled. Since they work in compile time, they could at least theoretically have the ability (itā€™d be interesting to see the assembler when compiled with and without optimizations).

The only reason I am aware of this need is because it has caused performance problems in rvizā€™s point cloud rendering before:

It boiled down to an expensive debug statement inside the pointcloud rendering inner loop that was removed when compiling with -DNDEBUG, which controlled whether or not debug logging statements were included.

Not exactly the same, but an example nonetheless of how the ability to not only remove the logging message but the work done to produce it was important as a compile time constraint.

3 Likes