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=101 loops=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 about runtime 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 this in 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 plan logging.",
 							 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 */
-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Reply via email to