Incorrect time calculation in loop.call_at()

[yope]

• uvloop version: 0.11.2
• Python version: 3.6.7
• Platform: ubuntu 18.10
• Can you reproduce the bug with PYTHONASYNCIODEBUG in env?: yes

There is a conceptual bug in the calculation of the time in call_at() here:
https://github.com/MagicStack/uvloop/blob/master/uvloop/loop.pyx#L1270
If an application calculates a time in the future to call a function with call_at(), it should be able to expect
the value of loop.time() when called inside that function to be equal or higher (later) than the timestamp that was specified. Due to timer resolution and the fact that call_at() internally does "when - self.time()" causes that this assumption is not guaranteed to be true.
The following script demonstrates this:

#!/usr/bin/env python3

import sys
import asyncio
import uvloop
asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())

def mytimer():
        global ti
        global loop
        ti0 = loop.time()
        print(ti, ti0)
        if ti > ti0:
                print("ERROR!!!")
                sys.exit(1)
        ti = ti0 + 0.1
        loop.call_at(ti, mytimer)


if __name__ == "__main__":
        global ti
        global loop
        loop = asyncio.get_event_loop()
        ti = loop.time()
        loop.call_at(ti + 1.0, mytimer)
        loop.run_forever()

Eventually this script will stop after printing "ERROR!!!". This means that the timer handler mytimer() was
called a bit too early.

[fantix]

I can reproduce this, even after fixing a floating-point precision issue in your demo script:

-        if ti > ti0:
+        if ti - ti0 > 0.0000001:

Also when failing, it is always called 1ms earlier than expected in my ~20 tries. I think the reason is:

1. libuv only provides integers in millisecond with uv_now() which is used by uvloop.
2. uvloop turns this millisecond to seconds in float.
3. After tweaking (+ 0.1), the float second is again changed back to integer millisecond truncating all decimals e.g. 0.09899999998742715 * 1000 -> 98, hence losing the 1ms.

I think the fix would be as easy as using round instead of the implicit floor:

-        when = <uint64_t>(delay * 1000)
+        when = <uint64_t>round(delay * 1000)

At least it didn't report an error in 10+ minutes in my local testing.

[yope]

@fantix Yes, I think you are right. It definitely is a rounding issue. Is this the only place that time is converted from float to milliseconds integer? I guess all such places would have to be changed...
For now, as a workaround in my code, I simply add 1ms to each timestamp given to call_at(). This seems to work well enough for me while waiting for the correct fix.

[fantix]

Is this the only place that time is converted from float to milliseconds integer?

Yes, this is the only place.

For now, as a workaround in my code, I simply add 1ms to each timestamp given to call_at().

Right, that should work for now. I'll create a PR to add the round if no objections.

[1st1]

Yeah, go for it!

[jlaine]

If we want this to be "no earlier than" shouldn't this be a ceil() ?

[fantix]

Using ceil() has a side-effect:

round((123123.1 + 0.1) * 1000)      # 123123200
math.ceil((123123.1 + 0.1) * 1000)  # 123123201

But yeah, I got your point that when called with loop.call_later(0.0004, ...), it may still get called too early. One possible solution could be to still use round(), but adding a time check before calling, and delay one more millisecond if the check fails. (This would also help with the failing unit test in this PR when PYTHONASYNCIODEBUG=1) However this would add a bit more complexity to the implementation, I'm not sure if it is worth it. Any thoughts, please?

[yope]

UVloop has a timer resolution of 1ms, so if call_at of higher than that resolution is made, uvloop may round up or down to whole milliseconds. How it does that is not so important.
What is important, is that whenever I want to call_at() a time that is an integer number of milliseconds, it does not get called at an earlier integer number of milliseconds.
In other words, if I run call_at(12.34, func) it does not get called at 12.399. In this case, round() should suffice.
OTOH, if I call_at(12.3456, func) and func gets called at either 12.345 or 12.236, that is not an issue because this is due to the resolution of uvloop. If you need more resolution than that, don't use uvloop.

[1st1]

when called with loop.call_later(0.0004, ...), it may still get called too early.

And that's probably fine, because the interval is less than the timer resolution. I think using round() instead of the implicit floor/cast should be a good enough solution.

[jlaine]

Okidoki, I'll butt out ;)

[1st1]

Fixed in uvloop 0.12.2.