Re: Queries getting canceled inside a proc that seems to slow down randomly - Mailing list pgsql-performance
| From | Skarsol |
|---|---|
| Subject | Re: Queries getting canceled inside a proc that seems to slow down randomly |
| Date | |
| Msg-id | CAMt8e=Gz-Ok=ZAt3+FOxv7ukA2JqkNmBhjm-ToiGXqjEov=+NA@mail.gmail.com Whole thread Raw |
| In response to | Re: Queries getting canceled inside a proc that seems to slow down randomly (Jim Nasby <Jim.Nasby@BlueTreble.com>) |
| Responses |
Re: Queries getting canceled inside a proc that seems to
slow down randomly
(Jim Nasby <Jim.Nasby@BlueTreble.com>)
|
| List | pgsql-performance |
On Fri, Nov 13, 2015 at 3:50 PM, Jim Nasby <Jim.Nasby@bluetreble.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)
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
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@127.0.0.1:6432 closing because: server idle timeout (age=612)
2016-01-11 12:21:46.600 32905 LOG S-0x17fd780: edi01/editor@127.0.0.1:6432 closing because: server idle timeout (age=612)
2016-01-11 12:23:28.142 32905 LOG S-0x17fd780: edi01/editor@127.0.0.1:6432 new connection to server
2016-01-11 12:23:28.143 32905 LOG S-0x17fd780: edi01/editor@127.0.0.1:6432 closing because: sent cancel req (age=0)
2016-01-11 12:26:31.510 32905 LOG S-0x17fd780: edi01/editor@127.0.0.1:6432 new connection to server
2016-01-11 12:23:28.143 32905 LOG S-0x17fd780: edi01/editor@127.0.0.1:6432 closing because: sent cancel req (age=0)
2016-01-11 12:26:31.510 32905 LOG S-0x17fd780: edi01/editor@127.0.0.1:6432 new connection to server
pgsql-performance by date: