Investigate why test_multithreaded_executor fails

[ivanpauno]

Bug report

It has been failing on linux CI:

• https://ci.ros2.org/view/nightly/job/nightly_linux_repeated/1858/testReport/junit/rclcpp/TestMultiThreadedExecutor/timer_over_take/.

#1105 was an attempt to make the test more reliable, but it seems to be actually failing for good reasons (i.e. something is broken).

See discussion here #907 (comment).

#1109 (review) will mark the test temporally as xfail, that should be removed after the test is fixed.

[Barry-Xu-2018]

@ivanpauno

About #907 (comment),
maybe it's better to update from

        if (diff < PERIOD - TOLERANCE || diff > PERIOD + TOLERANCE) {
          executor.cancel();
          ASSERT_GT(diff, PERIOD - TOLERANCE);
        }

to

        if (diff > PERIOD + TOLERANCE) {
          executor.cancel();
          ASSERT_LT(diff, PERIOD + TOLERANCE);
        }
        if (diff < PERIOD - TOLERANCE) {
          executor.cancel();
          ASSERT_GT(diff, PERIOD - TOLERANCE);
        }

Besides, about the test timer creating a period with 100ms

auto timer = node->create_wall_timer(100ms, timer_callback, cbg);

This timer expects the callback called ideally as follows,

100ms(now-last) timer callback
100ms(now-last) timer callback
100ms(now-last) timer callback

But if there is something happened to block (or consume time, ie. thread switching) between timer ready and callback trigger, the callback might be,

120ms(now-last) timer callback   
80ms(now-last) timer callback
100ms(now-last) timer callback

PERIOD=0.1s (same to the timer period), TOLERANCE=0.025s.
If 120ms(now-last) turns to 150ms, the next item will be about 50ms, which is not expected. (diff < PERIOD - TOLERANCE, and then ASSERT_GT(diff, PERIOD - TOLERANCE))

I think it is a possible way to make the issue happened.
In #1105, you adjust PERIOD and TOLERANCE. I agree with this modification. But I think 100ms in below code should be changed at the same time.

auto timer = node->create_wall_timer(100ms, timer_callback, cbg);

What do you think ?

[fujitatomoya]

@ivanpauno @Barry-Xu-2018

i was trying to reproduce this issue, but cannot do it so far.(using amd64 i7-3770 / Ubuntu18.04 / source build) i am not sure about the ROS2 CI back-end machines, but it depends on the system resource and situation. technically this could happen with certain condition.

If 120ms(now-last) turns to 150ms, the next item will be about 50ms

(nitpick: 1st of all, 150ms is over the threshold.)

I believe this is correct,
on the other hand, test application needs to check cyclic with static period because this is the user aspect.

if anything i can help, just let me know.

[ivanpauno]

I think it is a possible way to make the issue happened.
In #1105, you adjust PERIOD and TOLERANCE. I agree with this modification. But I think 100ms in below code should be changed at the same time.

auto timer = node->create_wall_timer(100ms, timer_callback, cbg);

What do you think ?

I overlooked the original code 🤦‍♂️ . I will try that, thanks!

[ivanpauno]

Fixed by #1105