-- Původní e-mail --
Od: David Turoň
Komu: Bruce Momjian
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,0,"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,0,"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,0,"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,0,"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,0,"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,0,"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,0,"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,0,"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,0,"disconnection: session time:
0:01:24.764 user=postgres database=postgres host=[local]","p
