EventsExecutor with an overrunning timer can lead to a burst of timer events

Hi,

I recently found an issue with the EventsExecutor relating to timers. If a timer callback is running slower than its period then it will create multiple timer events inside the EventsExecutor. This leads to 2 issues:

1. Other events will not run untill all queued timers events finish
2. If the timer callback starts running faster than its period, a sudden burst of timer events will run.

Example:

The code to reproduce the following is given at the end. I am running ROS2 rolling (commit: fa63fcf) on Ubuntu 24.04.
The first node is running a timer at 1Hz with a callback that publishes a message before sleeping for 2 seconds. A second node listens and measures the time between messages. The sleep time can be changed via:

ros2 topic pub /sleep_time std_msgs/msg/Float32 data:\ 0.01 -1

[1742020721.948124157] [timer]: Sleeping for 2s
[1742020723.948503266] [timer]: Sleeping for 2s
[1742020725.948874691] [timer]: Sleeping for 2s
# Change sleep time via topic publish
[1742020727.949180636] [timer]: Sleeping for 2s
[1742020729.949529014] [timer]: Sleeping for 2s
[1742020731.949896610] [timer]: Sleeping for 2s
[1742020733.950346696] [timer]: Sleep changed to 0.01s
[1742020733.950519795] [timer]: Sleeping for 0.01s
[1742020733.960805382] [timer]: Sleeping for 0.01s
[1742020733.970983523] [timer]: Sleeping for 0.01s
[1742020733.981356796] [timer]: Sleeping for 0.01s
[1742020733.991467761] [timer]: Sleeping for 0.01s
[1742020734.001641077] [timer]: Sleeping for 0.01s
[1742020734.011971792] [timer]: Sleeping for 0.01s
[1742020734.948141115] [timer]: Sleeping for 0.01s

[1742020723.949210626] [listener]: 2.00s since last msg
[1742020725.949705513] [listener]: 2.00s since last msg
[1742020727.949967365] [listener]: 2.00s since last msg
[1742020729.950338307] [listener]: 2.00s since last msg
[1742020731.950672321] [listener]: 2.00s since last msg
[1742020733.950973936] [listener]: 2.00s since last msg
[1742020733.961644347] [listener]: 0.01s since last msg
[1742020733.971437846] [listener]: 0.01s since last msg
[1742020733.982336222] [listener]: 0.01s since last msg
[1742020733.991988856] [listener]: 0.01s since last msg
[1742020734.002141092] [listener]: 0.01s since last msg
[1742020734.012680243] [listener]: 0.01s since last msg
[1742020734.948896185] [listener]: 0.94s since last msg

Why does this happen?

From my understanding of the EventsExecutor, it will add a timer event after each period of the timer regardless of if the timer has finished running or if there are other timer events in the queue. This leads to a build up of timer events. This backlog is the underlying root cause for both 1 and 2. The backlog will delay other incoming events (such as messages) and lead to the burst of timer events when the running time drops.

Observed behavioral differences to other executors:

SingleThreadedExecutor
The SingleThreadedExecutor does not display either of the behaviors. If you publish a new message, its callback will be executed after the current timer. If the running time suddenly changes, the timer doesn't run faster than its period.

[1742021683.638852022] [timer]: Sleeping for 2s
[1742021685.639544024] [timer]: Sleeping for 2s
[1742021687.640497810] [timer]: Sleeping for 2s
# Change sleep time via topic publish
[1742021689.641067579] [timer]: Sleep changed to 0.01s
[1742021689.641696092] [timer]: Sleeping for 0.01s
[1742021690.630587182] [timer]: Sleeping for 0.01s
[1742021691.630362444] [timer]: Sleeping for 0.01s

[1742021685.640179538] [listener]: 2.00s since last msg
[1742021687.641565372] [listener]: 2.00s since last msg
[1742021689.642392340] [listener]: 2.00s since last msg
[1742021690.631326976] [listener]: 0.99s since last msg
[1742021691.631014510] [listener]: 1.00s since last msg
[1742021692.631126469] [listener]: 1.00s since last msg
[1742021693.631281098] [listener]: 1.00s since last msg

MultiThreadedExecutor
The MultiThreadedExecutor can suffer from 1 (solvable by changing the setup of the callback groups) but should not suffer from 2. The issue with 1 has already been raised by this other issue https://github.com/ros2/rclcpp/issues/2402.

[1742023237.544478638] [timer]: Sleeping for 2s
[1742023239.544637552] [timer]: Sleeping for 2s
# Change sleep time via topic publish
[1742023241.413120711] [timer]: Sleep changed to 0.01s
[1742023241.545369667] [timer]: Sleeping for 0.01s
[1742023242.544485380] [timer]: Sleeping for 0.01s

[1742023239.545041922] [listener]: 2.00s since last msg
[1742023241.545763552] [listener]: 2.00s since last msg
[1742023242.545228901] [listener]: 1.00s since last msg
[1742023243.545049661] [listener]: 1.00s since last msg

Code to reproduce

Timer

#include <chrono>
#include <memory>
#include <string>

#include "rclcpp/rclcpp.hpp"
#include "rclcpp/experimental/executors/events_executor/events_executor.hpp"
#include "std_msgs/msg/float32.hpp"
#include "std_msgs/msg/bool.hpp"


using namespace std::chrono_literals;

class Timer : public rclcpp::Node
{
public:
  Timer()
  : Node("timer")
  {
    auto callback_group = create_callback_group(rclcpp::CallbackGroupType::MutuallyExclusive);
    rclcpp::SubscriptionOptions options;
    options.callback_group = callback_group;

    timer_ = this->create_wall_timer(1000ms, std::bind(&Timer::timer_callback, this));

    sleep_time_sub_ = this->create_subscription<std_msgs::msg::Float32>(
      "sleep_time", 10, std::bind(&Timer::sleep_time_callback, this, std::placeholders::_1), options);

    publisher_ = this->create_publisher<std_msgs::msg::Bool>("msg", 10);
  }

  private:
  void timer_callback()
  {        
    rclcpp::Rate wait_time(1.0/sleep_time_);

    RCLCPP_INFO_STREAM(get_logger(), "Sleeping for " << sleep_time_ << "s");
    publisher_->publish(std_msgs::msg::Bool());
    wait_time.sleep();
  }

  void sleep_time_callback(const std_msgs::msg::Float32::SharedPtr msg)
  {
    sleep_time_ = msg->data;
    RCLCPP_INFO_STREAM(get_logger(), "Sleep changed to " << msg->data << "s");
  }

private:
  rclcpp::TimerBase::SharedPtr timer_;
  rclcpp::Subscription<std_msgs::msg::Float32>::SharedPtr sleep_time_sub_;
  rclcpp::Publisher<std_msgs::msg::Bool>::SharedPtr publisher_;

  float sleep_time_{2.0f};
};

int main(int argc, char * argv[])
{
  rclcpp::init(argc, argv);

  auto node = std::make_shared<Timer>();

  rclcpp::experimental::executors::EventsExecutor executor;
  // rclcpp::executors::SingleThreadedExecutor executor;
  // rclcpp::executors::MultiThreadedExecutor executor;

  executor.add_node(node);
  executor.spin();

  rclcpp::shutdown();
  return 0;
}

Listener

#include <memory>

#include "rclcpp/rclcpp.hpp"
#include "std_msgs/msg/bool.hpp"

class Listener : public rclcpp::Node
{
public:
  Listener()
  : Node("listener")
  {
    subscription_ =
      this->create_subscription<std_msgs::msg::Bool>("msg", 10, std::bind(&Listener::callback, this, std::placeholders::_1));
  }

  void callback(std_msgs::msg::Bool::UniquePtr msg) 
  {
    auto current_time = std::chrono::steady_clock::now();
        
    // Calculate the time difference between the current time and the last received time
    auto duration = std::chrono::duration_cast<std::chrono::duration<float>>(current_time - last_time_);
    
    // Print the time difference in milliseconds
    RCLCPP_INFO(get_logger(), "%.2fs since last msg", duration.count());
    
    // Update the last time to the current time
    last_time_ = current_time;
  }

private:
  std::chrono::steady_clock::time_point last_time_;
  rclcpp::Subscription<std_msgs::msg::Bool>::SharedPtr subscription_;
};

int main(int argc, char * argv[])
{
  rclcpp::init(argc, argv);
  rclcpp::spin(std::make_shared<Listener>());
  rclcpp::shutdown();
  return 0;
}