Discussion:
statement_timeout doesn't work
Sergey Konoplev
2014-07-16 04:49:31 UTC
Permalink
Hi,

PostgreSQL 9.2.7, Linux 2.6.32

Several days ago I found one of my servers out of connections,
pg_stat_activity showed that everything was waiting for the DROP/ALTER
INDEX transaction (see the record 2 below), that, as I guess, was
waiting for the function call (record 1).

-[ RECORD 1 ]----------------------------------
ts_age | 00:07:15.52997
state | active
query_age | 00:07:15.529945
[...]
waiting | f
[...]
query | select foo(...)

-[ RECORD 2 ]----------------------------------
ts_age | 00:06:37.844036
state | active
query_age | 00:06:37.844036
[...]
waiting | t
[...]
query | BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX public.idx1;
ALTER INDEX public.idx2 RENAME TO idx1;
END;

The interesting thing is that the transaction sets local
statement_timeout to 1 second and its age was more than 6 minutes. The
foo() is a complex plpython function containing all the specter of mod
queries and using dblink(). I didn't manage to reproduce the problem
with a simple test.

psql -XAte <<EOF
\timing
CREATE LANGUAGE plpythonu;
CREATE TABLE test (t text);
CREATE INDEX test_idx ON test (t);
EOF
sleep 1
psql -XAte <<EOF &
\timing
CREATE OR REPLACE FUNCTION test_plpy()
RETURNS void LANGUAGE 'plpythonu' AS \$\$
import time
plpy.execute("INSERT INTO test VALUES ('a')")
plpy.execute("ALTER TABLE test ADD i integer")
plpy.execute("SELECT dblink_exec('dbname=grayhemp', 'DROP TABLE test')")
plpy.execute("SELECT * FROM dblink('', 'SELECT pg_sleep(3)') AS t (t text)")
\$\$;
SELECT test_plpy();
EOF
sleep 1
psql -XAte <<EOF
\timing
BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX test_idx;
END;
EOF

Any ideas why could it happen and what should I do to prevent this in future?
--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA

http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (499) 346-7196, +7 (988) 888-1979
***@gmail.com
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
Sergey Konoplev
2014-07-18 15:20:33 UTC
Permalink
No hope here?
Post by Sergey Konoplev
Hi,
PostgreSQL 9.2.7, Linux 2.6.32
Several days ago I found one of my servers out of connections,
pg_stat_activity showed that everything was waiting for the DROP/ALTER
INDEX transaction (see the record 2 below), that, as I guess, was
waiting for the function call (record 1).
-[ RECORD 1 ]----------------------------------
ts_age | 00:07:15.52997
state | active
query_age | 00:07:15.529945
[...]
waiting | f
[...]
query | select foo(...)
-[ RECORD 2 ]----------------------------------
ts_age | 00:06:37.844036
state | active
query_age | 00:06:37.844036
[...]
waiting | t
[...]
query | BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX public.idx1;
ALTER INDEX public.idx2 RENAME TO idx1;
END;
The interesting thing is that the transaction sets local
statement_timeout to 1 second and its age was more than 6 minutes. The
foo() is a complex plpython function containing all the specter of mod
queries and using dblink(). I didn't manage to reproduce the problem
with a simple test.
psql -XAte <<EOF
\timing
CREATE LANGUAGE plpythonu;
CREATE TABLE test (t text);
CREATE INDEX test_idx ON test (t);
EOF
sleep 1
psql -XAte <<EOF &
\timing
CREATE OR REPLACE FUNCTION test_plpy()
RETURNS void LANGUAGE 'plpythonu' AS \$\$
import time
plpy.execute("INSERT INTO test VALUES ('a')")
plpy.execute("ALTER TABLE test ADD i integer")
plpy.execute("SELECT dblink_exec('dbname=grayhemp', 'DROP TABLE test')")
plpy.execute("SELECT * FROM dblink('', 'SELECT pg_sleep(3)') AS t (t text)")
\$\$;
SELECT test_plpy();
EOF
sleep 1
psql -XAte <<EOF
\timing
BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX test_idx;
END;
EOF
Any ideas why could it happen and what should I do to prevent this in future?
--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA
http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (499) 346-7196, +7 (988) 888-1979
^^^
--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA

http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (499) 346-7196, +7 (988) 888-1979
***@gmail.com
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
David G Johnston
2014-07-19 01:15:55 UTC
Permalink
Post by Sergey Konoplev
Hi,
PostgreSQL 9.2.7, Linux 2.6.32
Several days ago I found one of my servers out of connections,
pg_stat_activity showed that everything was waiting for the DROP/ALTER
INDEX transaction (see the record 2 below), that, as I guess, was
waiting for the function call (record 1).
-[ RECORD 1 ]----------------------------------
ts_age | 00:07:15.52997
state | active
query_age | 00:07:15.529945
[...]
waiting | f
[...]
query | select foo(...)
-[ RECORD 2 ]----------------------------------
ts_age | 00:06:37.844036
state | active
query_age | 00:06:37.844036
[...]
waiting | t
[...]
query | BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX public.idx1;
ALTER INDEX public.idx2 RENAME TO idx1;
END;
The interesting thing is that the transaction sets local
statement_timeout to 1 second and its age was more than 6 minutes. The
foo() is a complex plpython function containing all the specter of mod
queries and using dblink(). I didn't manage to reproduce the problem
with a simple test.
If I read this correctly you sent the entire begin...end as a single
compound statement and so, depending on how you did this, the actual SET
LOCAL command never got executed since the entire command is waiting for the
necessary locks before it can be executed.

Your sample test doesn't appear to correctly exercise this behavior. Are
you maybe using -c in the problem case? Or a client library besides psql
that would behave in this manner?

Note that the fact that "query" is a compound statement is why I claim the
above...

David J.






--
View this message in context: http://postgresql.1045698.n5.nabble.com/statement-timeout-doesn-t-work-tp5811704p5812037.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
Sergey Konoplev
2014-07-21 14:59:01 UTC
Permalink
On Fri, Jul 18, 2014 at 6:15 PM, David G Johnston
Post by David G Johnston
Post by Sergey Konoplev
query | BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX public.idx1;
ALTER INDEX public.idx2 RENAME TO idx1;
END;
If I read this correctly you sent the entire begin...end as a single
compound statement and so, depending on how you did this, the actual SET
LOCAL command never got executed since the entire command is waiting for the
necessary locks before it can be executed.
Right, I send it as a single command.
Post by David G Johnston
Your sample test doesn't appear to correctly exercise this behavior. Are
you maybe using -c in the problem case? Or a client library besides psql
that would behave in this manner?
In this case I use DBD::Pg, but I haven't found any notes about such
kind of behavior.
Post by David G Johnston
Note that the fact that "query" is a compound statement is why I claim the
above...
So, If I separate the commands everything will will work as expected, correct?
Post by David G Johnston
David J.
--
View this message in context: http://postgresql.1045698.n5.nabble.com/statement-timeout-doesn-t-work-tp5811704p5812037.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.
--
http://www.postgresql.org/mailpref/pgsql-general
--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA

http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (499) 346-7196, +7 (988) 888-1979
***@gmail.com
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
David G Johnston
2014-07-21 17:16:19 UTC
Permalink
Post by Sergey Konoplev
On Fri, Jul 18, 2014 at 6:15 PM, David G Johnston
&lt;
Post by David G Johnston
Post by Sergey Konoplev
query | BEGIN;
SET LOCAL statement_timeout TO 1000;
DROP INDEX public.idx1;
ALTER INDEX public.idx2 RENAME TO idx1;
END;
If I read this correctly you sent the entire begin...end as a single
compound statement and so, depending on how you did this, the actual SET
LOCAL command never got executed since the entire command is waiting for the
necessary locks before it can be executed.
Right, I send it as a single command.
Post by David G Johnston
Your sample test doesn't appear to correctly exercise this behavior. Are
you maybe using -c in the problem case? Or a client library besides psql
that would behave in this manner?
In this case I use DBD::Pg, but I haven't found any notes about such
kind of behavior.
Post by David G Johnston
Note that the fact that "query" is a compound statement is why I claim the
above...
So, If I separate the commands everything will will work as expected, correct?
I would assume so.

If you wait to send the DROP/ALTER index commands until the SET LOCAL
command returns successfully then both of those commands will die if they
exceed the timeout specified.

Dave




--
View this message in context: http://postgresql.1045698.n5.nabble.com/statement-timeout-doesn-t-work-tp5811704p5812243.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
Sergey Konoplev
2014-07-21 18:32:06 UTC
Permalink
On Mon, Jul 21, 2014 at 10:16 AM, David G Johnston
Post by David G Johnston
Post by Sergey Konoplev
So, If I separate the commands everything will will work as expected, correct?
I would assume so.
If you wait to send the DROP/ALTER index commands until the SET LOCAL
command returns successfully then both of those commands will die if they
exceed the timeout specified.
Thank you. I'll try it.
--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA

http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (499) 346-7196, +7 (988) 888-1979
***@gmail.com
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
Sergey Konoplev
2014-07-30 05:27:25 UTC
Permalink
Post by Sergey Konoplev
On Mon, Jul 21, 2014 at 10:16 AM, David G Johnston
Post by David G Johnston
Post by Sergey Konoplev
So, If I separate the commands everything will will work as expected, correct?
I would assume so.
If you wait to send the DROP/ALTER index commands until the SET LOCAL
command returns successfully then both of those commands will die if they
exceed the timeout specified.
So, you were right, when I send the BEGIN/SET LOCAL/DROP/END as a
single command the statement timeout doesn't work.

Below is the test reproducing the problem.

psql -XAte <<EOF
\timing
CREATE DATABASE test;
\c test
CREATE LANGUAGE plpythonu;
EOF

psql -XAte test <<EOF
\timing
CREATE TABLE test (t text);
CREATE INDEX test_idx ON test (t);
EOF

sleep 1

psql -XAte test <<EOF &
\timing
BEGIN;
INSERT INTO test VALUES ('a');
SELECT pg_sleep(100);
END;
EOF

sleep 1

psql -XAte test -c "\
BEGIN;\
SET LOCAL statement_timeout TO 1000;\
DROP TABLE test;\
END;"

And at the separate console check the activity.

SELECT
pid, backend_start, xact_start, query_start, state_change,
waiting, state, query, now() - xact_start AS age
FROM pg_stat_activity
WHERE state <> 'idle' AND pid <> pg_backend_pid();

-[ RECORD 1 ]-+---------------------------------------------------------------
pid | 20071
backend_start | 2014-07-29 22:21:17.322722-07
xact_start | 2014-07-29 22:21:17.32666-07
query_start | 2014-07-29 22:21:17.328291-07
state_change | 2014-07-29 22:21:17.328293-07
waiting | f
state | active
query | SELECT pg_sleep(100);
age | 00:00:06.855373
-[ RECORD 2 ]-+---------------------------------------------------------------
pid | 20085
backend_start | 2014-07-29 22:21:18.330979-07
xact_start | 2014-07-29 22:21:18.332332-07
query_start | 2014-07-29 22:21:18.332332-07
state_change | 2014-07-29 22:21:18.332332-07
waiting | t
state | active
query | BEGIN;SET LOCAL statement_timeout TO 1000;DROP TABLE test;END;
age | 00:00:05.849701

The age of the compound statement is more than the specified statement timeout.
--
Kind regards,
Sergey Konoplev
PostgreSQL Consultant and DBA

http://www.linkedin.com/in/grayhemp
+1 (415) 867-9984, +7 (499) 346-7196, +7 (988) 888-1979
***@gmail.com
--
Sent via pgsql-general mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
Loading...