public inbox for [email protected]help / color / mirror / Atom feed
auto_explain.log_min_duration is limit for nested statement 3+ messages / 3 participants [nested] [flat]
* auto_explain.log_min_duration is limit for nested statement @ 2019-11-04 07:11 PG Doc comments form <[email protected]> 0 siblings, 1 reply; 3+ messages in thread From: PG Doc comments form @ 2019-11-04 07:11 UTC (permalink / raw) To: [email protected]; +Cc: [email protected] The following documentation comment has been logged on the website: Page: https://www.postgresql.org/docs/12/auto-explain.html Description: Hello, I had problem with setup auto_explain.log_min_duration for COPY command on table with triggers. I set minimum duration to '2s' but no plan logged (duration of COPY command was above this limit). I thought that this extension not working with COPY command. After some testing I investigate that extension is working becouse duration limit is for nested statement (query in trigger) not for base statement (COPY) - it will be fine write somewere in documentation. Thanks ^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: auto_explain.log_min_duration is limit for nested statement @ 2019-11-07 03:42 Bruce Momjian <[email protected]> parent: PG Doc comments form <[email protected]> 0 siblings, 1 reply; 3+ messages in thread From: Bruce Momjian @ 2019-11-07 03:42 UTC (permalink / raw) To: [email protected]; [email protected] On Mon, Nov 4, 2019 at 07:11:48AM +0000, PG Doc comments form wrote: > The following documentation comment has been logged on the website: > > Page: https://www.postgresql.org/docs/12/auto-explain.html > Description: > > Hello, > > I had problem with setup auto_explain.log_min_duration for COPY command on > table with triggers. I set minimum duration to '2s' but no plan logged > (duration of COPY command was above this limit). I thought that this > extension not working with COPY command. After some testing I investigate > that extension is working becouse duration limit is for nested statement > (query in trigger) not for base statement (COPY) - it will be fine write > somewere in documentation. COPY doesn't go through the optimizer, so there is nothing to explain, e.g., test=> EXPLAIN COPY test FROM STDIN; ERROR: syntax error at or near "COPY" LINE 1: EXPLAIN COPY test FROM STDIN; ^ -- Bruce Momjian <[email protected]> http://momjian.us EnterpriseDB http://enterprisedb.com + As you are, so once was I. As I am, so you will be. + + Ancient Roman grave inscription + ^ permalink raw reply [nested|flat] 3+ messages in thread
* Fwd: Re: auto_explain.log_min_duration is limit for nested statement @ 2019-11-09 23:19 David Turoň <[email protected]> parent: Bruce Momjian <[email protected]> 0 siblings, 0 replies; 3+ messages in thread From: David Turoň @ 2019-11-09 23:19 UTC (permalink / raw) To: [email protected] ---------- Původní e-mail ---------- Od: David Turoň <[email protected]> Komu: Bruce Momjian <[email protected]> Datum: 8. 11. 2019 8:02:03 Předmět: Re: auto_explain.log_min_duration is limit for nested statement " Good morning, yes in case of table without triggers, but table with triggers like this: postgres=# CREATE TABLE t(a int); CREATE TABLE Time: 168.747 ms postgres=# postgres=# CREATE FUNCTION tr() RETURNS TRIGGER AS $$ BEGIN PERFORM pg_sleep (3); RETURN NEW; END; $$ LANGUAGE plpgsql; CREATE FUNCTION Time: 182.356 ms postgres=# postgres=# CREATE TRIGGER tr1 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); CREATE TRIGGER Time: 29.718 ms postgres=# CREATE TRIGGER tr2 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); CREATE TRIGGER Time: 210.136 ms postgres=# postgres=# INSERT INTO t VALUES(1); INSERT 0 1 Time: 6034.487 ms (00:06.034) postgres=# postgres=# \copy t TO /tmp/test.csv; COPY 1 Time: 0.494 ms postgres=# postgres=# LOAD 'auto_explain'; LOAD Time: 2.464 ms postgres=# SET auto_explain.log_min_duration = '5s'; SET Time: 0.205 ms postgres=# SET auto_explain.log_analyze = true; SET Time: 0.264 ms postgres=# SET auto_explain.log_buffers = true; SET Time: 0.181 ms postgres=# SET auto_explain.log_triggers = true; SET Time: 0.185 ms postgres=# SET auto_explain.log_nested_statements= true; SET Time: 0.187 ms postgres=# SET client_min_messages TO debug; SET Time: 0.155 ms postgres=# SET log_min_duration_statement = 0; LOG: duration: 0.103 ms statement: SET log_min_duration_statement = 0; SET Time: 0.771 ms postgres=# postgres=# \copy t FROM /tmp/test.csv; --statement duration 6s, but plan not logged, becouse nested statement duration tr1 is 3s and tr2 3s LOG: duration: 6022.433 ms statement: COPY t FROM STDIN ; --statement duration 6s, but plan not logged, becouse nested statement duration tr1 is 3 s and tr2 3s COPY 1 Time: 6022.862 ms (00:06.023) postgres=# postgres=# SET auto_explain.log_min_duration = '3s'; LOG: duration: 0.087 ms statement: SET auto_explain.log_min_duration = '3 s'; SET Time: 0.264 ms postgres=# postgres=# \copy t FROM /tmp/test.csv; --finnaly logged LOG: duration: 3003.234 ms plan: Query Text: SELECT pg_sleep(3) Result (cost=0.00..0.01 rows=1 width=4) (actual time=3003.219..3003.220 rows=1 loops=1) LOG: duration: 3003.129 ms plan: Query Text: SELECT pg_sleep(3) Result (cost=0.00..0.01 rows=1 width=4) (actual time=3003.119..3003.120 rows=1 loops=1) LOG: duration: 6027.909 ms statement: COPY t FROM STDIN ; --finnaly logged COPY 1 Time: 6028.267 ms (00:06.028) and in log is something like this: 2019-11-08 06:52:36.990 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 2,"authentication",2019-11-08 06:52:36 UTC,3/1,0,LOG,00000,"connection authorized: user=postgres database=postgres application_name= psql",,,,,,,,,"" 2019-11-08 06:52:51.302 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 3,"INSERT",2019-11-08 06:52:36 UTC,3/0,0,LOG,00000,"duration: 6034.112 ms statement: INSERT INTO t VALUES(1);",,,,,,,,,"psql" 2019-11-08 06:52:51.316 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 4,"SET",2019-11-08 06:52:36 UTC,3/0,0,LOG,00000,"duration: 0.103 ms statement: SET log_min_duration_statement = 0;",,,,,,,,,"psql" 2019-11-08 06:52:57.342 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 5,"COPY",2019-11-08 06:52:36 UTC,3/0,0,LOG,00000,"duration: 6022.433 ms statement: COPY t FROM STDIN ; --statement duration 6s, but plan not logged, becouse nested statement duration tr1 is 3s and tr2 3s",,,,,,,,," psql" 2019-11-08 06:52:57.344 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 6,"SET",2019-11-08 06:52:36 UTC,3/0,0,LOG,00000,"duration: 0.087 ms statement: SET auto_explain.log_min_duration = '3s';",,,,,,,,,"psql" 2019-11-08 06:53:00.349 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 7,"COPY",2019-11-08 06:52:36 UTC,3/18,494,LOG,00000,"duration: 3003.234 ms plan: Query Text: SELECT pg_sleep(3) Result (cost=0.00..0.01 rows=1 width=4) (actual time=3003.219..3003.220 rows=1 loops=1)",,,,,"SQL statement ""SELECT pg_sleep(3)"" PL/pgSQL function tr() line 1 at PERFORM",,,,"psql" 2019-11-08 06:53:03.352 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 8,"COPY",2019-11-08 06:52:36 UTC,3/18,494,LOG,00000,"duration: 3003.129 ms plan: Query Text: SELECT pg_sleep(3) Result (cost=0.00..0.01 rows=1 width=4) (actual time=3003.119..3003.120 rows=1 loops=1)",,,,,"SQL statement ""SELECT pg_sleep(3)"" PL/pgSQL function tr() line 1 at PERFORM",,,,"psql" 2019-11-08 06:53:03.373 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 9,"COPY",2019-11-08 06:52:36 UTC,3/0,0,LOG,00000,"duration: 6027.909 ms statement: COPY t FROM STDIN ; --finnaly logged",,,,,,,,,"psql" 2019-11-08 06:54:01.746 UTC,"postgres","postgres",62,"[local]",5dc510b4.3e, 10,"idle",2019-11-08 06:52:36 UTC,,0,LOG,00000,"disconnection: session time: 0:01:24.764 user=postgres database=postgres host=[local]",,,,,,,,,"psql" My problem was that plan of copy command with duration 6s was not logged, but when i set limit to 3s then second COPY was logged, becouse value auto_ explain.log_min_duration is probably for nested statement. Tested on PG12. Have nice day and thanks! Sorry for my bad english. David Turoň ---------- Původní e-mail ---------- Od: Bruce Momjian <[email protected]> Komu: [email protected], [email protected] Datum: 7. 11. 2019 4:45:03 Předmět: Re: auto_explain.log_min_duration is limit for nested statement "On Mon, Nov 4, 2019 at 07:11:48AM +0000, PG Doc comments form wrote: > The following documentation comment has been logged on the website: > > Page: https://www.postgresql.org/docs/12/auto-explain.html > Description: > > Hello, > > I had problem with setup auto_explain.log_min_duration for COPY command on > table with triggers. I set minimum duration to '2s' but no plan logged > (duration of COPY command was above this limit). I thought that this > extension not working with COPY command. After some testing I investigate > that extension is working becouse duration limit is for nested statement > (query in trigger) not for base statement (COPY) - it will be fine write > somewere in documentation. COPY doesn't go through the optimizer, so there is nothing to explain, e.g., test=> EXPLAIN COPY test FROM STDIN; ERROR: syntax error at or near "COPY" LINE 1: EXPLAIN COPY test FROM STDIN; ^ -- Bruce Momjian <[email protected]> http://momjian.us EnterpriseDB http://enterprisedb.com + As you are, so once was I. As I am, so you will be. + + Ancient Roman grave inscription + " " CREATE TABLE t(a int); CREATE FUNCTION tr() RETURNS TRIGGER AS $$ BEGIN PERFORM pg_sleep(3); RETURN NEW; END; $$ LANGUAGE plpgsql; CREATE TRIGGER tr1 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); CREATE TRIGGER tr2 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); INSERT INTO t VALUES(1); \copy t TO /tmp/test.csv; LOAD 'auto_explain'; SET auto_explain.log_min_duration = '5s'; SET auto_explain.log_analyze = true; SET auto_explain.log_buffers = true; SET auto_explain.log_triggers = true; SET auto_explain.log_nested_statements= true; SET client_min_messages TO debug; SET log_min_duration_statement = 0; \copy t FROM /tmp/test.csv; --statement duration 6s, but plan not logged, becouse nested statement duration tr1 is 3s and tr2 3s SET auto_explain.log_min_duration = '3s'; \copy t FROM /tmp/test.csv; --finnaly logged Attachments: [text/plain] test.sql (847B, 3-test.sql) download | inline: CREATE TABLE t(a int); CREATE FUNCTION tr() RETURNS TRIGGER AS $$ BEGIN PERFORM pg_sleep(3); RETURN NEW; END; $$ LANGUAGE plpgsql; CREATE TRIGGER tr1 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); CREATE TRIGGER tr2 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); INSERT INTO t VALUES(1); \copy t TO /tmp/test.csv; LOAD 'auto_explain'; SET auto_explain.log_min_duration = '5s'; SET auto_explain.log_analyze = true; SET auto_explain.log_buffers = true; SET auto_explain.log_triggers = true; SET auto_explain.log_nested_statements= true; SET client_min_messages TO debug; SET log_min_duration_statement = 0; \copy t FROM /tmp/test.csv; --statement duration 6s, but plan not logged, becouse nested statement duration tr1 is 3s and tr2 3s SET auto_explain.log_min_duration = '3s'; \copy t FROM /tmp/test.csv; --finnaly logged ^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2019-11-09 23:19 UTC | newest] Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2019-11-04 07:11 auto_explain.log_min_duration is limit for nested statement PG Doc comments form <[email protected]> 2019-11-07 03:42 ` Bruce Momjian <[email protected]> 2019-11-09 23:19 ` David Turoň <[email protected]>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox