WIP: make EXPLAIN ANALYZE show time spent in triggers
The attached patch allows EXPLAIN ANALYZE to break out the time spent in
triggers when EXPLAINing a statement that can fire triggers. Formerly
this time was included in "Total runtime" but not otherwise accounted
for.
An example is
regression=# explain analyze delete from foo;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Seq Scan on foo (cost=0.00..172.70 rows=11770 width=6) (actual time=0.063..86.650 rows=10000 loops=1)
Trigger RI_ConstraintTrigger_60781: time=3899.609 calls=10000
Total runtime: 4218.309 ms
(3 rows)
The trigger display text probably still needs some work --- in
particular I'm wondering if RI triggers couldn't be displayed in some
more intelligent fashion than just the internal trigger name.
What I'm actually more interested in right now is comments on the
infrastructure changes. To make this work, I modified the executor's
ResultRelInfo structs to include provisions to store per-trigger
Instrumentation nodes, and changed AfterTriggerEndQuery to receive the
query's EState in which it could look up the ResultRelInfos. A nifty
side benefit is that the after-event trigger code doesn't have to open
result relations for itself anymore for non-deferred triggers: it can
use the executor's main copies of the relations. I had to change the
call order so that AfterTriggerEndQuery is called before instead of
after ExecutorEnd (because ExecutorEnd closes down all this state).
I don't see any downside to that, but am I missing something?
regards, tom lane
The attached patch allows EXPLAIN ANALYZE to break out the time spent in
triggers when EXPLAINing a statement that can fire triggers. Formerly
this time was included in "Total runtime" but not otherwise accounted
for.
Very nice.
An example is
regression=# explain analyze delete from foo;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Seq Scan on foo (cost=0.00..172.70 rows=11770 width=6) (actual time=0.063..86.650 rows=10000 loops=1)
Trigger RI_ConstraintTrigger_60781: time=3899.609 calls=10000
Total runtime: 4218.309 ms
(3 rows)
Could we get plain EXPLAIN output as well:
regression=# explain analyze delete from foo;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Seq Scan on foo (cost=0.00..172.70 rows=11770 width=6)
Trigger RI_ConstraintTrigger_60781: calls=11770
(2 rows)
Also, have you considered statement level triggers?
Chris
Christopher Kings-Lynne <chriskl@familyhealth.com.au> writes:
Could we get plain EXPLAIN output as well:
Plain EXPLAIN doesn't run the query, and therefore not the triggers.
Also, have you considered statement level triggers?
I haven't actually tested that case, but I believe they'll show up
if used.
regards, tom lane
Could we get plain EXPLAIN output as well:
Plain EXPLAIN doesn't run the query, and therefore not the triggers.
But the point of it is to estimate, right? Could it not estimate the
number of time each trigger would be called. Surely that's the same as
estimating the number of rows each clause will return?
Chris
Christopher Kings-Lynne <chriskl@familyhealth.com.au> writes:
Plain EXPLAIN doesn't run the query, and therefore not the triggers.
But the point of it is to estimate, right? Could it not estimate the
number of time each trigger would be called. Surely that's the same as
estimating the number of rows each clause will return?
Right. So what's the point? It seems like the printout would just be
useless noise: it'd repeat N times the estimate of the top-level number
of output rows.
regards, tom lane
Right. So what's the point? It seems like the printout would just be
useless noise: it'd repeat N times the estimate of the top-level number
of output rows.
Well I guess the point would be to remind people that there are
(potentially) expensive triggers that will run, so even though the
analysis presented indicates that the tested query will be fast, it
might not be...
Chris
The attached patch allows EXPLAIN ANALYZE to break out the time spent in
triggers when EXPLAINing a statement that can fire triggers. Formerly
this time was included in "Total runtime" but not otherwise accounted
for.
Actually, should you make it talk about RULEs as well?
Chris
Christopher Kings-Lynne <chriskl@familyhealth.com.au> writes:
Right. So what's the point? It seems like the printout would just be
useless noise: it'd repeat N times the estimate of the top-level number
of output rows.
Well I guess the point would be to remind people that there are
(potentially) expensive triggers that will run, so even though the
analysis presented indicates that the tested query will be fast, it
might not be...
If we had any way to estimate the costs of the triggers, I'd agree with
listing those numbers --- but the triggers are just black boxes. So I
don't see the point. We might as well just add one line saying
<ding> You've got triggers!
regards, tom lane