Thread: [HACKERS] Stats for triggers on partitioned tables not shown in EXPLAIN ANALYZE

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.

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. 
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.

* 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.

Best regards,
Etsuro Fujita

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

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

On Wed, Aug 16, 2017 at 05:14:25PM +0900, Amit Langote wrote:
> On 2017/08/15 21:20, Etsuro Fujita wrote:
> > 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:

> > So here is a
> > patch for fixing both issues.

> Adding this to the PG 10 open items list.

[Action required within three days.  This is a generic notification.]

The above-described topic is currently a PostgreSQL 10 open item.  Robert,
since you committed the patch believed to have created it, you own this open
item.  If some other commit is more relevant or if this does not belong as a
v10 open item, please let us know.  Otherwise, please observe the policy on
open item ownership[1] and send a status update within three calendar days of
this message.  Include a date for your subsequent status update.  Testers may
discover new open items at any time, and I want to plan to get them all fixed
well in advance of shipping v10.  Consequently, I will appreciate your efforts
toward speedy resolution.  Thanks.

[1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

On Fri, Aug 18, 2017 at 1:15 AM, Noah Misch <noah@leadboat.com> wrote:
> The above-described topic is currently a PostgreSQL 10 open item.  Robert,
> since you committed the patch believed to have created it, you own this open
> item.  If some other commit is more relevant or if this does not belong as a
> v10 open item, please let us know.  Otherwise, please observe the policy on
> open item ownership[1] and send a status update within three calendar days of
> this message.  Include a date for your subsequent status update.  Testers may
> discover new open items at any time, and I want to plan to get them all fixed
> well in advance of shipping v10.  Consequently, I will appreciate your efforts
> toward speedy resolution.  Thanks.
>
> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

Committed and back-patched the proposed patch.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2017/08/19 2:09, Robert Haas wrote:
> On Fri, Aug 18, 2017 at 1:15 AM, Noah Misch <noah@leadboat.com> wrote:
>> The above-described topic is currently a PostgreSQL 10 open item.  Robert,
>> since you committed the patch believed to have created it, you own this open
>> item.  If some other commit is more relevant or if this does not belong as a
>> v10 open item, please let us know.  Otherwise, please observe the policy on
>> open item ownership[1] and send a status update within three calendar days of
>> this message.  Include a date for your subsequent status update.  Testers may
>> discover new open items at any time, and I want to plan to get them all fixed
>> well in advance of shipping v10.  Consequently, I will appreciate your efforts
>> toward speedy resolution.  Thanks.
>>
>> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com
> 
> Committed and back-patched the proposed patch.

Thanks.

Regards,
Amit

On 2017/08/21 9:18, Amit Langote wrote:
> On 2017/08/19 2:09, Robert Haas wrote:
>> On Fri, Aug 18, 2017 at 1:15 AM, Noah Misch <noah@leadboat.com> wrote:
>>> The above-described topic is currently a PostgreSQL 10 open item.  Robert,
>>> since you committed the patch believed to have created it, you own this open
>>> item.  If some other commit is more relevant or if this does not belong as a
>>> v10 open item, please let us know.  Otherwise, please observe the policy on
>>> open item ownership[1] and send a status update within three calendar days of
>>> this message.  Include a date for your subsequent status update.  Testers may
>>> discover new open items at any time, and I want to plan to get them all fixed
>>> well in advance of shipping v10.  Consequently, I will appreciate your efforts
>>> toward speedy resolution.  Thanks.
>>>
>>> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com
>>
>> Committed and back-patched the proposed patch.
> 
> Thanks.

Thank you!

Best regards,
Etsuro Fujita