Re: Async queries pretending to be synchronous

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.

>
> So, any idea why it's blocking, before I spend more time digging in?
>
> Thanks!
>
> --
> Dave Page
> Blog: http://pgsnake.blogspot.com
> Twitter: @pgsnake
>
> EnterpriseDB UK: http://www.enterprisedb.com
> The Enterprise PostgreSQL Company
>