New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sleep time is not respected after monkey patch #1227

Closed
champax opened this Issue May 30, 2018 · 5 comments

Comments

Projects
None yet
3 participants
@champax

champax commented May 30, 2018

  • gevent version: 1.3.2.post0
  • Python version: Python 3.5.3
  • Operating System: Debian 4.9.88-1+deb9u1 (2018-05-07) x86_64 GNU/Linux

Description:

This repro on Python 3.5.3 and 3.6.5
This do not repro on Python 2.7
This do not repro on gevent 1.2.2

Repro source code below (repro 100% : first sleep after monkey patch should result in 100 ms sleep, but got a 1 ms effective sleep).

Please note i have weird behavior with sleep not respected (90 ms instead of 100 ms) but i cannot repro this in a single isolated test.

Logs:
python run_failed =0
python run_failed_ar=[]
gevent run_failed =0
gevent run_failed_ar=[]
monkey_gevent run_failed =1
monkey_gevent run_failed_ar=[(0, 1.108407974243164)]
monkey_python run_failed =0
monkey_python run_failed_ar=[]

"""
# -*- coding: utf-8 -*-
"""

import time

import gevent
from gevent import monkey


def _test_sleep(sleep_method, s_text):
    """
    Test
    :param sleep_method: Test
    :param s_text: Test
    """

    loop_count = 10
    sleep_sec = 0.1
    sleep_ms = sleep_sec * 1000.0

    # python
    run_failed = 0
    run_failed_ar = list()
    for i in range(0, loop_count):
        t_start = time.time()
        sleep_method(sleep_sec)
        t_end = time.time()
        t_ms = (t_end - t_start) * 1000.0
        if t_ms < sleep_ms:
            run_failed += 1
            run_failed_ar.append((i, t_ms))

    print("%s run_failed   =%s" % (s_text, run_failed))
    print("%s run_failed_ar=%s" % (s_text, run_failed_ar))
    return run_failed


def test_sleep_all():
    """
    Test
    """

    i = 0
    i += _test_sleep(time.sleep, "python")
    i += _test_sleep(gevent.sleep, "gevent")

    # monkey
    monkey.patch_all(aggressive=True)

    # Here, the first call is dead...
    i += _test_sleep(gevent.sleep, "monkey_gevent")
    i += _test_sleep(time.sleep, "monkey_python")

    if i > 0:
        raise Exception("Failed with i=%s" % i)


# run
test_sleep_all()
@jamadden

This comment has been minimized.

Member

jamadden commented May 30, 2018

I'm sorry, you'll need to be much more specific about what you think the problem is, especially in light of the documented changes around unspecified behaviour such as callbacks.

@laurentL

This comment has been minimized.

laurentL commented May 30, 2018

hi,
After the monkey_patch, the first sleep(0.1) return after 0.001 sec.

import time
import gevent
from gevent import monkey

import argparse
parser = argparse.ArgumentParser()
parser.add_argument("--sleep-before-patch", help="")
args = parser.parse_args()

if args.sleep_before_patch:
    gevent.sleep(0.1)

monkey.patch_all(aggressive=True)
t_start = time.time()
gevent.sleep(0.2)
t_end = time.time()
t_ms = (t_end - t_start) 
print("time elapsed %s sec " % t_ms)
& time python  debug.py --sleep-before-patch true
time elapsed 0.03220248222351074 sec 

real	0m0.387s
user	0m0.240s
sys	0m0.012s

$ time python  debug.py 
time elapsed 0.2005610466003418 sec 

real	0m0.470s
user	0m0.256s
sys	0m0.008s

Why in the fist case the sleep 0.2 is durring 0.03 sec?

@laurentL

This comment has been minimized.

laurentL commented May 30, 2018

another stange test:

import time
import gevent
from gevent import monkey

import argparse
parser = argparse.ArgumentParser()
parser.add_argument("--sleep-before-patch", help="")
args = parser.parse_args()

if args.sleep_before_patch:
    gevent.sleep(0.1)

for _ in range(10):
    monkey.patch_all(aggressive=True)
    t_start = time.time()
    gevent.sleep(0.1)
    t_end = time.time()
    t_ms = (t_end - t_start) 
    print("time elapsed %s sec " % t_ms)
python  debug.py --sleep-before-patch true
time elapsed 0.0011293888092041016 sec 
time elapsed 0.10027360916137695 sec 
time elapsed 0.10031867027282715 sec 
time elapsed 0.10025143623352051 sec 
time elapsed 0.10023307800292969 sec 
time elapsed 0.10028672218322754 sec 
time elapsed 0.10028719902038574 sec 
time elapsed 0.10022139549255371 sec 
time elapsed 0.10022974014282227 sec 
time elapsed 0.10022544860839844 sec 
@champax

This comment has been minimized.

champax commented May 31, 2018

@jamadden
Ok so to be clear, i have unittests checking my tools utilities computing milliseconds difference between time.time and utc dates are correct.

The code is basically : get current millis or utc date, sleep 100 ms, compute millis difference (current millis|date - start millis|date), assert millis difference is greater than 100 ms. Simple, easy.

This was working until gevent <= 1.2.2.
With gevent 1.3 its failing.

Now the tests are failing, because millis difference after sleep 100 ms is lower then 100 ms (usually 80/90 ms), which is indeed an unexpected weird behavior => a sleep statement is something predictive.... If i want to sleep 100 ms, i want to sleep 100 ms, not 1 ms, not 80 ms.

Lets imagine you spawn a greenlet that refresh something every 500 ms. You expect a refresh every 500 ms, not 1 ms, not 400 ms...

So i dig into, but i cannot repro that 100% currently outside my bunch of code.

However i can repro 100% than the first sleep (after a monkey patch) is not respecting the sleep time.

I may dig more, but assuming this behavior is strange, i think you may an issue related to the switch interval recently introduced in 1.3....

@jamadden

This comment has been minimized.

Member

jamadden commented May 31, 2018

What you're seeing is the event loop's notion of the current time and how that interacts with event loop timers. The current time is automatically updated between event loop iterations, and the current time is used to compute the timer expiration, in order to prevent timers from drifting too far. The current time can also be explicitly updated.

There were some changes around when gevent explicitly updates the current time in 1.3 as part of the libuv support. gevent.sleep probably needs to explicitly update the current time now.

jamadden added a commit that referenced this issue May 31, 2018

Sleeping updates the loop's current time always.
That had been disabled for libuv, but now that we run timers in our own code that's not a concern anymore.

Fixes #1227.

jamadden added a commit that referenced this issue May 31, 2018

Sleeping updates the loop's current time always. (#1228)
* Sleeping updates the loop's current time always.

That had been disabled for libuv, but now that we run timers in our own code that's not a concern anymore.

Fixes #1227.

* Try Python 3.5.5 because of the weird Illegal Instruction crash we suddenly see with 3.5.4

* Increase the value; test_sendall_timeout was often failing to actually timeout.

* Really python3.5
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment