Hello!
Recently I got few times into situation where I was trying to find out what
is blocking DELETE queries. Running EXPLAIN (even VERBOSE one) wasn't
useful, since the reason was slow trigger (missing index on foreign key
column). I had to create testing entry and run EXPLAIN ANALYZE DELETE to
get this information.
It will be really valuable for me to show triggers in EXPLAIN query since
it will make clear for me there will be any trigger "activated" during
execution of DELETE query and that can be the reason for slow DELETE.
I have seen initial discussion at
https://www.postgresql.org/message-id/flat/20693.1111732761%40sss.pgh.pa.us
to show time spent in triggers in EXPLAIN ANALYZE including quick
discussion to possibly show triggers during EXPLAIN. Anyway since it
doesn't show any additional cost and just inform about the possibilities, I
still consider this feature useful. This is probably implementation of idea
mentioned at
https://www.postgresql.org/message-id/21221.1111736869%40sss.pgh.pa.us by
Tom Lane.
After initial discussion with Pavel Stěhule and Tomáš Vondra at czech
postgresql maillist (
https://groups.google.com/forum/#!topic/postgresql-cz/Dq1sT7huVho) I was
able to prepare initial version of this patch. I have added EXPLAIN option
called TRIGGERS enabled by default.There's already autoexplain property for
this. I understand it is not possible to show only triggers which will be
really activated unless query is really executed. EXPLAIN ANALYZE remains
untouched with this patch.
- patch with examples can be found at
https://github.com/simi/postgres/pull/2
- DIFF format https://github.com/simi/postgres/pull/2.diff
- PATCH format (also attached) https://github.com/simi/postgres/pull/2.patch
All regression tests passed with this change locally on latest git master.
I would like to cover this patch with more regression tests, but I wasn't
sure where to place them, since there's no "EXPLAIN" related test "group".
Is "src/test/regress/sql/triggers.sql" the best place to add tests related
to this change?
PS: This is my first try to contribute to postgresql codebase. The quality
of patch is probably not the best, but I will be more than happy to do any
requested change if needed.
Regards,
Josef Šimánek
From 18578e3d07aa159631e0903abae496a6482fa279 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Josef=20=C5=A0im=C3=A1nek?= <josef.sima...@gmail.com>
Date: Sat, 27 Jul 2019 09:27:41 +0200
Subject: [PATCH] Show possible triggers in EXPLAIN.
---
doc/src/sgml/ref/explain.sgml | 9 ++++
src/backend/commands/explain.c | 43 +++++++++++++++----
src/include/commands/explain.h | 1 +
src/test/regress/expected/foreign_key.out | 6 ++-
src/test/regress/expected/insert_conflict.out | 4 +-
src/test/regress/expected/updatable_views.out | 10 ++++-
6 files changed, 60 insertions(+), 13 deletions(-)
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 385d10411fa0..ba0d8df88c19 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -43,6 +43,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac
BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
TIMING [ <replaceable class="parameter">boolean</replaceable> ]
SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
+ TRIGGERS [ <replaceable class="parameter">boolean</replaceable> ]
FORMAT { TEXT | XML | JSON | YAML }
</synopsis>
</refsynopsisdiv>
@@ -224,6 +225,14 @@ ROLLBACK;
</listitem>
</varlistentry>
+ <varlistentry>
+ <term><literal>TRIGGERS</literal></term>
+ <listitem>
+ <para>
+ TODO
+ </para>
+ </listitem>
+ </varlistentry>
<varlistentry>
<term><literal>FORMAT</literal></term>
<listitem>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 62fb3434a32f..93845bcaad36 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -149,6 +149,7 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, const char *queryString,
ListCell *lc;
bool timing_set = false;
bool summary_set = false;
+ bool triggers_set = false;
/* Parse options list. */
foreach(lc, stmt->options)
@@ -175,6 +176,11 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, const char *queryString,
summary_set = true;
es->summary = defGetBoolean(opt);
}
+ else if (strcmp(opt->defname, "triggers") == 0)
+ {
+ triggers_set = true;
+ es->triggers = defGetBoolean(opt);
+ }
else if (strcmp(opt->defname, "format") == 0)
{
char *p = defGetString(opt);
@@ -210,6 +216,9 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, const char *queryString,
/* if the timing was not set explicitly, set default value */
es->timing = (timing_set) ? es->timing : es->analyze;
+ /* if the triggers was not set explicitly, set default value */
+ es->triggers = (triggers_set) ? es->triggers : true;
+
/* check that timing is used with EXPLAIN ANALYZE */
if (es->timing && !es->analyze)
ereport(ERROR,
@@ -556,7 +565,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
}
/* Print info about runtime of triggers */
- if (es->analyze)
+ if (es->triggers)
ExplainPrintTriggers(es, queryDesc);
/*
@@ -911,17 +920,23 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
{
int nt;
- if (!rInfo->ri_TrigDesc || !rInfo->ri_TrigInstrument)
+ if (!rInfo->ri_TrigDesc || (es->analyze && !rInfo->ri_TrigInstrument))
return;
for (nt = 0; nt < rInfo->ri_TrigDesc->numtriggers; nt++)
{
Trigger *trig = rInfo->ri_TrigDesc->triggers + nt;
- Instrumentation *instr = rInfo->ri_TrigInstrument + nt;
+ Instrumentation *instr;
char *relname;
char *conname = NULL;
/* Must clean up instrumentation state */
- InstrEndLoop(instr);
+ if (es->analyze) {
+ instr = rInfo->ri_TrigInstrument + nt;
+ InstrEndLoop(instr);
+
+ if (instr->ntuples == 0)
+ continue;
+ }
/*
* We ignore triggers that were never invoked; they likely aren't
@@ -951,11 +966,15 @@ 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);
- if (es->timing)
- appendStringInfo(es->str, ": time=%.3f calls=%.0f\n",
- 1000.0 * instr->total, instr->ntuples);
+ if (es->analyze)
+ {
+ if (es->timing)
+ appendStringInfo(es->str, ": time=%.3f calls=%.0f",
+ 1000.0 * instr->total, instr->ntuples);
else
- appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples);
+ appendStringInfo(es->str, ": calls=%.0f", instr->ntuples);
+ }
+ appendStringInfoString(es->str, "\n");
}
else
{
@@ -966,7 +985,13 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
if (es->timing)
ExplainPropertyFloat("Time", "ms", 1000.0 * instr->total, 3,
es);
- ExplainPropertyFloat("Calls", NULL, instr->ntuples, 0, es);
+ if (es->analyze)
+ {
+ if (es->timing)
+ ExplainPropertyFloat("Time", "ms", 1000.0 * instr->total, 3,
+ es);
+ ExplainPropertyFloat("Calls", NULL, instr->ntuples, 0, es);
+ }
}
if (conname)
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 8639891c1643..7c67e4745b00 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -35,6 +35,7 @@ typedef struct ExplainState
bool buffers; /* print buffer usage */
bool timing; /* print detailed node timing */
bool summary; /* print total planning and execution timing */
+ bool triggers; /* print triggers */
bool settings; /* print modified settings */
ExplainFormat format; /* output format */
/* state for output formatting --- not reset for each new plan tree */
diff --git a/src/test/regress/expected/foreign_key.out b/src/test/regress/expected/foreign_key.out
index 894084f94f14..2eb68575de39 100644
--- a/src/test/regress/expected/foreign_key.out
+++ b/src/test/regress/expected/foreign_key.out
@@ -1421,11 +1421,15 @@ explain (costs off) delete from t1 where a = 1;
Index Cond: (a = 1)
-> Seq Scan on t2
Filter: (b = 1)
+ Trigger for constraint t2_b_fkey
+ Trigger for constraint t2_b_fkey
Delete on t1
-> Index Scan using t1_pkey on t1
Index Cond: (a = 1)
-(10 rows)
+ Trigger for constraint t2_b_fkey
+ Trigger for constraint t2_b_fkey
+(14 rows)
delete from t1 where a = 1;
-- Test a primary key with attributes located in later attnum positions
diff --git a/src/test/regress/expected/insert_conflict.out b/src/test/regress/expected/insert_conflict.out
index 1338b2b23e17..94a0fefc3a41 100644
--- a/src/test/regress/expected/insert_conflict.out
+++ b/src/test/regress/expected/insert_conflict.out
@@ -218,7 +218,9 @@ explain (costs off, format json) insert into insertconflicttest values (0, 'Bilb
"Parallel Aware": false +
} +
] +
- } +
+ }, +
+ "Triggers": [ +
+ ] +
} +
]
(1 row)
diff --git a/src/test/regress/expected/updatable_views.out b/src/test/regress/expected/updatable_views.out
index 8443c24f18b7..162fac6904c4 100644
--- a/src/test/regress/expected/updatable_views.out
+++ b/src/test/regress/expected/updatable_views.out
@@ -899,7 +899,10 @@ EXPLAIN (costs off) UPDATE rw_view2 SET a=3 WHERE a=2;
Recheck Cond: (a > 0)
-> Bitmap Index Scan on base_tbl_pkey
Index Cond: (a > 0)
-(7 rows)
+ Trigger rw_view1_del_trig
+ Trigger rw_view1_ins_trig
+ Trigger rw_view1_upd_trig
+(10 rows)
EXPLAIN (costs off) DELETE FROM rw_view2 WHERE a=2;
QUERY PLAN
@@ -911,7 +914,10 @@ EXPLAIN (costs off) DELETE FROM rw_view2 WHERE a=2;
Recheck Cond: (a > 0)
-> Bitmap Index Scan on base_tbl_pkey
Index Cond: (a > 0)
-(7 rows)
+ Trigger rw_view1_del_trig
+ Trigger rw_view1_ins_trig
+ Trigger rw_view1_upd_trig
+(10 rows)
DROP TABLE base_tbl CASCADE;
NOTICE: drop cascades to 2 other objects
