Re: Async queries pretending to be synchronous

On Tue, Mar 5, 2019 at 10:13 PM Dave Page <dpage(at)pgadmin(dot)org> wrote:

>
>
> On Tue, Mar 5, 2019 at 6:36 AM Khushboo Vashi <
> khushboo(dot)vashi(at)enterprisedb(dot)com> wrote:
>
>>
>>
>> On Mon, Mar 4, 2019 at 4:05 PM Khushboo Vashi <
>> khushboo(dot)vashi(at)enterprisedb(dot)com> wrote:
>>
>>>
>>>
>>> On Mon, Mar 4, 2019 at 4:00 PM Dave Page <dpage(at)pgadmin(dot)org> wrote:
>>>
>>>>
>>>>
>>>> On Mon, Mar 4, 2019 at 10:18 AM Khushboo Vashi <
>>>> khushboo(dot)vashi(at)enterprisedb(dot)com> wrote:
>>>>
>>>>>
>>>>>
>>>>> On Mon, Mar 4, 2019 at 3:43 PM Dave Page <dpage(at)pgadmin(dot)org> wrote:
>>>>>
>>>>>> Hi
>>>>>>
>>>>>> On Mon, Mar 4, 2019 at 5:43 AM Khushboo Vashi <
>>>>>> khushboo(dot)vashi(at)enterprisedb(dot)com> wrote:
>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Fri, Mar 1, 2019 at 10:01 PM Dave Page <dpage(at)pgadmin(dot)org> wrote:
>>>>>>>
>>>>>>>> In investigating #3656 I found the initial problem to be that when
>>>>>>>> running in a container, Gunicorn will kill the worker process if a thread
>>>>>>>> doesn't respond for 30 seconds by default. I fixed that by making the
>>>>>>>> timeout match the application session timeout, but it revealed another
>>>>>>>> issue.
>>>>>>>>
>>>>>>>> Given the function below (from the ticket), if you open the query
>>>>>>>> tool and run:
>>>>>>>>
>>>>>>>> SELECT 1; SELECT fails_after(30);
>>>>>>>>
>>>>>>>> the async query actually blocks for 30 seconds in the cur.execute()
>>>>>>>> call in execute_async() in connection.py (line 968). This causes the entire
>>>>>>>> app to hang (watch the dashboard requests pile up in pending state in the
>>>>>>>> network tab of the browser dev tools).
>>>>>>>>
>>>>>>>> If you run just the second SELECT, it works as expected, as does
>>>>>>>> running something like:
>>>>>>>>
>>>>>>>> SELECT 1; SELECT pg_sleep(30);
>>>>>>>>
>>>>>>>> Anyone have any idea what's going on?
>>>>>>>>
>>>>>>>
>>>>>>> Connection.poll() blocking the call here. ( connection.py - _wait_timeout
>>>>>>> function line #1378 state = conn.poll() )
>>>>>>> In the asynchronous connection, after executing the query, the
>>>>>>> conn.poll() is being called to fetch the connection status.
>>>>>>> It gives the status accordingly but in this case, it is blocking and
>>>>>>> not giving the status.
>>>>>>>
>>>>>>
>>>>>> If I put a breakpoint on the _wait_timeout call (line 969 in
>>>>>> execute_async), it hits it *after* the 30 seconds has passed (during which
>>>>>> time all other queries for cancel or dashboards and status etc don't get
>>>>>> processed).
>>>>>>
>>>>>> Put the breakpoint in the _wait_timeout function itself. The line no
>>>>> 1378 (state = conn.poll()) is blocking the execution 30 seconds.
>>>>>
>>>>>> If I walk down the call stack, it returns from the _cursor.execute
>>>>>> call in cursor.py and then hangs right before it goes into _wait_timeout.
>>>>>>
>>>>>
>>>> Hmm, yeah - my debugger is doing some weird off-by-one thing. If I put
>>>> the break point on the while 1, it blocks there! If I put it on the poll()
>>>> call, then it does do as you describe.
>>>>
>>> It's a psycopg2 call, it should return the specific status but it
>>> doesn't, so right now I am digging the Psycopg2 code.
>>>
>>
>> If I remove RAISE statements and then execute SELECT 1; SELECT
>> fails_after(30); it works as expected.
>>
>> As per the documentation, (Ref:
>> http://initd.org/psycopg/docs/connection.html)
>> Connection.poll returns one of the constants defined in Poll constants
>> <http://initd.org/psycopg/docs/extensions.html#poll-constants>. If it
>> returns POLL_OK
>> <http://initd.org/psycopg/docs/extensions.html#psycopg2.extensions.POLL_OK> then
>> the connection has been established or the query results are available on
>> the client. Otherwise wait until the file descriptor returned by fileno()
>> <http://initd.org/psycopg/docs/connection.html#connection.fileno> is
>> ready to read or to write.
>>
>> So, in case of Raise no file descriptor to read or write, and so before
>> raising the notice, It will block the connection till the pg_sleep
>> completes.
>>
>
> Thanks - confirmed, and created a test case for a bug report:
> https://github.com/psycopg/psycopg2/issues/856
>
>
This issue has been resolved in psycopg2 v2.8.
@Dave, can you please move it to *in testing* as I couldn't.

> --
> Dave Page
> Blog: http://pgsnake.blogspot.com
> Twitter: @pgsnake
>
> EnterpriseDB UK: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company
>