# ROS2 logging using FMT

**URL:** <https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978>\
**Category:** ROS General\
**Created:** [June 9, 2022, 10:28am UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978 "2022-06-09T10:28:55Z")\
**Posts on this page:** 10\
**Page:** 1

<div class="post-metadata">

**Author:** ![facontidavide](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/facontidavide/32/1674_2.png) [@facontidavide](https://discourse.openrobotics.org/u/facontidavide)\
**Post date:** [June 9, 2022, 10:28am UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/1 "2022-06-09T10:28:55Z")

</div>

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](https://github.com/fmtlib/fmt) with RCLCPP logging.

[https://github.com/facontidavide/ros2\_logging\_fmt](https://github.com/facontidavide/ros2_logging_fmt)

As an example, user will write:

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

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

```

Instead of:

```c++
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](https://github.com/xqms/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.

---

<div class="post-metadata">

**Author:** ![Timple](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/timple/32/4891_2.png) [@Timple](https://discourse.openrobotics.org/u/Timple)\
**Post date:** [June 9, 2022, 4:41pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/2 "2022-06-09T16:41:21Z")

</div>

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’.

---

<div class="post-metadata">

**Author:** ![facontidavide](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/facontidavide/32/1674_2.png) [@facontidavide](https://discourse.openrobotics.org/u/facontidavide)\
**Post date:** [June 9, 2022, 5:22pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/3 "2022-06-09T17:22:59Z")

</div>

You can literally copy and paste this file in your project 😄

---

<div class="post-metadata">

**Author:** ![wjwwood](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/wjwwood/32/13715_2.png) [@wjwwood](https://discourse.openrobotics.org/u/wjwwood)\
**Post date:** [June 9, 2022, 8:33pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/4 "2022-06-09T20:33:45Z")

</div>

> [@facontidavide](#):
>
> 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.

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

> [@facontidavide](#):
>
> zero-overhead if the logging level is disabled, negative overhead, otherwise.

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. 🙂

---

<div class="post-metadata">

**Author:** ![facontidavide](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/facontidavide/32/1674_2.png) [@facontidavide](https://discourse.openrobotics.org/u/facontidavide)\
**Post date:** [June 9, 2022, 9:28pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/5 "2022-06-09T21:28:01Z")

</div>

@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](https://github.com/fmtlib/fmt#speed-tests)

> 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](https://github.com/facontidavide/ros2_logging_fmt/blob/master/include/ros2_logging_fmt/ros2_logging_fmt.hpp#L21)). 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 😄

> 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**.

---

<div class="post-metadata">

**Author:** ![peci1](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/peci1/32/10145_2.png) [@peci1](https://discourse.openrobotics.org/u/peci1)\
**Post date:** [June 9, 2022, 10:10pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/6 "2022-06-09T22:10:55Z")

</div>

> [@facontidavide](#):
>
> I don’t know if you looked at the code, but I do use the RCLCPP macros (see [here](https://github.com/facontidavide/ros2_logging_fmt/blob/master/include/ros2_logging_fmt/ros2_logging_fmt.hpp#L21)). When the log level is disabled, the **fmt** function is not called.

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?

---

<div class="post-metadata">

**Author:** ![wjwwood](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/wjwwood/32/13715_2.png) [@wjwwood](https://discourse.openrobotics.org/u/wjwwood)\
**Post date:** [June 9, 2022, 10:26pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/7 "2022-06-09T22:26:17Z")

</div>

> [@peci1](#):
>
> 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.

That ^

Consider:

```auto
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.

> [@facontidavide](#):
>
> Correct me if I am wrong, but **rclcpp** depends already on **spdlog\_vendor** that has its own version of **fmt**.

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.

---

<div class="post-metadata">

**Author:** ![facontidavide](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/facontidavide/32/1674_2.png) [@facontidavide](https://discourse.openrobotics.org/u/facontidavide)\
**Post date:** [June 9, 2022, 10:38pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/8 "2022-06-09T22:38:57Z")

</div>

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 🙂

UPDATE: I corrected my claims about “zero overhead”. I might eventually use macros too.

---

<div class="post-metadata">

**Author:** ![peci1](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/peci1/32/10145_2.png) [@peci1](https://discourse.openrobotics.org/u/peci1)\
**Post date:** [June 9, 2022, 11:14pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/9 "2022-06-09T23:14:33Z")

</div>

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).

---

<div class="post-metadata">

**Author:** ![wjwwood](https://sea2.discourse-cdn.com/flex022/user_avatar/discourse.openrobotics.org/wjwwood/32/13715_2.png) [@wjwwood](https://discourse.openrobotics.org/u/wjwwood)\
**Post date:** [June 9, 2022, 11:15pm UTC](https://discourse.openrobotics.org/t/ros2-logging-using-fmt/25978/10 "2022-06-09T23:15:14Z")

</div>

> [@facontidavide](#):
>
> But I think I have never seen functions called inside a logging macro like that.

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

[https://github.com/ros-visualization/rviz/issues/775#issuecomment-59185412](https://github.com/ros-visualization/rviz/issues/775#issuecomment-59185412)

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.