time.time() in ipython notebook producing impossible results

[jonschull]

This may be an interaction with gevent and ipython notebook.

I'm getting bogus results from code that produces sensible results when run from the command line with ipython.

Here's the code

import string
import time 
def upcaser(s, duration):
    print
    print time.time(), s, 'UPCASER is beginning to ponder'
    gevent.sleep(duration) #CHANGED FROM TIME.SLEEP
    print time.time(), s, 'UPCASER ready to deliver after sleeping', duration, 'seconds'
    return string.upper(s)


import gevent

print time.time(), 'Starting!'
g1 = gevent.spawn(upcaser, 'First', 3)
g2 = gevent.spawn(upcaser, 'Second', 2)
print time.time(), 'gevent.sleep(0)'
gevent.sleep(0)
print time.time(), 'Checking for results', g1.value, g2.value
gevent.sleep(1)    #CHANGED FROM TIME.SLEEP
print time.time(), 'Checking for results', g1.value, g2.value
gevent.sleep(1)    #CHANGED FROM TIME.SLEEP
print time.time(), 'Checking for results', g1.value, g2.value
gevent.sleep(1)    #CHANGED FROM TIME.SLEEP
print time.time(), 'Checking for results', g1.value, g2.value

The results I'm expecting come from running ipython test.py

Jon-Schulls-MacBook-Pro-2:mypaintapp7 jonschull$ ipython test.py
1345088981.42 Starting!
1345088981.42 gevent.sleep(0)

1345088981.42 First UPCASER is beginning to ponder

1345088981.42 Second UPCASER is beginning to ponder
1345088981.42 Checking for results None None
1345088982.42 Checking for results None None
1345088983.42 Second UPCASER ready to deliver after sleeping 2 seconds
1345088983.42 Checking for results None SECOND
1345088984.42 First UPCASER ready to deliver after sleeping 3 seconds
1345088984.42 Checking for results FIRST SECOND

The results I get from shift-enter within ipython are:

1345089068.46 Starting!
1345089068.46 gevent.sleep(0)

1345089068.46 First UPCASER is beginning to ponder

1345089068.46 Second UPCASER is beginning to ponder
1345089068.46 Checking for results None None
1345089068.46 Second UPCASER ready to deliver after sleeping 2 seconds
1345089068.46 First UPCASER ready to deliver after sleeping 3 seconds
1345089069.46 Checking for results FIRST SECOND
1345089070.47 Checking for results FIRST SECOND
1345089071.47 Checking for results FIRST SECOND

Our two task are allegedly complete 1 second after we begin (and supposedly after at least 3 seconds of sleeping.)

Of course, I might be confused.

[minrk]

When I run this in notebook I get the expected output. Have you made any other gevent-related calls, or is this the only code that has been run in the process?

Also, what version of gevent are you using?

[jonschull]

Thanks for the quick follow up.

Indeed, if I restart the kernel the results make sense. But when I re-run
the last item, they go bad. I suspect gevent is not being recreated when I
create it anew.

gevent version info: (0, 13, 7)

please see attached

Jon Schull Jon.Schull@rit.edu cell: 585-738-6696
Dept. of Interactive Games and Media, and Center for Student Innovation, RIT
My free/busy info is
herehttps://www.google.com/calendar/b/0/embed?src=jschull@gmail.com&ctz=America/New_York.
For an appointment, make me an offer.

On Thu, Aug 16, 2012 at 1:14 PM, Min RK notifications@github.com wrote:

When I run this in notebook I get the expected output. Have you made any
other gevent-related calls, or is this the only code that has been run in
the process?

Also, what version of gevent are you using?

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/2309#issuecomment-7792284.

[minrk]

I can confirm that the second run encounters this issue with gevent-0.13, and does not with gevent 1.0-dev, so this is a gevent bug.

The issue seems to be that the gevent loop timer is still running in the background while IPython is sitting idle, so when you do spawn(...3), the sleep seems to wake itself 3 seconds after the previous gevent call, not 3 seconds after the call to gevent.sleep. A call to gevent.sleep(0) before the calls to gevent.spawn seems to workaround the issue.

I'm closing this, because I can reproduce this behavior exactly without IPython at all, and has even been fixed in gevent-dev.

please see attached

NB: GitHub comments do not support attachments.

[jonschull]

Thanks for your impressive, and impressively fast, analysis!

Sent from my iPhone 585-738-6696; pls excuse tyops

On Aug 17, 2012, at 7:05 PM, Min RK notifications@github.com wrote:

I can confirm that the second run encounters this issue with gevent-0.13,
and does not with gevent 1.0-dev, so this is a gevent bug.

The issue seems to be that the gevent loop timer is still running in the
background while IPython is sitting idle, so when you do spawn(...3), the
sleep seems to wake itself 3 seconds after the previous gevent call,
_not_3 seconds after the call to
gevent.sleep. A call to gevent.sleep(0) before the calls to
gevent.spawnseems to workaround the issue.

I'm closing this, because I can reproduce
https://gist.github.com/3383348this behavior exactly without IPython
at all, and has even been fixed in
gevent-dev.

please see attached

NB: GitHub comments do not support attachments.

—
Reply to this email directly or view it on
GitHubhttps://github.com//issues/2309#issuecomment-7837545.