gevent exceptions are ignored while blocking on queries

Issue #1 new
David Wolever created an issue

Gevent exceptions — like Timeout — appear to be ignored while a query is active.

Example follows.

Note that a Timeout should be raised after 2 second, but instead it is raised after 5 seconds, and the main thread is blocked (even to ^C) after 2 seconds:

$ python test.py
ping: 0.5
ping: 1.0
ping: 1.5
================================================================================
ELAPSED: 5.0
================================================================================
Traceback (most recent call last):
    …
gevent.timeout.Timeout: 2 seconds

test.py:

import time

from gevent import monkey
monkey.patch_all(subprocess=True)

from psycogreen.gevent import patch_psycopg
patch_psycopg()

import psycopg2

import gevent

start = time.time()

def spinner():
    while True:
        gevent.sleep(0.5)
        print "ping: %0.01f" %(time.time() - start)

try:
    gevent.spawn(spinner)
    gevent.Timeout(2).start()
    cxn = psycopg2.connect("host=localhost")
    cur = cxn.cursor()
    cur.execute("select pg_sleep(5)")
finally:
    print "=" * 80
    print "ELAPSED: %0.01f" %(time.time() - start)
    print "=" * 80

Tested on OS X 10.8.4 and Linux + epoll.

Comments (7)

  1. David Wolever reporter

    I've tested and confirmed that this happens on Linux too.

    Running under strace it seems like the root cause is that, after the exception is raised, something calls poll() instead of epoll.

    Line A, below, shows where epoll is correctly used to wait on the Postgres socket (fd=5), and line B shows the call to poll after the exception is raised. Note that, in this case, Timeout(5) and pg_sleep(10) are used.

       21:08:31 recvfrom(5, "C\0\0\0\nBEGIN\0C\0\0\0\10SET\0Z\0\0\0\5T", 16384, 0, NULL, NULL) = 26
       21:08:31 sendto(5, "Q\0\0\0\30select pg_sleep(10)\0", 25, MSG_NOSIGNAL, NULL, 0) = 25
       21:08:31 epoll_ctl(3, EPOLL_CTL_ADD, 5, {EPOLLIN, {u32=5, u64=21474836485}}) = -1 EEXIST (File exists)
       21:08:31 clock_gettime(CLOCK_MONOTONIC, {179866, 55234130}) = 0
    A: 21:08:31 epoll_wait(3, {}, 64, 4979)    = 0
       21:08:36 clock_gettime(CLOCK_MONOTONIC, {179871, 39352128}) = 0
       21:08:36 gettimeofday({1427332116, 435776}, NULL) = 0
    B: 21:08:36 poll([{fd=5, events=POLLIN|POLLERR}], 1, -1) = 1 ([{fd=5, revents=POLLIN}])
       21:08:41 recvfrom(5, "T\0\0\0!\0\1pg_sleep\0\0\0\0\0\0\0\0\0\10\346\0\4\377\377\377\377"..., 16384, 0, NULL, NULL) = 65
       21:08:41 fstat(1, {st_mode=S_IFREG|0664, st_size=443149, ...}) = 0
       21:08:41 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd4aef1b000
       21:08:41 gettimeofday({1427332121, 454229}, NULL) = 0
    
  2. Daniele Varrazzo repo owner

    I'd wait for an answer from gevent guys. I may be wrong but it seems mostly gevent related as the entire point of psycogreen is to return the control to the events loop while the server is busy doing his thing.

  3. Log in to comment