[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

[DeveloperPaul123]

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

[DeveloperPaul123]

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.

[DeveloperPaul123]

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

[DeveloperPaul123]

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