Thread: Trigger information for auto_explain.

Trigger information for auto_explain.

From
Kyotaro HORIGUCHI
Date:
Hello,

Now explain can show trigger statistics (from when?).

=# create table t (a int, b int);
=# create or replace function hoge() returns trigger as 'begin new.b = new.a; return new; end;' language plpgsql;
=# create trigger ins_hoge before insert or update on t for each row execute procedure hoge();

Explain analyze shows trigger information.

=# explain analyze insert into t (select a from generate_series(0, 100) a);
|                                QUERY PLAN      
|----------------------------------------------------------------
| Insert on t  (cost=0.00..10.00 rows=1000 width=4) (actual time=2.712.....
|   ->  Function Scan on generate_series a  (cost=0.00..10.00 rows=1000 width=4)
|       (actual time=0.047..0.147 rows=101 loops=1)
| Trigger ins_hoge: time=1.881 calls=101
| Total runtime: 3.009 ms

On the other hand, auto_explain doesn't.

=# load auto_explain;
=# set auto_explain.log_min_duration = 0;
=# set auto_explain.log_analyze = 'yes';
=# insert into t (select a from generate_series(0, 100) a);
|LOG:  duration: 2.871 ms  plan:
|        Query Text: insert into t (select a from generate_series(0, 100) a);
|        Insert on t  (cost=0.00..10.00 rows=1000 width=4)
|          ->  Function Scan on generate_series a  (cost=0.00..10.00 ...

auto_explain will show trigger infos with this patch like this.

=# set auto_explain.log_triggers = 'yes';
=# insert into t (select a from generate_series(0, 100) a);
| LOG:  duration: 2.098 ms  plan:
|         Query Text: insert into t (select a from generate_series(0, 100) a);
|         Insert on t  (cost=0.00..10.00 rows=1000 width=4) (actual time=2.097..2.097 rows=0 loops=1)
|           ->  Function Scan on generate_series a  (cost=0.00..10.00 rows=1000 width=4) (actual time=0.044..0.123
rows=101loops=1)
 
|         Trigger ins_hoge: time=1.452 calls=101

This patch consists of two parts,
0001_expose_explain_triggers_v1_20140114.patch
 Expose the code to print out trigger information currently hidden in ExplainOnePlan().
0002_auto_explain_triggers_v1_20140114.patch
 Enable auto_explain to output trigger information.

Documentation will be added later..

regards,

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 9969a25..45beb5b 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -484,29 +484,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,    /* Print info
aboutruntime of triggers */    if (es->analyze)
 
-    {
-        ResultRelInfo *rInfo;
-        bool        show_relname;
-        int            numrels = queryDesc->estate->es_num_result_relations;
-        List       *targrels = queryDesc->estate->es_trig_target_relations;
-        int            nr;
-        ListCell   *l;
-
-        ExplainOpenGroup("Triggers", "Triggers", false, es);
-
-        show_relname = (numrels > 1 || targrels != NIL);
-        rInfo = queryDesc->estate->es_result_relations;
-        for (nr = 0; nr < numrels; rInfo++, nr++)
-            report_triggers(rInfo, show_relname, es);
-
-        foreach(l, targrels)
-        {
-            rInfo = (ResultRelInfo *) lfirst(l);
-            report_triggers(rInfo, show_relname, es);
-        }
-
-        ExplainCloseGroup("Triggers", "Triggers", false, es);
-    }
+        ExplainPrintTriggers(es, queryDesc);    /*     * Close down the query and free resources.  Include time for
thisin the
 
@@ -563,6 +541,42 @@ ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)}/*
+ * ExplainPrintTriggers -
+
+ *      convert a QueryDesc's trigger statistics to text and append it to
+ *      es->str
+ *
+ * The caller should have set up the options fields of *es, as well as
+ * initializing the output buffer es->str.    Other fields in *es are
+ * initialized here.
+ */
+void
+ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc)
+{
+    ResultRelInfo *rInfo;
+    bool        show_relname;
+    int            numrels = queryDesc->estate->es_num_result_relations;
+    List       *targrels = queryDesc->estate->es_trig_target_relations;
+    int            nr;
+    ListCell   *l;
+
+    ExplainOpenGroup("Triggers", "Triggers", false, es);
+
+    show_relname = (numrels > 1 || targrels != NIL);
+    rInfo = queryDesc->estate->es_result_relations;
+    for (nr = 0; nr < numrels; rInfo++, nr++)
+        report_triggers(rInfo, show_relname, es);
+
+    foreach(l, targrels)
+    {
+        rInfo = (ResultRelInfo *) lfirst(l);
+        report_triggers(rInfo, show_relname, es);
+    }
+
+    ExplainCloseGroup("Triggers", "Triggers", false, es);
+}
+
+/* * ExplainQueryText - *      add a "Query Text" node that contains the actual text of the query *
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index ca213d7..4c4226d 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -71,6 +71,7 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,               const char
*queryString,ParamListInfo params);extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
 
+extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);extern void ExplainQueryText(ExplainState
*es,QueryDesc *queryDesc); 
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 57dfbe2..ec80132 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -25,6 +25,7 @@ static int    auto_explain_log_min_duration = -1; /* msec or -1 */static bool
auto_explain_log_analyze= false;static bool auto_explain_log_verbose = false;static bool auto_explain_log_buffers =
false;
+static bool auto_explain_log_triggers = false;static bool auto_explain_log_timing = false;static int
auto_explain_log_format= EXPLAIN_FORMAT_TEXT;static bool auto_explain_log_nested_statements = false;
 
@@ -113,6 +114,17 @@ _PG_init(void)                             NULL,                             NULL);
+    DefineCustomBoolVariable("auto_explain.log_triggers",
+                             "Collect trigger stats, avaialble when log_analyze.",
+                             NULL,
+                             &auto_explain_log_triggers,
+                             true,
+                             PGC_SUSET,
+                             0,
+                             NULL,
+                             NULL,
+                             NULL);
+    DefineCustomEnumVariable("auto_explain.log_format",                             "EXPLAIN format to be used for
planlogging.",                             NULL,
 
@@ -295,6 +307,8 @@ explain_ExecutorEnd(QueryDesc *queryDesc)            ExplainBeginOutput(&es);
ExplainQueryText(&es,queryDesc);            ExplainPrintPlan(&es, queryDesc);
 
+            if (es.analyze && auto_explain_log_triggers)
+                ExplainPrintTriggers(&es, queryDesc);            ExplainEndOutput(&es);            /* Remove last line
break*/ 

Re: Trigger information for auto_explain.

From
Jaime Casanova
Date:
On Tue, Jan 14, 2014 at 4:25 AM, Kyotaro HORIGUCHI
<horiguchi.kyotaro@lab.ntt.co.jp> wrote:
>
> This patch consists of two parts,
>
>  0001_expose_explain_triggers_v1_20140114.patch
>
>   Expose the code to print out trigger information currently
>   hidden in ExplainOnePlan().
>
>  0002_auto_explain_triggers_v1_20140114.patch
>
>   Enable auto_explain to output trigger information.
>
> Documentation will be added later..
>

Hi,

I think documentation is the only thing that stops this patch to be
commitable... can you add it?

--
Jaime Casanova         www.2ndQuadrant.com
Professional PostgreSQL: Soporte 24x7 y capacitación
Phone: +593 4 5107566         Cell: +593 987171157



Re: Trigger information for auto_explain.

From
Alvaro Herrera
Date:
Jaime Casanova wrote:
> On Tue, Jan 14, 2014 at 4:25 AM, Kyotaro HORIGUCHI
> <horiguchi.kyotaro@lab.ntt.co.jp> wrote:
> >
> > This patch consists of two parts,
> >
> >  0001_expose_explain_triggers_v1_20140114.patch

> >  0002_auto_explain_triggers_v1_20140114.patch

> > Documentation will be added later..

> I think documentation is the only thing that stops this patch to be
> commitable... can you add it?

Agreed.  I have pushed patch 0001 for now.

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services



Re: Trigger information for auto_explain.

From
Kyotaro HORIGUCHI
Date:
Hello,

> > > This patch consists of two parts,
> > >
> > >  0001_expose_explain_triggers_v1_20140114.patch
> 
> > >  0002_auto_explain_triggers_v1_20140114.patch
> 
> > > Documentation will be added later..
> 
> > I think documentation is the only thing that stops this patch to be
> > commitable... can you add it?
> 
> Agreed.  I have pushed patch 0001 for now.

Thank you, I'll put it sooner.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center



Re: Trigger information for auto_explain.

From
Kyotaro HORIGUCHI
Date:
Hello, I came back with doc patch and revised 0002 patch.

> > > I think documentation is the only thing that stops this patch to be
> > > commitable... can you add it?
> > 
> > Agreed.  I have pushed patch 0001 for now.
> 
> Thank you, I'll put it sooner.

I found the default setting for log_triggers was true in the last
patch while writing doc but it's better be false ragarding
backward compatibility. The 0002 patch attached has been changed
there.

- 0002_auto_explain_triggers_v2_20140122.patch
 default value for log_triggers from 'true' to 'false'. As added documents says.

- 0003_auto_explain_triggers_doc_v1_20140122.patch
 documentation.

regards,

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index c9b8192..53f38cb 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -124,6 +124,24 @@ LOAD 'auto_explain';   <varlistentry>    <term>
+     <varname>auto_explain.log_triggers</varname> (<type>boolean</type>)
+    </term>
+    <indexterm>
+     <primary><varname>auto_explain.log_triggers</> configuration parameter</primary>
+    </indexterm>
+    <listitem>
+     <para>
+      <varname>auto_explain.log_triggers</varname> causes additional trigger
+      statistics output to be printed when an execution plan is logged. This
+      parameter is off by default. Only superusers can change this
+      setting. This parameter has no effect
+      unless <varname>auto_explain.log_analyze</> parameter is set.
+     </para>
+    </listitem>
+   </varlistentry>
+
+   <varlistentry>
+    <term>     <varname>auto_explain.log_format</varname> (<type>enum</type>)    </term>    <indexterm>
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index af68479..2354327 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -25,6 +25,7 @@ static int    auto_explain_log_min_duration = -1; /* msec or -1 */static bool
auto_explain_log_analyze= false;static bool auto_explain_log_verbose = false;static bool auto_explain_log_buffers =
false;
+static bool auto_explain_log_triggers = false;static bool auto_explain_log_timing = false;static int
auto_explain_log_format= EXPLAIN_FORMAT_TEXT;static bool auto_explain_log_nested_statements = false;
 
@@ -113,6 +114,17 @@ _PG_init(void)                             NULL,                             NULL);
+    DefineCustomBoolVariable("auto_explain.log_triggers",
+                             "Collect trigger stats, avaialble when log_analyze.",
+                             NULL,
+                             &auto_explain_log_triggers,
+                             false,
+                             PGC_SUSET,
+                             0,
+                             NULL,
+                             NULL,
+                             NULL);
+    DefineCustomEnumVariable("auto_explain.log_format",                             "EXPLAIN format to be used for
planlogging.",                             NULL,
 
@@ -295,6 +307,8 @@ explain_ExecutorEnd(QueryDesc *queryDesc)            ExplainBeginOutput(&es);
ExplainQueryText(&es,queryDesc);            ExplainPrintPlan(&es, queryDesc);
 
+            if (es.analyze && auto_explain_log_triggers)
+                ExplainPrintTriggers(&es, queryDesc);            ExplainEndOutput(&es);            /* Remove last line
break*/ 

Re: Trigger information for auto_explain.

From
Kyotaro HORIGUCHI
Date:
Hi, I saw this patch has been moved into "committed patches" but
only the first part (0001_..) for the core is committed as of
32001ab but the rest for extension side seem not to have been
committed.

Would you mind taking a look on that, Álvaro?

regards,

At Wed, 22 Jan 2014 17:28:27 +0900, Kyotaro HORIGUCHI wrote
me> Hello, I came back with doc patch and revised 0002 patch.
me> 
me> > > > I think documentation is the only thing that stops this patch to be
me> > > > commitable... can you add it?
me> > > 
me> > > Agreed.  I have pushed patch 0001 for now.
me> > 
me> > Thank you, I'll put it sooner.
me> 
me> I found the default setting for log_triggers was true in the last
me> patch while writing doc but it's better be false ragarding
me> backward compatibility. The 0002 patch attached has been changed
me> there.
me> 
me> - 0002_auto_explain_triggers_v2_20140122.patch
me> 
me>   default value for log_triggers from 'true' to 'false'. As added
me>   documents says.
me> 
me> - 0003_auto_explain_triggers_doc_v1_20140122.patch
me> 
me>   documentation.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

Re: Trigger information for auto_explain.

From
Alvaro Herrera
Date:
Kyotaro HORIGUCHI wrote:
> Hi, I saw this patch has been moved into "committed patches" but
> only the first part (0001_..) for the core is committed as of
> 32001ab but the rest for extension side seem not to have been
> committed.
> 
> Would you mind taking a look on that, Álvaro?

Yep, pushed.

-- 
Álvaro Herrera                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services



Re: Trigger information for auto_explain.

From
Kyotaro HORIGUCHI
Date:
Hello,

> Kyotaro HORIGUCHI wrote:
> > Hi, I saw this patch has been moved into "committed patches" but
> > only the first part (0001_..) for the core is committed as of
> > 32001ab but the rest for extension side seem not to have been
> > committed.
> >
> > Would you mind taking a look on that, Álvaro?
>
> Yep, pushed.

Thank you.

--
Kyotaro Horiguchi
NTT Open Source Software Center