Improving ROS2 logging with spdlog and fmt

Projects
, ,
1

Hey everyone,

Lately I’ve been experimenting a little bit with the logging system in ros2, and thought it would be a fun project to just try out what would happen if we were to use spdlog as a underlying system for it. I’ve seen at least some interest from some folks here that wanted to use fmt for example (like ROS2 logging using FMT - ROS General - Open Robotics Discourse and GitHub - xqms/rosfmt: ROS wrapper for the fmt library), so I also wanted to take a crack at it and see what I could do :smiley:

My approach works by disabling the auto-initialization of the logging system in rclcpp::init(), and by manually setting rcl global logging output handler to my custom (thread-safe) sink, which parses it with the same printf formatting, and then forwards it to its respective spdlog logger

This means that you can use spdlog for yourself, and enjoy all the benefits of the fmtlib, while maintaining compatiblity with other ros2 third party libraries :tada:

This also makes all log calls (optional, on by default) asynchronous, which could lead to some performance improvements, and this makes it super easy to customize, since you can just add all your custom spdlog sinks and all log calls will be forwarded to these (including from all of these third party libraries using rclcpp logging macros)!

You can find the project here!
https://github.com/jncfa/ros2_spdlog_logger/

If you have any comments or suggestions I would be really glad to hear them out!!

I think it would be wise to leave a small disclaimer about this package though: while this will work perfectly fine for most people, I am quite certain that the rcl logging system isn’t meant to be abused in this manner so please do keep that in mind, this was mostly done for fun and to learn about the internals of rcl/rclcpp :laughing:

Also, I am aware that ros2 uses spdlog to write the file logs, but I did not find this flexible enough for what I wanted to do, I had some different ideas in mind :stuck_out_tongue_closed_eyes:

To see an example of how this works, you can check out this example code:

2 Likes
2

@jncfa thanks for sharing the information.

according to the implementation, it generates the new dependency for ros2_spdlog_logger spdlog and fmt?

and as far as i see the implementation, this is for configuring spdlog with different sink or managing the logger threads in ros2_spdlog_logger.

i think that if the application wants to use the specific logger, they can use it in the application with the dependency without any interfaces such as rcl_logging_interface.

that is the most performative for user application, i think.

we actually have our own proprietary logging backend, which is lock-free with using CAS instruction, in-memory logging implementation.

but we have that implementation behind rcl_logging_interface as well, all this is for application modularity and portability depends on the use cases and business logics. (i believe this is why and what interfaces are for.)

besides, if that is the problem is how flexibly to configure the logging backend behind rcl_logging_interface, i would suggest that we probably want to consider ROS 2 logging configuration spec below.

(*) argument is defined, but never implemented.

so that we can have abstracted ROS 2 generic configuration that can be mapped to the backend specific configuration, and we can configure the backend logging implementation via rcl_logging_interface. i actually am interested in this development and discussion, so if you are interested, maybe we can discuss on this.

thanks for bringing the idea! appreciate it!

Best,
Tomoya

2 Likes
3

@tomoyafujita Thank you for talking the time to go over this :slight_smile:

according to the implementation, it generates the new dependency for ros2_spdlog_logger spdlog and fmt?

and as far as i see the implementation, this is for configuring spdlog with different sink or managing the logger threads in ros2_spdlog_logger.

Sort of, I had two goals here basically:

  • Replace rcl/rcutils logging backend entirely with spdlog. I wanted to use spdlog since it’s pretty easy to use and safe (much safer than vsnprintf, which already caused me too many headaches with segfaults…), and to try out some custom spdlog sinks easily, like this one;
  • But ensure I couldn’t break compatibility with any existing code that relies on the normal rclcpp macros (meaning I needed somehow to maintain the vsnprintf calls to format the messages, but only in these cases), but still have those messages being somehow forwarded to spdlog to leverage those data sinks.

Since the backend is just spdlog, it’s very easy to add new data sinks to process the messages (even ones that were previously using rclcpp logging macros).
You can even easily setup per-logger data sinks (e.g. logging to different files on different loggers), which I think is pretty useful at times.

i think that if the application wants to use the specific logger, they can use it in the application with the dependency without any interfaces such as rcl_logging_interface.

that is the most performative for user application, i think.

While this is true, I do feel like getting any customization out of the logging system is quite cumbersome currently. If I want a custom backend I would need to make my own based off of rcl_logging_interface, and recompile rcl to link to my custom backend, which doesn’t seem like the most practical approach.

I would like for there to be some sort of easier API I could leverage in my node to add it, but I don’t know how much portability / modularity you would lose out on with something like this.

we actually have our own proprietary logging backend, which is lock-free with using CAS instruction, in-memory logging implementation.

but we have that implementation behind rcl_logging_interface as well, all this is for application modularity and portability depends on the use cases and business logics. (i believe this is why and what interfaces are for.)

I assume in that case you replaced the rcl_logging_spdlog with you own external library. But I do have a couple of questions about that:

  • Did you notice any meaningful performance difference by having this lock-free implementation here? Since all logging calls from rclcpp are under a
    global mutex, I would assume that this would be the bigger bottleneck. In this implementation, I replaced it entirely with a thread-safe handler, that formats the message and forwards it to spdlog, which should improve multi-threaded performance.
  • How do you customize your logging backend – do you also use the config_file parameter you mentioned during initialization to set everything up?

besides, if that is the problem is how flexibly to configure the logging backend behind rcl_logging_interface, i would suggest that we probably want to consider ROS 2 logging configuration spec below.

so that we can have abstracted ROS 2 generic configuration that can be mapped to the backend specific configuration, and we can configure the backend logging implementation via rcl_logging_interface. i actually am interested in this development and discussion, so if you are interested, maybe we can discuss on this.

I think this is a ongoing discussion for some time right?

From my limited experience, I think there would be some benefit towards promoting spdlog to be used as the main logging backend (as it seemed to be suggested in that issue as well, though definitely not in the way I did it), since I feel like it’s a bit underwhelming to just use it to log to files :sweat_smile:

But I wouldn’t mind contributing towards improving the logging system in some way or another if you feel like I could be of help, feel free to reach out :slight_smile: