rcl_wait() returns early when a timer awakes

[hidmic]

Bug report

Required Info:

• Operating System:
  • Windows 10
• Installation type:
  • From source
• Version or commit hash:
  • master
• DDS implementation:
  • RTI Connext

Steps to reproduce issue

Run timer tests using rmw_connext_cpp.

Expected behavior

Tests pass.

Actual behavior

Often, tests fail when rcl_wait() returns early when a timer awakes.

Additional information

For one, even though a clock is specified for timers, how rmw_wait() abides to the given timeout is not specified. This issue persists for both steady time and system time timers.

This issue does not occur when using rmw_fastrtps*_cpp or rmw_cyclonedds_cpp, as these return at the right time or (most often) past it.

Suspecting a bug in rmw_connext_cpp, I could confirm that the expected timeout is passed to RTI Connext's WaitSet::wait() API which nonetheless returns early for both steady time and system time clocks. However, I believe this is less of a bug in RTI Connext than a misuse of rmw_wait() for rcl timers' implementation, considering time resolution. The closest achievable timeout on a given OS is not necessarily greater than or equal than any one specified.

[hidmic]

One potential workaround would be to relax the definition of a ready rcl timer using a platform specific time tolerance, and even make that configurable for a user to tune it.

[hidmic]

Alternatively, since it's quite likely not every possible timer period can be achieved due to time resolution constrains, the expectation on rcl timers' period could be relaxed to be just an average quantity over some time window. For instance, if some OS time resolution is 200us and a timer is configured with 500us period, by sleeping 400us and 600us in an alternate fashion it can average the intended 2kHz.

[hidmic]

CC @ivanpauno @wjwwood @peterpena

[clalancette]

I guess what I don't understand about this is that if you ask for 1 nanosecond sleep, then yeah, it might take the OS considerably longer than that to return (maybe on the order of 10ms for time slicing). But if you ask for 10ms sleep, the OS should never return in 9 ms; that's just not doing what the user application asked for.

Extending this to rmw_wait(), I would expect the same thing. It seems like the contract for rmw_wait() should be "wait for at least wait_timeout, unless there was a ready entity, then return early". Do you agree, or am I misunderstanding the problem entirely?

[hidmic]

That is true for a plain sleep, but arguable for a time deadline (and even more so if you want to sustain some periodicity, but that's unrelated to rmw_wait()). And I have the impression that may be the case in Windows under specific circumstances (see second paragraph in this MSVC documentation article). We do not know how RTI Connext implements rmw_wait() timeouts though.

[wjwwood]

I agree with @clalancette about the expectation that it should never return before the time period the user specified. This is the case on Linux and macOS, and I would have extended that to rmw_wait or dds_wait, but maybe that's not guaranteed.

If a timer interval, or relative expiration time, is instead specified, the expiration can occur up to a period earlier than or a period later than the specified time, depending on where exactly the start and end times of this interval fall between system clock ticks.

That block from the Microsoft docs makes me sad, but basically I agree it could end early based on that, assuming that's the same kind of timer that is being used by RTI.

This is also a condition we could check for and at least log something about it. Or even we could go back to sleep if needed.

On the other hand, we could adjust the tests (and our documentation) to reflect reality on Windows (if I understand the core issue correctly).

[hidmic]

This is also a condition we could check for and at least log something about it. Or even we could go back to sleep if needed.

That's fair for wait() APIs, but I'm not entirely convinced we should ignore how this affects rcl timers performance if we consistently overshoot timer timeouts. Or the documentation should be explicit about timer periods being a rough lower bound.

On the other hand, we could adjust the tests (and our documentation) to reflect reality on Windows (if I understand the core issue correctly).

I agree with updating wait() APIs documentation accordingly. Specifying what clock that timeout is defined against would be good too.

[ivanpauno]

I guess what I don't understand about this is that if you ask for 1 nanosecond sleep, then yeah, it might take the OS considerably longer than that to return (maybe on the order of 10ms for time slicing)

👍

But if you ask for 10ms sleep, the OS should never return in 9 ms; that's just not doing what the user application asked for.

👍 I think this one is the problem we have to solve.

And I have the impression that may be the case in Windows under specific circumstances (see second paragraph in this MSVC documentation article).

It's not only that.
rmw_wait uses always the system clock (at least for connext), and timers can use any clock.
Thus, I think the logic in rcl to decide the rmw_wait duration isn't valid, and can be problematic in all platforms.
We might add a tolerance or not, but we do need some sort of "retry wait" logic in case rmw_wait waked up early.

[hidmic]

Thus, I think the logic in rcl to decide the rmw_wait duration isn't valid, and can be problematic in all platforms.

There's that too, yeah. And waking up earlier won't do if the timer clock goes faster than the system's (typical in CI settings using simulation with an RTF > 1). This is a separate issue though.

But if you ask for 10ms sleep, the OS should never return in 9 ms; that's just not doing what the user application asked for.

I will say that a delay (or sleep) and a timeout are two conceptually different things. If you ask for a 10ms delay, then yes, you'd expect it to last 10ms at least. But if you set a 10ms timeout, I'd expect it to last 10ms at most. And thus RTI Connext's WaitSet::wait() behavior makes more sense to me than Fast-RTPS' or CycloneDDS' if and only if it's not possible to get any closer to the requested time due to clock resolution.

[clalancette]

I will point out that that MSVC article says that starting on Windows 8, KeDelayExecutionThread is a lot more precise. It doesn't say anything about KeWaitForSingleObject or KeSetTimer, so I assume they still have the old behavior and can wake up early. Unfortunately, we don't really know which of the APIs Connext is using.

That's fair for wait() APIs, but I'm not entirely convinced we should ignore how this affects rcl timers performance if we consistently overshoot timer timeouts. Or the documentation should be explicit about timer periods being a rough lower bound.

To be fair, on a non-realtime OS, all timer periods are a rough lower bound. So I think that expectation is pretty well set, and I think we could go back to sleep in that case (note that in the above discussion, I've been ignoring signals on Unix anyway, which is another case that might cause a sleep to wake up early and have to go back to sleep). But I definitely agree with you that the documentation should be clear about this.

I will say that a delay (or sleep) and a timeout are two conceptually different things. If you ask for a 10ms delay, then yes, you'd expect it to last 10ms at least. But if you set a 10ms timeout, I'd expect it to last 10ms at most.

I don't think so. At least, that's not how I understand e.g. the timeout on select, the man page for which says:

       The timeout argument specifies the interval that select() should block waiting for a file descriptor to become ready.  The call will block  until
       either:

       *  a file descriptor becomes ready;

       *  the call is interrupted by a signal handler; or

       *  the timeout expires.

       Note  that  the timeout interval will be rounded up to the system clock granularity, and kernel scheduling delays mean that the blocking interval
       may overrun by a small amount.  If both fields of the timeval structure are zero,  then  select()  returns  immediately.   (This  is  useful  for
       polling.)  If timeout is NULL (no timeout), select() can block indefinitely.

[hidmic]

To be fair, on a non-realtime OS, all timer periods are a rough lower bound.

That is true. Not sure about embedded ROS though.

At least, that's not how I understand e.g. the timeout on select

IMHO the choices that select() (or any other POSIX API) makes about how to deal with clock resolution is of no consequence. It does make it way easier to implement if the specified time is greater than 0 but less than one clock resolution unit. We can make the same choice, I just think we can do better.

[brawner]

I think resolving this issue could also resolve some rclpy related failures:
ros2/rclpy#267
ros2/rclpy#513

Or at least they are related, the rclpy issues happen across multiple rmw implementations.

[wjwwood]

But if you set a 10ms timeout, I'd expect it to last 10ms at most.

Yeah, I can't agree with this either. For me a timeout is always "we'll start trying to exit after this period of time". In fact I'd never assume it comes back before or "on time".