auto_explain.log_min_duration is limit for nested statement

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

auto_explain.log_min_duration is limit for nested statement

PG Bug reporting form
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
Reply | Threaded
Open this post in threaded view
|

Re: auto_explain.log_min_duration is limit for nested statement

Bruce Momjian
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  <[hidden email]>        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 +


Reply | Threaded
Open this post in threaded view
|

Fwd: Re: auto_explain.log_min_duration is limit for nested statement

turon.david



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 3s 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 = '3s';
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ň


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 <[hidden email]> 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 +

test.sql (1008 bytes) Download Attachment