Re: Stats for triggers on partitioned tables not shown in EXPLAIN ANALYZE

Fujita-san,

Thanks for reporting the bugs and patches to fix the same.

On 2017/08/15 21:20, Etsuro Fujita wrote:
> Hi hackers,
>
> I noticed that runtime stats for BEFORE ROW INSERT triggers on leaf
> partitions of partitioned tables aren't reported in EXPLAIN ANALYZE. Here
> is an example:
>
> postgres=# create table trigger_test (a int, b text) partition by list (a);
> CREATE TABLE
> postgres=# create table trigger_test1 partition of trigger_test for values
> in (1);
> CREATE TABLE
> postgres=# create trigger before_ins_row_trig BEFORE INSERT ON
> trigger_test1 FOR EACH ROW EXECUTE PROCEDURE trigger_data();
> CREATE TRIGGER
> postgres=# create trigger after_ins_row_trig AFTER INSERT ON trigger_test1
> FOR EACH ROW EXECUTE PROCEDURE trigger_data();
> CREATE TRIGGER
> postgres=# explain analyze insert into trigger_test values (1, 'foo');
> NOTICE: before_ins_row_trig() BEFORE ROW INSERT ON trigger_test1
> NOTICE: NEW: (1,foo)
> NOTICE: after_ins_row_trig() AFTER ROW INSERT ON trigger_test1
> NOTICE: NEW: (1,foo)
> QUERY PLAN
> -----------------------------------------------------------------------------------------------------
>
> Insert on trigger_test (cost=0.00..0.01 rows=1 width=36) (actual
> time=0.193..0.193 rows=0 loops=1)
> -> Result (cost=0.00..0.01 rows=1 width=36) (actual time=0.002..0.003
> rows=1 loops=1)
> Planning time: 0.027 ms
> Trigger after_ins_row_trig on trigger_test1: time=0.075 calls=1
> Execution time: 0.310 ms
> (5 rows)
>
> where trig_data() is borrowed from the regression test in postgres_fdw.
> The stats for the AFTER ROW INSERT trigger after_ins_row_trig are well
> shown in the output, but the stats for the BEFORE ROW INSERT trigger
> before_ins_row_trig aren't at all. I think we should show the latter as
> well.

Right. ExplainPrintTriggers() is unable to find the leaf partition
ResultRelInfos in the insert tuple-routing case, because they are not
present in EState.es_result_relations. If a leaf partition happened to
have an insert AR trigger, corresponding ResultRelInfo *would be* present
in EState.es_trig_target_relations, but that would be useless to show the
information about insert BR triggers that might also be present, because
that ResultRelInfo is created long after the BR triggers are executed.
So, the instrumentation information corresponding to the BR triggers'
invocation is not updated in that ResultRelInfo, giving the impression
that they were never invoked (report_triggers does not list such triggers).

> Another thing I noticed is: runtime stats for BEFORE STATEMENT
> UPDATE/DELETE triggers on partitioned table roots aren't reported in
> EXPLAIN ANALYZE, either, as shown in a below example:
>
> postgres=# create trigger before_upd_stmt_trig BEFORE UPDATE ON
> trigger_test FOR EACH STATEMENT EXECUTE PROCEDURE trigger_func();
> CREATE TRIGGER
> postgres=# create trigger after_upd_stmt_trig AFTER UPDATE ON trigger_test
> FOR EACH STATEMENT EXECUTE PROCEDURE trigger_func();
> CREATE TRIGGER
> postgres=# explain analyze update trigger_test set b = 'bar' where a = 1;
> NOTICE: trigger_func(<NULL>) called: action = UPDATE, when = BEFORE,
> level = STATEMENT
> NOTICE: trigger_func(<NULL>) called: action = UPDATE, when = AFTER, level
> = STATEMENT
> QUERY PLAN
>
> ----------------------------------------------------------------------------------------------------------
>
> -----
> Update on trigger_test (cost=0.00..25.88 rows=6 width=42) (actual
> time=0.296..0.296 rows=0 loops=1)
> Update on trigger_test1
> -> Seq Scan on trigger_test1 (cost=0.00..25.88 rows=6 width=42)
> (actual time=0.010..0.011 rows=1 loops=1)
> Filter: (a = 1)
> Planning time: 0.152 ms
> Trigger after_upd_stmt_trig on trigger_test: time=0.141 calls=1
> Execution time: 0.476 ms
> (7 rows)
>
> where trigger_func() is borrowed from the regression test, too. The stats
> for the BEFORE STATEMENT UPDATE trigger before_upd_stmt_trig aren't shown
> at all in the output. I think this should also be fixed.

Yes. Again, ExplainPrintTriggers() fails to find the ResultRelInfos for
the root partitioned table in the update/delete cases, because they are
not present in EState.es_result_relations. If the root partitioned table
happened to have an AS trigger, corresponding ResultRelInfo *would be*
present in EState.es_trig_target_relations, but that would be useless to
show the information about update/delete BS triggers that might also be
present, because that ResultRelInfo is created long after the BS triggers
are executed. So, the instrumentation information corresponding to the BS
triggers' invocation is not updated in that ResultRelInfo, giving the
impression that they were never invoked.

> So here is a
> patch for fixing both issues. Changes I made are:
>
> * To fix the former, I added a new List member es_leaf_result_relations to
> EState, modified ExecSetupPartitionTupleRouting so that it creates
> ResultRelInfos with the EState's es_instrument and then saves them in that
> list, and modified ExplainPrintTriggers to show stats for BEFORE ROW
> INSERT triggers on leaf partitions (if any) by looking at that list. I
> also modified copy.c so that ExecSetupPartitionTupleRouting and related
> things are performed in CopyFrom after its EState creation.
>
> * To fix the latter, I modified ExplainPrintTriggers to show stats for
> BEFORE STATEMENT UPDATE/DELETE triggers on partitioned table roots (if
> any) by looking at the es_root_result_relations array.

Having ExplainPrintTriggers look at (the new) es_leaf_result_relations and
es_root_result_relations seems to get the job done. IOW, the proposed
patch is good to fix the issue.

> * While fixing these, I noticed that AFTER ROW INSERT triggers on leaf
> partitions and BEFORE STATEMENT UPDATE/DELETE triggers on partitioned
> table roots re-open relations and re-create ResultRelInfos (trigger-only
> ResultRelInfos!) in ExecGetTriggerResultRel when executing triggers (and
> that in the above examples, the stats for AFTER ROW INSERT trigger/AFTER
> STATEMENT UPDATE trigger are shown the result for es_trig_target_relations
> in ExplainPrintTriggers). But that wouldn't be efficient (and EXPLAIN
> ANALYZE might produce odd outputs), so I modified ExecGetTriggerResultRel
> so that it searches es_leaf_result_relations and es_root_result_relations
> in addition to es_result_relations.

I guess this change means that no trigger-only ResultRelInfos are created
for leaf partitions in the insert tuple-routing case and for the root
partitioned table in the update/delete cases. Instead, we use the
originally created ResultRelInfo (one that ExecSetupPartitionTupleRouting
creates for the leaf partitions and InitPlan creates for the root
partitioned table for trigger-firing) even for the AFTER triggers, for
which, currently, a trigger-only ResultRelInfo would get created. Sounds
good to me.

Adding this to the PG 10 open items list.

Thanks again.

Regards,
Amit