Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iTpml-0005Sz-Oc for pgsql-docs@arkaria.postgresql.org; Sun, 10 Nov 2019 16:09:56 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1iTpmk-0004v7-HT for pgsql-docs@arkaria.postgresql.org; Sun, 10 Nov 2019 16:09:54 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iTa1T-0002bx-N6 for pgsql-docs@lists.postgresql.org; Sat, 09 Nov 2019 23:20:03 +0000 Received: from mxc1.seznam.cz ([2a02:598:a::79:23]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iTa1Q-0007Nk-He for pgsql-docs@lists.postgresql.org; Sat, 09 Nov 2019 23:20:03 +0000 Received: from email.seznam.cz by email-smtpc8b.ko.seznam.cz (email-smtpc8b.ko.seznam.cz [10.53.13.225]) id 5eec2f72e4eb5d785efe24f4; Sun, 10 Nov 2019 00:19:58 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=seznam.cz; s=beta; t=1573341598; bh=smltboNT3w0bDBbIDQfIM3t1Ocy4w5IBlEgOeafxkq8=; h=Received:From:To:Subject:Date:Message-Id:References:Mime-Version: X-Mailer:Content-Type; b=GYWKGuD4/6ruxUZgiKnSLePkOHkJBoiUCB4f9FVfCqrSDg8zHoPeNS+an4c2deFd3 ovXjmmpaPdbp0RJJt7+00aboRa4qxPXxmGFprnyHtXl2ogfGYELM4zKJWzKzdtn8QA VS4qD4iUCtxzZ8Pg0AX80v3otJwaOk2XKLBDgBPI= Received: from unknown ([::ffff:78.108.156.47]) by email.seznam.cz (szn-ebox-4.5.377) with HTTP; Sun, 10 Nov 2019 00:19:52 +0100 (CET) From: =?utf-8?q?David_Turo=C5=88?= To: Subject: Fwd: Re: auto_explain.log_min_duration is limit for nested statement Date: Sun, 10 Nov 2019 00:19:52 +0100 (CET) Message-Id: <15j.5n49.7uJFCqMHXZr.1TnqcO@seznam.cz> References: <157285150885.14272.17400824163768264403@wrigleys.postgresql.org> <20191107034230.GC12478@momjian.us> Mime-Version: 1.0 (szn-mime-2.0.46) X-Mailer: szn-ebox-4.5.377 Content-Type: multipart/mixed; boundary="=_692e0ef6668f1f5030ef401c=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_=" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --=_692e0ef6668f1f5030ef401c=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_= Content-Type: multipart/alternative; boundary="=_410ac0c646045a190293a12e=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_=" --=_410ac0c646045a190293a12e=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_= Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable ---------- P=C5=AFvodn=C3=AD e-mail ---------- Od: David Turo=C5=88 Komu: Bruce Momjian Datum: 8. 11. 2019 8:02:03 P=C5=99edm=C4=9Bt: Re: auto_explain.log_min_duration is limit for nested s= tatement " Good morning, yes in case of table without triggers, but table with triggers like this:= postgres=3D# CREATE TABLE t(a int); CREATE TABLE Time: 168.747 ms postgres=3D#=C2=A0 postgres=3D# CREATE FUNCTION tr() RETURNS TRIGGER AS $$ BEGIN PERFORM pg_s= leep (3); RETURN NEW; END; $$ LANGUAGE plpgsql; CREATE FUNCTION Time: 182.356 ms postgres=3D#=C2=A0 postgres=3D# CREATE TRIGGER tr1 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); CREATE TRIGGER Time: 29.718 ms postgres=3D# CREATE TRIGGER tr2 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr(); CREATE TRIGGER Time: 210.136 ms postgres=3D#=C2=A0 postgres=3D# INSERT INTO t VALUES(1); INSERT 0 1 Time: 6034.487 ms (00:06.034) postgres=3D#=C2=A0 postgres=3D# \copy t TO /tmp/test.csv; COPY 1 Time: 0.494 ms postgres=3D#=C2=A0 postgres=3D# LOAD 'auto_explain'; LOAD Time: 2.464 ms postgres=3D# SET auto_explain.log_min_duration =3D '5s'; SET Time: 0.205 ms postgres=3D# SET auto_explain.log_analyze =3D true; SET Time: 0.264 ms postgres=3D# SET auto_explain.log_buffers =3D true; SET Time: 0.181 ms postgres=3D# SET auto_explain.log_triggers =3D true; SET Time: 0.185 ms postgres=3D# SET auto_explain.log_nested_statements=3D true; SET Time: 0.187 ms postgres=3D# SET client_min_messages TO debug; SET Time: 0.155 ms postgres=3D# SET log_min_duration_statement =3D 0; LOG:=C2=A0 duration: 0.103 ms=C2=A0 statement: SET log_min_duration_statem= ent =3D 0; SET Time: 0.771 ms postgres=3D#=C2=A0 postgres=3D# \copy t FROM /tmp/test.csv; --statement duration 6s, but plan= not logged, becouse nested statement duration tr1 is 3s and tr2 3s LOG:=C2=A0 duration: 6022.433 ms=C2=A0 statement: COPY=C2=A0 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=3D#=C2=A0 postgres=3D# SET auto_explain.log_min_duration =3D '3s'; LOG:=C2=A0 duration: 0.087 ms=C2=A0 statement: SET auto_explain.log_min_du= ration =3D '3 s'; SET Time: 0.264 ms postgres=3D#=C2=A0 postgres=3D# \copy t FROM /tmp/test.csv; --finnaly logged LOG:=C2=A0 duration: 3003.234 ms=C2=A0 plan: Query Text: SELECT pg_sleep(3) Result=C2=A0 (cost=3D0.00..0.01 rows=3D1 width=3D4) (actual time=3D3003.21= 9..3003.220 rows=3D1 loops=3D1) LOG:=C2=A0 duration: 3003.129 ms=C2=A0 plan: Query Text: SELECT pg_sleep(3) Result=C2=A0 (cost=3D0.00..0.01 rows=3D1 width=3D4) (actual time=3D3003.11= 9..3003.120 rows=3D1 loops=3D1) LOG:=C2=A0 duration: 6027.909 ms=C2=A0 statement: COPY=C2=A0 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=3Dpostgres database=3Dpostgres application_name=3D 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= =C2=A0 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=C2=A0 = statement: SET log_min_duration_statement =3D 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= =C2=A0 statement: COPY=C2=A0 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=C2=A0 = statement: SET auto_explain.log_min_duration =3D '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= =C2=A0 plan: Query Text: SELECT pg_sleep(3) Result=C2=A0 (cost=3D0.00..0.01 rows=3D1 width=3D4) (actual time=3D3003.21= 9..3003.220 rows=3D1 loops=3D1)",,,,,"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= =C2=A0 plan: Query Text: SELECT pg_sleep(3) Result=C2=A0 (cost=3D0.00..0.01 rows=3D1 width=3D4) (actual time=3D3003.11= 9..3003.120 rows=3D1 loops=3D1)",,,,,"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= =C2=A0 statement: COPY=C2=A0 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 tim= e: 0:01:24.764 user=3Dpostgres database=3Dpostgres host=3D[local]",,,,,,,,,"p= sql" 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= =C2=A0auto_ explain.log_min_duration=C2=A0is probably for nested statement. Tested on = PG12. Have nice day and thanks! Sorry for my bad english. David Turo=C5=88 ---------- P=C5=AFvodn=C3=AD e-mail ---------- Od: Bruce Momjian Komu: turon.david@seznam.cz, pgsql-docs@lists.postgresql.org Datum: 7. 11. 2019 4:45:03 P=C5=99edm=C4=9Bt: Re: auto_explain.log_min_duration is limit for nested s= tatement "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 investigat= e > 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=3D> EXPLAIN COPY test FROM STDIN; ERROR: syntax error at or near "COPY" LINE 1: EXPLAIN COPY test FROM STDIN; ^ -- Bruce Momjian 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 + " " --=_410ac0c646045a190293a12e=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_= Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable


Good morning,

yes in case of table without triggers, = but table with triggers like this:

postgres= =3D# CREATE TABLE t(a int);
CREATE TABLE
Time: 168.747= ms
postgres=3D# 
postgres=3D# CREATE FUNCTION tr= () RETURNS TRIGGER AS $$ BEGIN PERFORM pg_sleep(3); RETURN NEW; END; $$ LA= NGUAGE plpgsql;
CREATE FUNCTION
Time: 182.356 ms
=
postgres=3D# 
postgres=3D# CREATE TRIGGER tr1 AFTER IN= SERT ON t FOR EACH ROW EXECUTE PROCEDURE tr();
CREATE TRIGGER
Time: 29.718 ms
postgres=3D# CREATE TRIGGER tr2 AFTER IN= SERT ON t FOR EACH ROW EXECUTE PROCEDURE tr();
CREATE TRIGGER
Time: 210.136 ms
postgres=3D# 
postgres= =3D# INSERT INTO t VALUES(1);
INSERT 0 1
Time: 6034.48= 7 ms (00:06.034)
postgres=3D# 
postgres=3D# \copy= t TO /tmp/test.csv;
COPY 1
Time: 0.494 ms
p= ostgres=3D# 
postgres=3D# LOAD 'auto_explain';
LO= AD
Time: 2.464 ms
postgres=3D# SET auto_explain.log_mi= n_duration =3D '5s';
SET
Time: 0.205 ms
post= gres=3D# SET auto_explain.log_analyze =3D true;
SET
Ti= me: 0.264 ms
postgres=3D# SET auto_explain.log_buffers =3D true;=
SET
Time: 0.181 ms
postgres=3D# SET auto_ex= plain.log_triggers =3D true;
SET
Time: 0.185 ms
<= div>postgres=3D# SET auto_explain.log_nested_statements=3D true;
SET
Time: 0.187 ms
postgres=3D# SET client_min_messag= es TO debug;
SET
Time: 0.155 ms
postgres=3D#= SET log_min_duration_statement =3D 0;
LOG:  duration: 0.10= 3 ms  statement: SET log_min_duration_statement =3D 0;
SET<= /div>
Time: 0.771 ms
postgres=3D# 
postgres= =3D# \copy t FROM /tmp/test.csv; --statement duration 6s, but plan not log= ged, 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 durat= ion tr1 is 3s and tr2 3s
COPY 1
Time: 6022.862 ms (00:= 06.023)
postgres=3D# 
postgres=3D# SET auto_expla= in.log_min_duration =3D '3s';
LOG:  duration: 0.087 ms = ; statement: SET auto_explain.log_min_duration =3D '3s';
SET
Time: 0.264 ms
postgres=3D# 
postgres=3D# = \copy t FROM /tmp/test.csv; --finnaly logged
LOG:  duration= : 3003.234 ms  plan:
Query Text: SELECT pg_sleep(3)
Result  (cost=3D0.00..0.01 rows=3D1 width=3D4) (actual time=3D3003= .219..3003.220 rows=3D1 loops=3D1)
LOG:  duration: 3003.129= ms  plan:
Query Text: SELECT pg_sleep(3)
Result&= nbsp; (cost=3D0.00..0.01 rows=3D1 width=3D4) (actual time=3D3003.119..3003= .120 rows=3D1 loops=3D1)
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 au= thorized: user=3Dpostgres database=3Dpostgres application_name=3Dpsql",,,,= ,,,,,""
2019-11-08 06:52:51.302 UTC,"postgres","postgres",62,"[l= ocal]",5dc510b4.3e,3,"INSERT",2019-11-08 06:52:36 UTC,3/0,0,LOG,00000,"dur= ation: 6034.112 ms  statement: INSERT INTO t VALUES(1);",,,,,,,,,"psq= l"
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 =3D 0;",,,,,,,,,"p= sql"
2019-11-08 06:52:57.342 UTC,"postgres","postgres",62,"[loca= l]",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 durat= ion 6s, but plan not logged, becouse nested statement duration tr1 is 3s a= nd 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_d= uration =3D '3s';",,,,,,,,,"psql"
2019-11-08 06:53:00.349 UTC,"p= ostgres","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=3D0.00..0.01 rows=3D= 1 width=3D4) (actual time=3D3003.219..3003.220 rows=3D1 loops=3D1)",,,,,"S= QL 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,4= 94,LOG,00000,"duration: 3003.129 ms  plan:
Query Text: SELE= CT pg_sleep(3)
Result  (cost=3D0.00..0.01 rows=3D1 width=3D= 4) (actual time=3D3003.119..3003.120 rows=3D1 loops=3D1)",,,,,"SQL stateme= nt ""SELECT pg_sleep(3)""
PL/pgSQL function tr() line 1 at PERFO= RM",,,,"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 ; --finnal= y 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,L= OG,00000,"disconnection: session time: 0:01:24.764 user=3Dpostgres databas= e=3Dpostgres host=3D[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&nbs= p;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=C5=88


On Mon, Nov 4, 20= 19 at 07:11:48AM +0000, PG Doc comments form wrote:=0A=
> The following documentation comment has been logged on the websit= e:=0A=
> =0A=
> Page: https://www.postgresql.org/docs/12/auto-explain.html=0A=
> Description:=0A=
> =0A=
> Hello,=0A=
> =0A=
> I had problem with setup auto_explain.log_min_duration for COPY c= ommand on=0A=
> table with triggers. I set minimum duration to '2s' but no plan l= ogged=0A=
> (duration of COPY command was above this limit). I thought that t= his=0A=
> extension not working with COPY command. After some testing I inv= estigate=0A=
> that extension is working becouse duration limit is for nested st= atement=0A=
> (query in trigger) not for base statement (COPY) - it will be fin= e write=0A=
> somewere in documentation.=0A=
=0A=
COPY doesn't go through the optimizer, so there is nothing to explain,= =0A=
e.g.,=0A=
=0A=
test=3D> EXPLAIN COPY test FROM STDIN;=0A=
ERROR: syntax error at or near "COPY"=0A=
LINE 1: EXPLAIN COPY test FROM STDIN;=0A=
^=0A=
=0A=
-- =0A=
Bruce Momjian <bruce@momjian.us> http://momjian.us= =0A=
EnterpriseDB http://enterprisedb.com= =0A=
=0A=
+ As you are, so once was I. As I am, so you will be. +=0A=
+ Ancient Roman grave inscription +=0A=
--=_410ac0c646045a190293a12e=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_=-- --=_692e0ef6668f1f5030ef401c=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_= Content-Type: text/plain; charset=us-ascii; name=test.sql Content-Transfer-Encoding: quoted-printable Content-Disposition: attachment; size=847; filename=test.sql =0A= =0A= CREATE TABLE t(a int);=0A= =0A= CREATE FUNCTION tr() RETURNS TRIGGER AS $$ BEGIN PERFORM pg_sleep(3); RETU= RN NEW; END; $$ LANGUAGE plpgsql;=0A= =0A= CREATE TRIGGER tr1 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr();= =0A= CREATE TRIGGER tr2 AFTER INSERT ON t FOR EACH ROW EXECUTE PROCEDURE tr();= =0A= =0A= INSERT INTO t VALUES(1);=0A= =0A= \copy t TO /tmp/test.csv;=0A= =0A= LOAD 'auto_explain';=0A= SET auto_explain.log_min_duration =3D '5s';=0A= SET auto_explain.log_analyze =3D true;=0A= SET auto_explain.log_buffers =3D true;=0A= SET auto_explain.log_triggers =3D true;=0A= SET auto_explain.log_nested_statements=3D true;=0A= SET client_min_messages TO debug;=0A= SET log_min_duration_statement =3D 0;=0A= =0A= \copy t FROM /tmp/test.csv; --statement duration 6s, but plan not logged, = becouse nested statement duration tr1 is 3s and tr2 3s=0A= =0A= SET auto_explain.log_min_duration =3D '3s';=0A= =0A= \copy t FROM /tmp/test.csv; --finnaly logged=0A= --=_692e0ef6668f1f5030ef401c=963bf9b8-91b8-5fa5-b0df-8c6c1586d0c4_=--