Re: Queries getting canceled inside a proc that seems to slow down randomly

On Fri, Nov 13, 2015 at 3:50 PM, Jim Nasby <Jim(dot)Nasby(at)bluetreble(dot)com> wrote:

> On 11/11/15 11:57 AM, Skarsol wrote:
>
>> Are we doing anything weird with this procedure? Is there anything more
>> I can do to get more info as to why/how the cancellation is happening or
>> why the function would slow down seemingly randomly?
>>
>> ERROR: canceling statement due to user request
>> CONTEXT: PL/pgSQL function chooselast(character varying,character
>> varying) line 1 at IF
>> SQL statement "INSERT INTO partition_2015 VALUES (NEW.*)"
>> PL/pgSQL function table1_insert_trigger() line 4 at SQL statement
>> STATEMENT: INSERT into table1 (create_time,cusid,last1) Values
>> ('NOW','8175','ROBERT'')
>>
>
> The error tells you what's causing this; it's a client-side interrupt.
> Actually, looking at the code, you might get the same request if someone
> sent a signal to the relevant backend, either at the OS level or via
> pg_cancel_backend(). You can test that and see what error you get. A
> statement_timeout expiration would give you a different error.
>
> As for the hang, maybe someone is ALTERing or replacing the function?
>
> BTW, you could write that function in the SQL language, which might allow
> the optimizer to inline it. Even if it couldn't, you'd probably still see a
> performance gain from not firing up plpgsql on every row. Though, if you
> didn't allow empty strings in last1, you could also just replace that whole
> function with coalesce(). I see the function is marked IMMUTABLE, which is
> good.
> --
> Jim Nasby, Data Architect, Blue Treble Consulting, Austin TX
> Experts in Analytics, Data Architecture and PostgreSQL
> Data in Trouble? Get it in Treble! http://BlueTreble.com
>

No one is ALTERing or replacing the function (I'm the only person that
would). Recently we had an automated process attempted to load a file
containing one record (which usually takes under a second) and it failed
because of this issue (the insert was cancelled due to user request at the
IF in the chooselast function).

Similarly, but unrelated to the functions, we had a PHP script running as a
headless daemon process get this error (ERROR: canceling statement due to
user request) while running 'SELECT * FROM connection WHERE id=109'.
Everyone was at lunch, so there's no way a user could have cancelled it.
These scripts run for months at a time with no issues, so it's not timeout
related. It's not a long running or complicated query:

QUERY PLAN
-----------------------------------------------------------------------------------------------------
Seq Scan on connection (cost=0.00..7.83 rows=1 width=60) (actual
time=0.031..0.033 rows=1 loops=1)
Filter: (id = 109)
Rows Removed by Filter: 306
Total runtime: 0.047 ms
(4 rows)

This is going through pgbouncer and the related log entries are:

postgres:
5018 2016-01-11 12:23:28.143 CST:ERROR: canceling statement due to user
request
5018 2016-01-11 12:23:28.143 CST:STATEMENT: SELECT * FROM connection WHERE
id=109

pgbouncer (S-0x17fd780 entries):
2016-01-11 12:21:46.600 32905 LOG S-0x17fd780: edi01/editor(at)127(dot)0(dot)0(dot)1:6432
closing because: server idle timeout (age=612)
2016-01-11 12:23:28.142 32905 LOG S-0x17fd780: edi01/editor(at)127(dot)0(dot)0(dot)1:6432
new connection to server
2016-01-11 12:23:28.143 32905 LOG S-0x17fd780: edi01/editor(at)127(dot)0(dot)0(dot)1:6432
closing because: sent cancel req (age=0)
2016-01-11 12:26:31.510 32905 LOG S-0x17fd780: edi01/editor(at)127(dot)0(dot)0(dot)1:6432
new connection to server