Fwd: [BUG] Print timing statistics of trigger execution under turned off timing option of EXPLAIN ANALYZE

Started by maksimover 9 years ago2 messages
#1maksim
m.milyutin@postgrespro.ru
1 attachment(s)

Hello, hackers!

At this moment EXPLAIN ANALYZE with turned off timing option after
execution query that expires trigger prints time of total execution of
trigger function:

postgres=# EXPLAIN (ANALYZE, timing false) insert INTO foo
values(1000001, '');
QUERY PLAN
--------------------------------------------------------------------------
Insert on foo (cost=0.00..0.01 rows=1 width=36) (actual rows=0 loops=1)
-> Result (cost=0.00..0.01 rows=1 width=36) (actual rows=1 loops=1)
Planning time: 0.038 ms
Trigger unique_foo_c1:*/time=0.000/* calls=1
Execution time: 340.766 ms
(5 rows)

My patch fixes this problem.

--
Maksim Milyutin
Postgres Professional:http://www.postgrespro.com
Russian Postgres Company

Attachments:

trigger_timing.patchtext/x-patch; name=trigger_timing.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index dbd27e5..808e23e 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -698,8 +698,11 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
 				appendStringInfo(es->str, " for constraint %s", conname);
 			if (show_relname)
 				appendStringInfo(es->str, " on %s", relname);
-			appendStringInfo(es->str, ": time=%.3f calls=%.0f\n",
-							 1000.0 * instr->total, instr->ntuples);
+			if (es->timing)
+				appendStringInfo(es->str, ": time=%.3f calls=%.0f\n",
+								 1000.0 * instr->total, instr->ntuples);
+			else
+				appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples);
 		}
 		else
 		{
@@ -707,7 +710,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
 			if (conname)
 				ExplainPropertyText("Constraint Name", conname, es);
 			ExplainPropertyText("Relation", relname, es);
-			ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es);
+			if (es->timing)
+				ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es);
 			ExplainPropertyFloat("Calls", instr->ntuples, 0, es);
 		}
 
#2Tom Lane
tgl@sss.pgh.pa.us
In reply to: maksim (#1)
Re: Fwd: [BUG] Print timing statistics of trigger execution under turned off timing option of EXPLAIN ANALYZE

maksim <m.milyutin@postgrespro.ru> writes:

postgres=# EXPLAIN (ANALYZE, timing false) insert INTO foo
values(1000001, '');
QUERY PLAN
--------------------------------------------------------------------------
Insert on foo (cost=0.00..0.01 rows=1 width=36) (actual rows=0 loops=1)
-> Result (cost=0.00..0.01 rows=1 width=36) (actual rows=1 loops=1)
Planning time: 0.038 ms
Trigger unique_foo_c1:*/time=0.000/* calls=1
Execution time: 340.766 ms
(5 rows)

Hmm, yeah, it shouldn't do that.

My patch fixes this problem.

Will push, thanks.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers