Обсуждение: statement_timeout doesn't work
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
gray.ru@gmail.com
No hope here?
On Tue, Jul 15, 2014 at 9:49 PM, Sergey Konoplev <gray.ru@gmail.com> wrote:
> 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
> gray.ru@gmail.com
^^^
--
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
gray.ru@gmail.com
Sergey Konoplev-2 wrote > 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.
On Fri, Jul 18, 2014 at 6:15 PM, David G Johnston <david.g.johnston@gmail.com> wrote: >> 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. > 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. > 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? > > 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-general@postgresql.org) > To make changes to your subscription: > 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 gray.ru@gmail.com
Sergey Konoplev-2 wrote > On Fri, Jul 18, 2014 at 6:15 PM, David G Johnston > < > david.g.johnston@ > > wrote: >>> 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. > >> 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. > >> 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.
On Mon, Jul 21, 2014 at 10:16 AM, David G Johnston <david.g.johnston@gmail.com> wrote: >> 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 gray.ru@gmail.com
On Mon, Jul 21, 2014 at 11:32 AM, Sergey Konoplev <gray.ru@gmail.com> wrote:
> On Mon, Jul 21, 2014 at 10:16 AM, David G Johnston
> <david.g.johnston@gmail.com> wrote:
>>> 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
gray.ru@gmail.com