Uvloop: Loop time does not pass when loop is blocked

[ze-phyr-us]

• uvloop version: 0.4.25
• python version: 3.5
• platform: Mac OS X, Linux

Some of my timing- and debouncing-related tests are failing when I replace asyncio loop with uvloop. I tracked it down to loop.time not increasing when the loop isn't running (e.g. when I'm blocking with time.sleep).

First, an example of call_later malfunctioning:

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


def f():
    print('f   ', time.time())


async def main(loop):
    await asyncio.sleep(0.001)
    time.sleep(1)
    print('main', time.time())
    loop.call_later(1, f)
    await asyncio.sleep(1)


loop = asyncio.get_event_loop()
loop.run_until_complete(main(loop))

There should be a 1-second difference between the two printed times, but actual output is

main 1463724375.72489
f    1463724375.725403

Second, a demonstration that this has something to do with loop.time:

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


async def test1(loop):
    T0 = loop.time()
    time.sleep(1)
    print(loop.time() - T0)


async def test2(loop):
    T0 = loop.time()
    time.sleep(1)
    await asyncio.sleep(0.001)
    print(loop.time() - T0)


async def test3(loop):
    T0 = loop.time()
    await asyncio.sleep(0.001)
    time.sleep(1)
    print(loop.time() - T0)


loop = asyncio.get_event_loop()
loop.run_until_complete(test1(loop))
loop.run_until_complete(test2(loop))
loop.run_until_complete(test3(loop))

In all three cases a difference of 1 second should be printed. Actual output is

0.0
1.0019999999785796
0.0010000000474974513

Note that test2 works as expected because the loop is given a chance to "catch up" during that millisecond wait. test3 shows that asyncio.sleep before the blocking call is accounted for.

Both examples behave "correctly" if you just comment out the set_event_loop_policy call.

I have no idea how to fix this but I hope this report helps you. Really excited to try uvloop in a stock trading platform I work on!

[1st1]

This happens because libuv caches the "now" time and only makes one syscall per loop iteration to refresh it. There is a special function to invalidate the cache -- uv_update_time -- which I think I'll use in loop.time now, to be compliant with asyncio.

[1st1]

Should be fixed in the master branch. I'll issue a new release shortly.

[1st1]

I've just released uvloop v0.4.26. Please check it out.

[ze-phyr-us]

@1st1 Thanks for the quick response. loop.time seems to be working correctly now, but my first test program is still behaving the same. call_later fires the callback immediately. Steps to reproduce:

$ virtualenv -p $(which python3) env && . env/bin/activate
Running virtualenv with interpreter /usr/local/bin/python3
Using base prefix '/usr/local/Cellar/python3/3.5.1/Frameworks/Python.framework/Versions/3.5'
New python executable in env/bin/python3.5
Also creating executable in env/bin/python
Installing setuptools, pip...done.


(env)$ pip install uvloop==0.4.26
Downloading/unpacking uvloop==0.4.26
  Downloading uvloop-0.4.26.tar.gz (1.9MB): 1.9MB downloaded
  Running setup.py (path:/private/tmp/env/build/uvloop/setup.py) egg_info for package uvloop

    warning: no previously-included files matching '*' found under directory 'vendor/libuv/.git'
    warning: no previously-included files matching '*' found under directory 'vendor/libuv/docs'
    warning: no previously-included files matching '*' found under directory 'vendor/libuv/img'
Installing collected packages: uvloop
  Running setup.py install for uvloop

  [SNIP]


(env)$ pip freeze
uvloop==0.4.26


(env)$ cat > test.py
import asyncio
import time
import uvloop
asyncio.set_event_loop_policy(uvloop.EventLoopPolicy())


def f():
    print('f   ', time.time())


async def main(loop):
    await asyncio.sleep(0.001)
    time.sleep(1)
    print('main', time.time())
    loop.call_later(1, f)
    await asyncio.sleep(1)


loop = asyncio.get_event_loop()
loop.run_until_complete(main(loop))
^D


(env)$ python test.py
main 1463967084.144865
f    1463967084.145064

[1st1]

Please try v0.4.27. I think I've finally fixed this.

[ze-phyr-us]

It works! Thank you very much.