Changing an active deadline_timer's expiry time not working as expected

32 Views Asked by At

I tried to restart a boost asio timer but it is not working as expected

The code is based on www.boost.org/doc/libs/1_84_0/doc/html/boost_asio/reference/steady_timer.html#boost_asio.reference.steady_timer.changing_an_active_waitable_timer_s_expiry_time

The output is

0 : Start at 
0 : ioContext.run()
1000 : on_timeout Timeout reached error=0
1100 : Too late, timer has already expired after 1100 ms
2200 : We managed to cancel the timer after 1100 ms
3300 : We managed to cancel the timer after 1100 ms
...

but should be something like:

0 : Start at 
0 : ioContext.run()
1000 : on_timeout Timeout reached error=0
1000 : Too late, timer has already expired after 1100 ms
2000 : on_timeout Timeout reached error=0
2000 : Too late, timer has already expired after 1100 ms
3000 : on_timeout Timeout reached error=0
3000 : Too late, timer has already expired after 1100 ms
...
#include <chrono>
#include <functional>
#include <iostream>
#include <thread>

#include <boost/asio.hpp>

long int millis() {
  static long int offset = std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now().time_since_epoch()).count();
  return std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now().time_since_epoch()).count() - offset;
}

class BoostAsioTimerEval {
 public:
  BoostAsioTimerEval(boost::asio::io_context& ioContext)
      : ioContext_(ioContext), timer_(ioContext_), interval_(std::chrono::milliseconds{1000}), lastMillis_(millis()) {
    timer_.expires_after(interval_);
    timer_.async_wait(std::bind(&BoostAsioTimerEval::on_timeout, this, std::placeholders::_1));
    std::cout << millis() << " : Start at " << std::endl;
  }

  void on_event() {
    if (timer_.expires_after(interval_) > 0) {
      std::cout << millis() << " : We managed to cancel the timer after " << (millis() - lastMillis_) << " ms" << std::endl;
      timer_.async_wait(std::bind(&BoostAsioTimerEval::on_timeout, this, std::placeholders::_1));
    } else {
      std::cout << millis() << " : Too late, timer has already expired after " << (millis() - lastMillis_) << " ms" << std::endl;
      // kick again
      timer_.expires_after(interval_);
      timer_.async_wait(std::bind(&BoostAsioTimerEval::on_timeout, this, std::placeholders::_1));
    }
    lastMillis_ = millis();
  }

  void on_timeout(const boost::system::error_code& error) {
    if (error != boost::asio::error::operation_aborted) {
      std::cout << millis() << " : on_timeout Timeout reached error=" << error.value() << std::endl;
    } else {
      std::cout << millis() << " : on_timeout Timeout aborted error=" << error.value() << std::endl;
    }
  }

 private:
  boost::asio::io_context& ioContext_;
  boost::asio::steady_timer timer_;
  std::chrono::milliseconds interval_;
  long int lastMillis_;
};

int main(int argc, char** argv) {
  boost::asio::io_context ioContext;
  BoostAsioTimerEval boostAsioTimerEval(ioContext);
  std::thread worker([&]() {
    for (int i = 0; i < 10; ++i) {
      const int sleep = 1100;
      std::cout << millis() << " : sleep for " << sleep << " ms" << std::endl;
      std::this_thread::sleep_for(std::chrono::milliseconds(sleep));
      boostAsioTimerEval.on_event();
    }
    ioContext.stop();
  });
  std::cout << millis() << " : ioContext.run()" << std::endl;
  ioContext.run();
  worker.join();
  return 0;
}
1

There are 1 best solutions below

3
sehe On

Firstly I sanitized the code. So millis() could actually just read return (now() - offset) / 1ms

Also taking care to avoid TOCTOU race conditions with the timer updates, so:

auto time  = now();
auto delta = (time - std::exchange(lastMillis_, time)) / 1ms;

I arrived at Live On Coliru

#include <boost/asio.hpp>
#include <iostream>
#include <syncstream>
namespace asio     = boost::asio;
using Clock        = std::chrono::steady_clock;
constexpr auto now = Clock::now;
using namespace std::chrono_literals;
using std::placeholders::_1;

static auto const g_start_time = now();

template <typename... Args> void trace(Args const&... args) {
    auto ts = (now() - g_start_time) / 1ms;
    ((std::osyncstream(std::cout) << "at" << std::setw(8) << ts << "ms: ") << ... << args) << std::endl;
}

struct TimerEval {
    TimerEval(asio::io_context& ioContext) : timer_(ioContext) {
        timer_.expires_after(interval_);
        timer_.async_wait(bind(&TimerEval::on_timeout, this, _1));
        trace("start");
    }

    void on_event() {
        auto time  = now();
        auto delta = (time - std::exchange(lastMillis_, time)) / 1ms;

        if (timer_.expires_after(interval_) > 0) {
            trace("timer canceled after ", delta, " ms");
            timer_.async_wait(bind(&TimerEval::on_timeout, this, _1));
        } else {
            trace("timer already expired after ", delta, " ms");
            // kick again
            timer_.expires_after(interval_);
            timer_.async_wait(bind(&TimerEval::on_timeout, this, _1));
        }
    }

    void on_timeout(boost::system::error_code ec) { trace("on_timeout ", ec.message()); }

  private:
    asio::steady_timer timer_;
    Clock::duration    interval_   = 1000ms;
    Clock::time_point  lastMillis_ = now();
};

int main() {
    asio::io_context ioContext;
    TimerEval        timer(ioContext);

    std::thread worker([&]() {
        for (int i = 0; i < 10; ++i) {
            const auto delay = 1100ms;
            trace("sleep for ", delay);
            std::this_thread::sleep_for(delay);
            timer.on_event();
        }
        ioContext.stop();
    });

    trace("ioContext.run()");
    ioContext.run();
    worker.join();
}

Indeed it prints:

at       0ms: start 
at       0ms: ioContext.run()
at       0ms: sleep for 1100ms
at    1000ms: on_timeout Success
at    1100ms: timer already expired after 1100 ms
at    1100ms: sleep for 1100ms
at    2200ms: timer canceled after 1100 ms
at    2200ms: sleep for 1100ms
at    3301ms: timer canceled after 1100 ms
at    3301ms: sleep for 1100ms
at    4401ms: timer canceled after 1100 ms
at    4401ms: sleep for 1100ms
at    5501ms: timer canceled after 1100 ms
at    5501ms: sleep for 1100ms
at    6601ms: timer canceled after 1100 ms
at    6601ms: sleep for 1100ms
at    7701ms: timer canceled after 1100 ms
at    7702ms: sleep for 1100ms
at    8802ms: timer canceled after 1100 ms
at    8802ms: sleep for 1100ms
at    9902ms: timer canceled after 1100 ms
at    9902ms: sleep for 1100ms
at   11002ms: timer canceled after 1100 ms

I must admit I've never used the return value of expires_after. Instead I'd like to observe that NONE of the on_timeout invocations actually show asio::error::operation_aborted ("Operation canceled") as the ec. So something else is wrong!

Regardless, your line commented // kick again really makes no sense, because it sets the expiry again, after just having done that, realizing that nothing was canceled.

Let's simplify on_event to:

void on_event() {
    auto time  = now();
    auto delta = (time - std::exchange(lastMillis_, time)) / 1ms;

    auto n = timer_.expires_after(interval_);
    timer_.async_wait(bind(&TimerEval::on_timeout, this, _1));
    trace("timer reset (n = ", n, ") after ", delta, " ms");
}

Undefined Behaviour

The first really issue I see is that you have UB (you're accessing timer from multiple threads without synchronization. Now, when you fix that, you will notice something interesting:

    // oops: timer.on_event(); FIXED:
    post(ioc, [&timer] { timer.on_event(); });

The Real Problem

Running that simply prints

at       0ms: start
at       1ms: ioContext.run()
at       1ms: sleep for 1100ms
at    1000ms: on_timeout Success after 1000
at    1102ms: sleep for 1100ms
at    2202ms: sleep for 1100ms
at    3302ms: sleep for 1100ms
at    4402ms: sleep for 1100ms

The reason is, after the first timer completion (on_timeout), the service runs out of work, because your thread isn't work. Indeed, if you add a little trace:

trace("ioContext.run()");
ioc.run();
trace("ioContext.run() returned");

You get

at       0ms: start
at       1ms: ioContext.run()
at       1ms: sleep for 1100ms
at    1000ms: on_timeout Success after 1000
at    1000ms: ioContext.run() returned

That's your problem.

Work Guards

There are several ways to fix this, but let's choose the most "low-level" one first:

std::thread worker([&, work = make_work_guard(ioc)]() {
    for (int i = 0; i < 10; ++i) {
        const auto delay = 1100ms;
        trace("sleep for ", delay);
        std::this_thread::sleep_for(delay);
        post(ioc, [&timer] { timer.on_event(); });
    }
    ioc.stop();
});

The work guard keeps the service alive at least until the end of the worker. In fact, you can drop the ioc.stop() as it is redundant!

Live On Coliru

#include <boost/asio.hpp>
#include <iostream>
#include <syncstream>
namespace asio     = boost::asio;
using Clock        = std::chrono::steady_clock;
constexpr auto now = Clock::now;
using namespace std::chrono_literals;
using std::placeholders::_1;

static auto const g_start_time = now();

template <typename... Args> void trace(Args const&... args) {
    auto ts = (now() - g_start_time) / 1ms;
    ((std::osyncstream(std::cout) << "at" << std::setw(8) << ts << "ms: ") << ... << args) << std::endl;
}

struct TimerEval {
    TimerEval(asio::io_context& ioc) : timer_(ioc) {
        timer_.expires_after(interval_);
        timer_.async_wait(bind(&TimerEval::on_timeout, this, _1));
        trace("start");
    }

    void on_event() {
        auto time  = now();
        auto delta = (time - std::exchange(lastMillis_, time)) / 1ms;

        auto n = timer_.expires_after(interval_);
        timer_.async_wait(bind(&TimerEval::on_timeout, this, _1));
        trace("timer reset (n = ", n, ") after ", delta, " ms");
    }

    void on_timeout(boost::system::error_code ec) {
        trace("on_timeout ", ec.message(), " after ", (now() - lastMillis_) / 1ms);
    }

  private:
    asio::steady_timer timer_;
    Clock::duration const interval_   = 1000ms;
    Clock::time_point     lastMillis_ = now();
};

int main() {
    asio::io_context ioc;
    TimerEval        timer(ioc);

    std::thread worker([&, work = make_work_guard(ioc)]() {
        for (int i = 0; i < 10; ++i) {
            const auto delay = 1100ms;
            trace("sleep for ", delay);
            std::this_thread::sleep_for(delay);
            post(ioc, [&timer] { timer.on_event(); });
        }
    });

    trace("ioContext.run()");
    ioc.run();
    trace("ioContext.run() returned");
    worker.join();
}

Prints

at       0ms: start
at       0ms: ioContext.run()
at       0ms: sleep for 1100ms
at    1000ms: on_timeout Success after 1000
at    1100ms: sleep for 1100ms
at    1100ms: timer reset (n = 0) after 1100 ms
at    2100ms: on_timeout Success after 1000
at    2200ms: sleep for 1100ms
at    2200ms: timer reset (n = 0) after 1100 ms
at    3200ms: on_timeout Success after 1000
at    3300ms: sleep for 1100ms
at    3300ms: timer reset (n = 0) after 1100 ms
at    4301ms: on_timeout Success after 1000
at    4401ms: sleep for 1100ms
at    4401ms: timer reset (n = 0) after 1100 ms
at    5401ms: on_timeout Success after 1000
at    5501ms: sleep for 1100ms
at    5501ms: timer reset (n = 0) after 1100 ms
at    6501ms: on_timeout Success after 1000
at    6601ms: sleep for 1100ms
at    6601ms: timer reset (n = 0) after 1100 ms
at    7601ms: on_timeout Success after 1000
at    7701ms: sleep for 1100ms
at    7701ms: timer reset (n = 0) after 1100 ms
at    8701ms: on_timeout Success after 1000
at    8802ms: sleep for 1100ms
at    8802ms: timer reset (n = 0) after 1100 ms
at    9802ms: on_timeout Success after 1000
at    9902ms: sleep for 1100ms
at    9902ms: timer reset (n = 0) after 1100 ms
at   10902ms: on_timeout Success after 1000
at   11002ms: timer reset (n = 0) after 1100 ms
at   12002ms: on_timeout Success after 1000
at   12002ms: ioContext.run() returned

In fact, reducing the delay (to e.g. 900ms) now shows that the n returned from expires_at is actually accurate. It was just the fact that the service wasn't running.


¹ I don't know why people keep hurting themselves with those heinously ridiculous incantations like std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::system_clock::now().time_since_epoch()).count() - just what now ¯\(ツ)