Issue with RCLCPP THROTTLE logging in the plugin based approach
saikishor opened this issue · 4 comments
Bug report
Hello!
I've a plugin that I use it to perform some computations and return and this plugin runs at a higher frequency, and then to reduce spamming, I've changed the original logging with THROTTLE. It works fine as long as only one plugin is loaded in my system. If I load multiple plugins of the same type, it doesn't print the THROTTLE log of other plugins but only the first one even though they have different loggers with different names.
I believe this is caused by the fact that the RCLCPP_XXX_THROTTLE internally uses the following macro RCUTILS_LOG_CONDITION_THROTTLE_BEFORE and this is using some static variables inside. The condition for logging (i.e., if a certain duration has passed since the last log message) will remain the same, as this is determined by the code in the macro, not by the logger. The __rcutils_logging_last_logged variable, which keeps track of the last time a log message was outputted, is static and unique to each line where the macro is used. Therefore, even if you change the logger, the duration-based condition for logging will still be unique to each line.
I think it makes sense to also consider the logger type to be same or not in the same check as well. In my current implementation, the logger name is changed depending on the name of the plugin, but not the type. This way it is unique for every plugin instance.
Required Info:
- Operating System:
- Ubuntu 22.04 and 24.04
- Installation type:
- Binaries
Expected behavior
Different loggers should have different throttles even if they are in the same line as the plugin
Actual behavior
Different loggers are throttles as one and the information is lost inside the plugin
Is there a workaround or a better approach in this case?
@saikishor thanks for creating the issue and good description.
your assumption is correct, with current implementation, throttle mechanism operates in global process space, not each logger object.
although this is how implemented at this moment, i am not sure if this is bug or unexpected behavior. please wait for the other comments and feedbacks here.
Consideration Note:
IMO, this can be enhanced with logger object granularity, so that each logger can have throttle mechanism. for doing so, maybe we need to be able to configure the logger with throttle duration and keep it in the hash map storage aligned with log level. then determine throttle should open or close based on the configured duration.
@ros2/team any thoughts?
Maintenance triage meeting today discussed this one for quite a bit. The conclusion is that this is in fact a bug, but the implementation of the RCUTILS_LOG_CONDITION_THROTTLE_BEFORE is generally not great. This was added to support migration from the equivalent ROS 1 equivalent macros, but since there isn't any additional state or locking mechanisms on a per-logger basis (especially in the rcutils level), this ends up forming a throttle for the entire application.
In order to correctly implement throttle in the short term, it would be advisable to do it in the application code. In the longer term, this implementation could live in rclcpp with the corresponding rcutils macros being deprecated and removed.
Thank you @mjcarroll. I'm happy to see some news on this. Thanks for the nice summary.
In order to correctly implement throttle in the short term, it would be advisable to do it in the application code.
Hello @mjcarroll!
Could you explain how the throttle can be implemented at the application level to properly throttle per logger?
Thank you!