[BUG] Execute point is not right

[gzliurc]

uint64_t check_point_1_last = TimeUtil::GetNowMillsecond();
uint64_t check_point_2_last = TimeUtil::GetNowMillsecond();
dp::periodic_function<std::function<void()>, dp::policies::schedule_next_missed_interval_policy> fu([&]() {
    auto now = TimeUtil::GetNowMillsecond();
    LOGD << "Check Point 1::" << (now - check_point_1_last);
    check_point_1_last = now;
    this_thread::sleep_for(chrono::milliseconds(1000));
    now = TimeUtil::GetNowMillsecond();
    LOGD << "Check Point 2::" << (now - check_point_2_last);
    check_point_2_last = now;
}, chrono::milliseconds(5000));
fu.start();

//LOG is 2020-10-29 17:34:49.677 DEBUG [1142] [main@36] Check Point 1::5001 2020-10-29 17:34:50.679 DEBUG [1142] [main@40] Check Point 2::6003 2020-10-29 17:34:53.674 DEBUG [1142] [main@36] Check Point 1::3997 2020-10-29 17:34:54.675 DEBUG [1142] [main@40] Check Point 2::3996 2020-10-29 17:34:57.674 DEBUG [1142] [main@36] Check Point 1::4000 2020-10-29 17:34:58.675 DEBUG [1142] [main@40] Check Point 2::4000 2020-10-29 17:35:01.673 DEBUG [1142] [main@36] Check Point 1::3999 2020-10-29 17:35:02.673 DEBUG [1142] [main@40] Check Point 2::3998 2020-10-29 17:35:05.672 DEBUG [1142] [main@36] Check Point 1::3999 2020-10-29 17:35:06.673 DEBUG [1142] [main@40] Check Point 2::4000

if i change sleep to 2000ms 2020-10-29 17:36:17.804 DEBUG [1172] [main@36] Check Point 1::5001 2020-10-29 17:36:19.807 DEBUG [1172] [main@40] Check Point 2::7004 2020-10-29 17:36:20.802 DEBUG [1172] [main@36] Check Point 1::2998 2020-10-29 17:36:22.802 DEBUG [1172] [main@40] Check Point 2::2995 2020-10-29 17:36:23.801 DEBUG [1172] [main@36] Check Point 1::2999 2020-10-29 17:36:25.802 DEBUG [1172] [main@40] Check Point 2::3000 2020-10-29 17:36:26.801 DEBUG [1172] [main@36] Check Point 1::3000 2020-10-29 17:36:28.802 DEBUG [1172] [main@40] Check Point 2::3000 2020-10-29 17:36:29.801 DEBUG [1172] [main@36] Check Point 1::3000

Period is not at right timing. expect check point 1 should be 5000ms

when i change sleep to random 1000~2000ms 2020-10-29 17:42:34.360 DEBUG [1202] [main@36] Check Point 1::5001 2020-10-29 17:42:35.388 DEBUG [1202] [main@40] Check Point 2::6029 2020-10-29 17:42:38.331 DEBUG [1202] [main@36] Check Point 1::3971 2020-10-29 17:42:40.328 DEBUG [1202] [main@40] Check Point 2::4940 2020-10-29 17:42:41.335 DEBUG [1202] [main@36] Check Point 1::3004 2020-10-29 17:42:42.914 DEBUG [1202] [main@40] Check Point 2::2586 2020-10-29 17:42:44.757 DEBUG [1202] [main@36] Check Point 1::3422 2020-10-29 17:42:46.735 DEBUG [1202] [main@40] Check Point 2::3821 2020-10-29 17:42:47.781 DEBUG [1202] [main@36] Check Point 1::3024 2020-10-29 17:42:49.433 DEBUG [1202] [main@40] Check Point 2::2698

[ptsouchlos]

Hi 👋 Thanks for filing an issue.

I'm trying to make sure I understand correctly what the issue is.

if i change sleep to 2000ms

By this I assume you mean the sleep inside the function callback yes?

Period is not at right timing. expect check point 1 should be 5000ms

But isn't check point 1 at 5000? By looking at the code and the logic you have for measuring the time I don't see any issues with how the code is functioning. Please correct me if I'm wrong.

[gzliurc]

I think the callback function should executed at same interval，but interval depend on callback function elapsed time. if callback function elapsed 1 second, the interval will change to 4 second, not 5sec.

i use asio lib，is easy to controll the interval asio::io_context io_context;

auto time = chrono::milliseconds(5000);
asio::steady_timer timer(io_context, time);
auto last = TimeUtil::GetNowMillsecond();
std::function<void(const std::error_code &)> func = [&](const std::error_code &err) {
    auto now = TimeUtil::GetNowMillsecond();
    LOGD << "Check Point::" << (now - last);
    last = now;
    this_thread::sleep_for(chrono::seconds(2));
    timer.expires_at(timer.expiry() + time);
    timer.async_wait(func);
};
timer.async_wait(func);
io_context.run();

Result，all check point is 5sec 2020-10-30 15:12:31.423 DEBUG [2904] [main@28] Check Point::5001 2020-10-30 15:12:36.422 DEBUG [2904] [main@28] Check Point::4999 2020-10-30 15:12:41.423 DEBUG [2904] [main@28] Check Point::5001 2020-10-30 15:12:46.423 DEBUG [2904] [main@28] Check Point::5000 2020-10-30 15:12:51.423 DEBUG [2904] [main@28] Check Point::5000 2020-10-30 15:12:56.423 DEBUG [2904] [main@28] Check Point::5000

[ptsouchlos]

Ok I see. The behavior you're seeing is intentional in my library. The duration of the callback function is checked on every execution and the scheduled time for the next callback execution is adjusted to take the callback execution time into account.

So if the callback take 1 second to execute and your callback timeout is 5 seconds, the interval will be 4 seconds so that the function is being called at the same absolute time. It sounds like you don't want this behavior so maybe this can be made optional.

[gzliurc]

I am interested in future "Reliable function timing (tested to be within ~1 millisecond)"，so i write a test before use it. The duration of the callback function is hard to be controlled by developer.
I think the duration of the callback function is alway a random value.

[ptsouchlos]

Hmm, maybe I'm misunderstanding the problem. I will dig a bit more and update the issue.

[ptsouchlos]

Runnable example using Wandbox with Boost ASIO https://wandbox.org/permlink/jmI0QkJXpE4XYNKK