Thread: EXPLAIN and nfiltered, take two
Hi, Here's a patch for $SUBJECT based on the feedback here: http://archives.postgresql.org/message-id/9053.1295888538@sss.pgh.pa.us I intentionally decided to omit the information for Join Filter, since the information can already be deduced from EXPLAIN ANALYZE output, and for Left Joins and Anti Joins "Rows Removed by Join Filter" didn't really make much sense. The "Rows Removed by .." information is always shown by default (when there is a Filter or Recheck Cond, of course), and I didn't feel like it was worth it to add a new option for EXPLAIN to turn that information off. As for documentation.. I'm really at a loss here. I tried numerous different things for doc/src/sgml/perform.sgml, but I didn't feel like any of them added anything. The EXPLAIN ANALYZE output seems quite self-explanatory after all. Attached are also the tests I used, and an example output. -- Marko Tiikkaja http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
Attachment
Hi! On Thu, Sep 8, 2011 at 15:11, Marko Tiikkaja <marko.tiikkaja@2ndquadrant.com> wrote: > Here's a patch for $SUBJECT based on the feedback here: > http://archives.postgresql.org/message-id/9053.1295888538@sss.pgh.pa.us I tried this patch and noticed something weird. This is probably not intentional: explain analyze select * from generate_series(1,10) i where i>1 and now()!=now(); Result (cost=0.01..12.51 rows=333 width=4) (actual time=0.010..0.010 rows=0 loops=1) One-Time Filter: (now() <> now()) -> Function Scan on generate_series i (cost=0.01..12.51 rows=333 width=4) (never executed) Filter: (i > 1) Rows Removed by Filter: -nan Since it's never executed, nfiltered shows up as "-nan" Regards, Marti
Hi, On 2011-09-10 19:50, Marti Raudsepp wrote: > I tried this patch and noticed something weird. This is probably not > intentional: Indeed, it is not intentional. Will see how I can fix this. Thank you for trying the patch out! -- Marko Tiikkaja http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
On 12/09/2011 12:12, I wrote: > On 2011-09-10 19:50, Marti Raudsepp wrote: >> I tried this patch and noticed something weird. This is probably not >> intentional: > > Indeed, it is not intentional. Will see how I can fix this. The attached patch is the best I could come up with. I considered showing "Rows Removed by Foo: (never executed)" and omitting the line altogether, but I didn't particularly like either of those options. The current patch simply displays "Rows Removed by Foo: 0". I also added a comment the last patch was missing. -- Marko Tiikkaja http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
Attachment
Marko Tiikkaja <marko.tiikkaja@2ndquadrant.com> writes:
> The attached patch is the best I could come up with. I considered
> showing "Rows Removed by Foo: (never executed)" and omitting the line
> altogether, but I didn't particularly like either of those options. The
> current patch simply displays "Rows Removed by Foo: 0".
I'm looking at this patch now. I can't escape the conclusion that we
should put the counters into struct Instrumentation after all. I know
I complained upthread that that would require arbitrary decisions about
how to use the counters in multi-filter nodes, but now I see there are
downsides to the way it's done here, too. The basic problem I've got
with this is that the counters are being managed differently from any
other instrumentation counters, and that will bite us in the rear sooner
or later. For example, if we needed a way to reset the counters for a
particular plan node, we'd be forced into some very ugly choices about
how to make that happen for counters that are in node-type-specific
structures.
So, unless there are objections, I'm going to adjust the patch to put
the counters back into struct Instrumentation.
I'm also thinking that it'd be wise to invent macros to encapsulate the
"if (node->ps.instrument) node->ps.instrument->counter += 1" sequences
that will be required.
One other point is that with or without macros, a large fraction of the
executor/nodeFoo.c files are going to need to #include instrument.h
if we put the counters into struct Instrumentation. We could only avoid
that by putting the increments into out-of-line functions instead of
macros, which I don't care for from a performance standpoint. So I'm
thinking we should just bite the bullet and #include instrument.h in
execnodes.h, which would also let us get rid of the "struct" hack that's
currently used to reference Instrumentation nodes there.
regards, tom lane
Marko Tiikkaja <marko.tiikkaja@2ndquadrant.com> writes:
>> The attached patch is the best I could come up with. I considered
>> showing "Rows Removed by Foo: (never executed)" and omitting the line
>> altogether, but I didn't particularly like either of those options. The
>> current patch simply displays "Rows Removed by Foo: 0".
I ran into a couple more issues with this patch.
One is the handling of bitmapqualorig filtering (and correspondingly
indexqualorig, which the patch misses entirely). These counts are
really quite a bit different from the other filter conditions we are
dealing with, because what they represent is not anything directly
user-controllable, but how lossy the indexscan is. That is, we get a
count for any tuple that the index told us to visit but that turned out
to not actually satisfy the indexqual. So the count is guaranteed zero
for any non-lossy indexscan, which includes most cases. In view of
that, I find it useless and probably confusing to put out "Rows Removed
by Recheck Cond: 0" unless we're dealing with a lossy index.
Now the difficulty is that EXPLAIN doesn't really have any way to know
if the index is lossy, especially not if every such check luckily
happened to pass.
What I'm inclined to do is suppress the "rows removed" output, at least
in textual output format, unless it's nonzero. But that sorta begs the
question of whether we shouldn't do that for all cases, not just index
recheck conditions.
Also, upthread it was argued that we shouldn't measure the effects of
joinqual filtering. I don't buy this for a minute, especially not in
merge/hash joins, where a row thrown away by joinqual filtering is just
as expensive as one thrown away by otherqual filtering, and where you
can *not* determine how big the raw merge/hash join result is if you're
not told how much the joinqual removed. I see the point about it not
being clear how to explain things for SEMI/ANTI join cases, but I think
we need to figure that out, not just punt.
Thoughts?
regards, tom lane
On Tue, Sep 20, 2011 at 8:19 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote: > Marko Tiikkaja <marko.tiikkaja@2ndquadrant.com> writes: >>> The attached patch is the best I could come up with. I considered >>> showing "Rows Removed by Foo: (never executed)" and omitting the line >>> altogether, but I didn't particularly like either of those options. The >>> current patch simply displays "Rows Removed by Foo: 0". > > I ran into a couple more issues with this patch. > > One is the handling of bitmapqualorig filtering (and correspondingly > indexqualorig, which the patch misses entirely). These counts are > really quite a bit different from the other filter conditions we are > dealing with, because what they represent is not anything directly > user-controllable, but how lossy the indexscan is. That is, we get a > count for any tuple that the index told us to visit but that turned out > to not actually satisfy the indexqual. So the count is guaranteed zero > for any non-lossy indexscan, which includes most cases. In view of > that, I find it useless and probably confusing to put out "Rows Removed > by Recheck Cond: 0" unless we're dealing with a lossy index. I don't really see the point of this. I think printing it always is both clear and appropriate; it would be even nicer if we also had a line for "Rows Rechecked". I am slightly worried that this additional information is going to make the output too verbose. But if that turns out to be the problem, I think the solution is to add another option to control whether this information is emitted - that's why we have a flexible options syntax in the first place - and not to start guessing which information the user will think is boring or confusing in any particular case. I think we are getting to the point where EXPLAIN is complex enough that it should really have its own chapter in the documentation. The existing treatment in the SQL reference page is a good start, but it doesn't really do the topic justice. And being able to document what all of these things mean would, I think, ease the problem of trying to make everything 100% self-documenting. > Also, upthread it was argued that we shouldn't measure the effects of > joinqual filtering. I don't buy this for a minute, especially not in > merge/hash joins, where a row thrown away by joinqual filtering is just > as expensive as one thrown away by otherqual filtering, and where you > can *not* determine how big the raw merge/hash join result is if you're > not told how much the joinqual removed. I see the point about it not > being clear how to explain things for SEMI/ANTI join cases, but I think > we need to figure that out, not just punt. Yep, I agree. We should measure everything we possibly can. I don't have a clear idea how this ought to be represented, but leaving it out doesn't seem like the right answer. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
Robert Haas <robertmhaas@gmail.com> writes:
> On Tue, Sep 20, 2011 at 8:19 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> I find it useless and probably confusing to put out "Rows Removed
>> by Recheck Cond: 0" unless we're dealing with a lossy index.
> I don't really see the point of this. I think printing it always is
> both clear and appropriate; it would be even nicer if we also had a
> line for "Rows Rechecked".
I think you'll be singing a different tune as soon as you find out that
every single indexscan in your plans has a generally-useless "Rows
Removed" line added to it. The patch as I have it now is doing this:
regression=# explain analyze select * from tenk1 where unique1 = 42;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------Index
Scanusing tenk1_unique1 on tenk1 (cost=0.00..8.27 rows=1 width=244) (actual time=0.137..0.153 rows=1 loops=1) Index
Cond:(unique1 = 42) Rows Removed by Index Cond: 0Total runtime: 0.635 ms
(4 rows)
and personally I object to a 50% increase in the vertical space occupied
by a plan item in order to tell me not a damn thing. For an ordinary
btree indexscan, that line WILL NOT EVER be nonzero. I do not own
monitors large enough to accept that sort of overhead without complaint.
Now the entry *is* useful when considering a lossy indexscan. I just
don't want it there otherwise. (Note that I'm not proposing suppressing
such entries from the machine-readable formats, just text format.)
> I think we are getting to the point where EXPLAIN is complex enough
> that it should really have its own chapter in the documentation.
Yeah, the lack of documentation in the submitted patch is another big
problem with it, but it's not especially relevant to arguing about what
the behavior should be. I'll see about documentation after I'm done
with the code.
>> Also, upthread it was argued that we shouldn't measure the effects of
>> joinqual filtering. I don't buy this for a minute, ...
> Yep, I agree. We should measure everything we possibly can. I don't
> have a clear idea how this ought to be represented, but leaving it out
> doesn't seem like the right answer.
After playing with it for awhile, I'm inclined to just put out the
measured count and let the user interpret it. Here are some examples
using table tenk1 from the regression database, with most of the
planner's enable_ flags turned off to force it to produce the same shape
of plan for each case:
regression=# explain analyze select * from tenk1 a join tenk1 b on a.thousand = b.hundred ;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------Merge
Join (cost=0.00..3172.38 rows=100000 width=488) (actual time=0.449..1678.464 rows=100000 loops=1) Merge Cond:
(b.hundred= a.thousand) -> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=10000 width=244)
(actualtime=0.228..117.637 rows=10000 loops=1) -> Materialize (cost=0.00..1727.20 rows=10000 width=244) (actual
time=0.154..431.251rows=100001 loops=1) -> Index Scan using tenk1_thous_tenthous on tenk1 a
(cost=0.00..1702.20rows=10000 width=244) (actual time=0.115..12.033 rows=1001 loops=1)Total runtime: 2057.743 ms
(6 rows)
regression=# explain analyze select * from tenk1 a join tenk1 b on a.thousand = b.hundred and a.four = b.ten;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------Merge
Join (cost=0.00..3422.38 rows=10000 width=488) (actual time=0.657..1314.394 rows=20000 loops=1) Merge Cond: (b.hundred
=a.thousand) Join Filter: (a.four = b.ten) Rows Removed by Join Filter: 80000 -> Index Scan using tenk1_hundred on
tenk1b (cost=0.00..1702.16 rows=10000 width=244) (actual time=0.395..110.506 rows=10000 loops=1) -> Materialize
(cost=0.00..1727.20rows=10000 width=244) (actual time=0.165..390.867 rows=100001 loops=1) -> Index Scan using
tenk1_thous_tenthouson tenk1 a (cost=0.00..1702.20 rows=10000 width=244) (actual time=0.121..11.680 rows=1001
loops=1)Totalruntime: 1386.446 ms
(8 rows)
OK, that's pretty straightforward, what about a left join?
regression=# explain analyze select * from tenk1 a left join tenk1 b on a.thousand = b.hundred ;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------Merge
LeftJoin (cost=0.00..4929.36 rows=100000 width=488) (actual time=0.469..2097.446 rows=109000 loops=1) Merge Cond:
(a.thousand= b.hundred) -> Index Scan using tenk1_thous_tenthous on tenk1 a (cost=0.00..1702.20 rows=10000
width=244)(actual time=0.164..141.034 rows=10000 loops=1) -> Materialize (cost=0.00..1727.16 rows=10000 width=244)
(actualtime=0.234..642.645 rows=99991 loops=1) -> Index Scan using tenk1_hundred on tenk1 b
(cost=0.00..1702.16rows=10000 width=244) (actual time=0.191..137.716 rows=10000 loops=1)Total runtime: 2549.644 ms
(6 rows)
regression=# explain analyze select * from tenk1 a left join tenk1 b on a.thousand = b.hundred and a.four = b.ten;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------Merge
LeftJoin (cost=0.00..5179.36 rows=10000 width=488) (actual time=0.532..1869.319 rows=29800 loops=1) Merge Cond:
(a.thousand= b.hundred) Join Filter: (a.four = b.ten) Rows Removed by Join Filter: 80000 -> Index Scan using
tenk1_thous_tenthouson tenk1 a (cost=0.00..1702.20 rows=10000 width=244) (actual time=0.160..147.302 rows=10000
loops=1) -> Materialize (cost=0.00..1727.16 rows=10000 width=244) (actual time=0.274..672.431 rows=99991 loops=1)
-> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=10000 width=244) (actual time=0.233..141.353
rows=10000loops=1)Total runtime: 2012.329 ms
(8 rows)
In this case there are about 800 more rows out than you might expect,
corresponding to left-hand rows that had null-extended rows emitted
for them rather than just going away entirely. That happens after the
"join filter" so the rows-removed count doesn't change.
Here's a semi join:
regression=# explain analyze select * from tenk1 a where exists(select 1 from tenk1 b where a.thousand = b.hundred );
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------Merge
SemiJoin (cost=0.00..3374.88 rows=1000 width=244) (actual time=0.460..301.648 rows=1000 loops=1) Merge Cond:
(a.thousand= b.hundred) -> Index Scan using tenk1_thous_tenthous on tenk1 a (cost=0.00..1702.20 rows=10000
width=244)(actual time=0.156..11.762 rows=1001 loops=1) -> Materialize (cost=0.00..1727.16 rows=10000 width=4)
(actualtime=0.231..208.458 rows=10000 loops=1) -> Index Scan using tenk1_hundred on tenk1 b
(cost=0.00..1702.16rows=10000 width=4) (actual time=0.188..111.263 rows=10000 loops=1)Total runtime: 306.712 ms
(6 rows)
regression=# explain analyze select * from tenk1 a where exists(select 1 from tenk1 b where a.thousand = b.hundred and
a.four= b.ten); QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------Merge
SemiJoin (cost=0.00..3624.88 rows=1000 width=244) (actual time=0.486..1035.129 rows=200 loops=1) Merge Cond:
(a.thousand= b.hundred) Join Filter: (a.four = b.ten) Rows Removed by Join Filter: 80000 -> Index Scan using
tenk1_thous_tenthouson tenk1 a (cost=0.00..1702.20 rows=10000 width=244) (actual time=0.164..11.507 rows=1001 loops=1)
-> Materialize (cost=0.00..1727.16 rows=10000 width=8) (actual time=0.232..477.475 rows=81991 loops=1) ->
IndexScan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=10000 width=8) (actual time=0.191..112.566
rows=10000loops=1)Total runtime: 1037.360 ms
(8 rows)
This is where somebody might get confused --- if there's only 1000 rows
emitted by the non-filtered version, how did 80000 rows get removed in
the filtered one? But still, hiding that information isn't terribly
helpful IMO, because if you were wondering why the mergejoin node took
4X longer to emit 5X fewer rows than before, the behavior of the filter
would be a valuable clue.
Last, the antijoin equivalent:
regression=# explain analyze select * from tenk1 a where not exists(select 1 from tenk1 b where a.thousand = b.hundred
); QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------Merge
AntiJoin (cost=0.00..4929.36 rows=9000 width=244) (actual time=296.501..481.179 rows=9000 loops=1) Merge Cond:
(a.thousand= b.hundred) -> Index Scan using tenk1_thous_tenthous on tenk1 a (cost=0.00..1702.20 rows=10000
width=244)(actual time=0.150..112.933 rows=10000 loops=1) -> Materialize (cost=0.00..1727.16 rows=10000 width=4)
(actualtime=0.228..209.522 rows=10000 loops=1) -> Index Scan using tenk1_hundred on tenk1 b
(cost=0.00..1702.16rows=10000 width=4) (actual time=0.188..111.769 rows=10000 loops=1)Total runtime: 514.568 ms
(6 rows)
regression=# explain analyze select * from tenk1 a where not exists(select 1 from tenk1 b where a.thousand = b.hundred
anda.four = b.ten); QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------Merge
AntiJoin (cost=0.00..5179.36 rows=9000 width=244) (actual time=16.105..1266.661 rows=9800 loops=1) Merge Cond:
(a.thousand= b.hundred) Join Filter: (a.four = b.ten) Rows Removed by Join Filter: 80000 -> Index Scan using
tenk1_thous_tenthouson tenk1 a (cost=0.00..1702.20 rows=10000 width=244) (actual time=0.157..113.719 rows=10000
loops=1) -> Materialize (cost=0.00..1727.16 rows=10000 width=8) (actual time=0.231..497.882 rows=81991 loops=1)
-> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=10000 width=8) (actual time=0.189..115.980
rows=10000loops=1)Total runtime: 1302.973 ms
(8 rows)
Again, the large number of removed rows does provide a useful
performance clue, even if it seems like the numbers don't add up.
It's possible that we could make the LEFT JOIN examples less confusing
if we were to add an additional counter (and display row) that shows the
number of null-extended rows added by the join mechanism. However, I
don't immediately see how to apply that idea to semi/anti joins.
regards, tom lane
Here's a revised version of the patch that behaves in a way that seems
reasonable to me, in particular it suppresses zero filter-count rows in
text mode. I've not done anything yet about the documentation.
regards, tom lane
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 6408d1653b33706be0780aac3b4a9558d12c9056..cd9fc929232b0eb721dd68e3d7a32b9216e5df91 100644
*** a/src/backend/commands/explain.c
--- b/src/backend/commands/explain.c
***************
*** 18,24 ****
#include "commands/defrem.h"
#include "commands/prepare.h"
#include "executor/hashjoin.h"
- #include "executor/instrument.h"
#include "foreign/fdwapi.h"
#include "optimizer/clauses.h"
#include "parser/parsetree.h"
--- 18,23 ----
*************** static void show_sort_keys_common(PlanSt
*** 76,81 ****
--- 75,82 ----
List *ancestors, ExplainState *es);
static void show_sort_info(SortState *sortstate, ExplainState *es);
static void show_hash_info(HashState *hashstate, ExplainState *es);
+ static void show_instrumentation_count(const char *qlabel, int which,
+ PlanState *planstate, ExplainState *es);
static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es);
static const char *explain_get_index_name(Oid indexId);
static void ExplainScanTarget(Scan *plan, ExplainState *es);
*************** ExplainNode(PlanState *planstate, List *
*** 1000,1008 ****
--- 1001,1015 ----
case T_IndexScan:
show_scan_qual(((IndexScan *) plan)->indexqualorig,
"Index Cond", planstate, ancestors, es);
+ if (((IndexScan *) plan)->indexqualorig)
+ show_instrumentation_count("Rows Removed by Index Recheck", 2,
+ planstate, es);
show_scan_qual(((IndexScan *) plan)->indexorderbyorig,
"Order By", planstate, ancestors, es);
show_scan_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
break;
case T_BitmapIndexScan:
show_scan_qual(((BitmapIndexScan *) plan)->indexqualorig,
*************** ExplainNode(PlanState *planstate, List *
*** 1011,1016 ****
--- 1018,1026 ----
case T_BitmapHeapScan:
show_scan_qual(((BitmapHeapScan *) plan)->bitmapqualorig,
"Recheck Cond", planstate, ancestors, es);
+ if (((BitmapHeapScan *) plan)->bitmapqualorig)
+ show_instrumentation_count("Rows Removed by Index Recheck", 2,
+ planstate, es);
/* FALL THRU */
case T_SeqScan:
case T_ValuesScan:
*************** ExplainNode(PlanState *planstate, List *
*** 1018,1023 ****
--- 1028,1036 ----
case T_WorkTableScan:
case T_SubqueryScan:
show_scan_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
break;
case T_FunctionScan:
if (es->verbose)
*************** ExplainNode(PlanState *planstate, List *
*** 1025,1030 ****
--- 1038,1046 ----
"Function Call", planstate, ancestors,
es->verbose, es);
show_scan_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
break;
case T_TidScan:
{
*************** ExplainNode(PlanState *planstate, List *
*** 1038,1071 ****
--- 1054,1114 ----
tidquals = list_make1(make_orclause(tidquals));
show_scan_qual(tidquals, "TID Cond", planstate, ancestors, es);
show_scan_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
}
break;
case T_ForeignScan:
show_scan_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
show_foreignscan_info((ForeignScanState *) planstate, es);
break;
case T_NestLoop:
show_upper_qual(((NestLoop *) plan)->join.joinqual,
"Join Filter", planstate, ancestors, es);
+ if (((NestLoop *) plan)->join.joinqual)
+ show_instrumentation_count("Rows Removed by Join Filter", 1,
+ planstate, es);
show_upper_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 2,
+ planstate, es);
break;
case T_MergeJoin:
show_upper_qual(((MergeJoin *) plan)->mergeclauses,
"Merge Cond", planstate, ancestors, es);
show_upper_qual(((MergeJoin *) plan)->join.joinqual,
"Join Filter", planstate, ancestors, es);
+ if (((MergeJoin *) plan)->join.joinqual)
+ show_instrumentation_count("Rows Removed by Join Filter", 1,
+ planstate, es);
show_upper_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 2,
+ planstate, es);
break;
case T_HashJoin:
show_upper_qual(((HashJoin *) plan)->hashclauses,
"Hash Cond", planstate, ancestors, es);
show_upper_qual(((HashJoin *) plan)->join.joinqual,
"Join Filter", planstate, ancestors, es);
+ if (((HashJoin *) plan)->join.joinqual)
+ show_instrumentation_count("Rows Removed by Join Filter", 1,
+ planstate, es);
show_upper_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 2,
+ planstate, es);
break;
case T_Agg:
case T_Group:
show_upper_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
break;
case T_Sort:
show_sort_keys((SortState *) planstate, ancestors, es);
*************** ExplainNode(PlanState *planstate, List *
*** 1079,1084 ****
--- 1122,1130 ----
show_upper_qual((List *) ((Result *) plan)->resconstantqual,
"One-Time Filter", planstate, ancestors, es);
show_upper_qual(plan->qual, "Filter", planstate, ancestors, es);
+ if (plan->qual)
+ show_instrumentation_count("Rows Removed by Filter", 1,
+ planstate, es);
break;
case T_Hash:
show_hash_info((HashState *) planstate, es);
*************** show_hash_info(HashState *hashstate, Exp
*** 1509,1514 ****
--- 1555,1591 ----
}
/*
+ * If it's EXPLAIN ANALYZE, show instrumentation information for a plan node
+ *
+ * "which" identifies which instrumentation counter to print
+ */
+ static void
+ show_instrumentation_count(const char *qlabel, int which,
+ PlanState *planstate, ExplainState *es)
+ {
+ double nfiltered;
+ double nloops;
+
+ if (!es->analyze || !planstate->instrument)
+ return;
+
+ if (which == 2)
+ nfiltered = planstate->instrument->nfiltered2;
+ else
+ nfiltered = planstate->instrument->nfiltered1;
+ nloops = planstate->instrument->nloops;
+
+ /* In text mode, suppress zero counts; they're not interesting enough */
+ if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT)
+ {
+ if (nloops > 0)
+ ExplainPropertyFloat(qlabel, nfiltered / nloops, 0, es);
+ else
+ ExplainPropertyFloat(qlabel, 0.0, 0, es);
+ }
+ }
+
+ /*
* Show extra information for a ForeignScan node.
*/
static void
diff --git a/src/backend/commands/trigger.c b/src/backend/commands/trigger.c
index 680962aa44499b67478075ad62cc9c0f8e079e0b..06d368e07736f73529797df31a4f143a784202b9 100644
*** a/src/backend/commands/trigger.c
--- b/src/backend/commands/trigger.c
***************
*** 29,35 ****
#include "commands/defrem.h"
#include "commands/trigger.h"
#include "executor/executor.h"
- #include "executor/instrument.h"
#include "miscadmin.h"
#include "nodes/bitmapset.h"
#include "nodes/makefuncs.h"
--- 29,34 ----
diff --git a/src/backend/executor/execAmi.c b/src/backend/executor/execAmi.c
index ffdcc966ee60a3b0edbf5ea26241e0f47d903663..711e8c778664123d996c69f62196d0e5247c28b9 100644
*** a/src/backend/executor/execAmi.c
--- b/src/backend/executor/execAmi.c
***************
*** 13,19 ****
#include "postgres.h"
#include "executor/execdebug.h"
- #include "executor/instrument.h"
#include "executor/nodeAgg.h"
#include "executor/nodeAppend.h"
#include "executor/nodeBitmapAnd.h"
--- 13,18 ----
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 1dfe8b9ac7823f8c92468178991107931a858ff5..fd7a9ed0339eed73b1523d84cacb8e8df55eb3f5 100644
*** a/src/backend/executor/execMain.c
--- b/src/backend/executor/execMain.c
***************
*** 47,53 ****
#include "commands/tablespace.h"
#include "commands/trigger.h"
#include "executor/execdebug.h"
- #include "executor/instrument.h"
#include "miscadmin.h"
#include "optimizer/clauses.h"
#include "parser/parse_clause.h"
--- 47,52 ----
diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c
index 17788761d7f101319388f8ad7a6cb964efe140f3..8bdfad2222380c9b7c4e88919267116f231d1d20 100644
*** a/src/backend/executor/execProcnode.c
--- b/src/backend/executor/execProcnode.c
***************
*** 77,83 ****
#include "postgres.h"
#include "executor/executor.h"
- #include "executor/instrument.h"
#include "executor/nodeAgg.h"
#include "executor/nodeAppend.h"
#include "executor/nodeBitmapAnd.h"
--- 77,82 ----
diff --git a/src/backend/executor/execScan.c b/src/backend/executor/execScan.c
index e90058847d9de9bb8554dd5548607429b1694b1d..d4ed2358564de38201e0cef120d98b3315be794a 100644
*** a/src/backend/executor/execScan.c
--- b/src/backend/executor/execScan.c
*************** ExecScan(ScanState *node,
*** 219,224 ****
--- 219,226 ----
return slot;
}
}
+ else
+ InstrCountFiltered1(node, 1);
/*
* Tuple fails qual, so free per-tuple memory and try again.
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index bf9bf12ab6a3bf9cbc764a704971cdc47dccaef2..9d30200ab3c311928e35b1748bfee037d8d097a1 100644
*** a/src/backend/executor/instrument.c
--- b/src/backend/executor/instrument.c
*************** BufferUsage pgBufferUsage;
*** 22,27 ****
--- 22,28 ----
static void BufferUsageAccumDiff(BufferUsage *dst,
const BufferUsage *add, const BufferUsage *sub);
+
/* Allocate new instrumentation structure(s) */
Instrumentation *
InstrAlloc(int n, int instrument_options)
*************** InstrAlloc(int n, int instrument_options
*** 31,43 ****
/* timer is always required for now */
Assert(instrument_options & INSTRUMENT_TIMER);
instr = palloc0(n * sizeof(Instrumentation));
if (instrument_options & INSTRUMENT_BUFFERS)
{
int i;
for (i = 0; i < n; i++)
! instr[i].needs_bufusage = true;
}
return instr;
--- 32,45 ----
/* timer is always required for now */
Assert(instrument_options & INSTRUMENT_TIMER);
+ /* initialize all fields to zeroes, then modify as needed */
instr = palloc0(n * sizeof(Instrumentation));
if (instrument_options & INSTRUMENT_BUFFERS)
{
int i;
for (i = 0; i < n; i++)
! instr[i].need_bufusage = true;
}
return instr;
*************** InstrStartNode(Instrumentation *instr)
*** 52,59 ****
else
elog(DEBUG2, "InstrStartNode called twice in a row");
! /* initialize buffer usage per plan node */
! if (instr->needs_bufusage)
instr->bufusage_start = pgBufferUsage;
}
--- 54,61 ----
else
elog(DEBUG2, "InstrStartNode called twice in a row");
! /* save buffer usage totals at node entry, if needed */
! if (instr->need_bufusage)
instr->bufusage_start = pgBufferUsage;
}
*************** InstrStopNode(Instrumentation *instr, do
*** 77,84 ****
INSTR_TIME_SET_ZERO(instr->starttime);
! /* Adds delta of buffer usage to node's count. */
! if (instr->needs_bufusage)
BufferUsageAccumDiff(&instr->bufusage,
&pgBufferUsage, &instr->bufusage_start);
--- 79,86 ----
INSTR_TIME_SET_ZERO(instr->starttime);
! /* Add delta of buffer usage since entry to node's totals */
! if (instr->need_bufusage)
BufferUsageAccumDiff(&instr->bufusage,
&pgBufferUsage, &instr->bufusage_start);
*************** InstrEndLoop(Instrumentation *instr)
*** 119,130 ****
instr->tuplecount = 0;
}
static void
BufferUsageAccumDiff(BufferUsage *dst,
const BufferUsage *add,
const BufferUsage *sub)
{
- /* dst += add - sub */
dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
--- 121,132 ----
instr->tuplecount = 0;
}
+ /* dst += add - sub */
static void
BufferUsageAccumDiff(BufferUsage *dst,
const BufferUsage *add,
const BufferUsage *sub)
{
dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
diff --git a/src/backend/executor/nodeAgg.c b/src/backend/executor/nodeAgg.c
index 13d7723480144575103dc2efb42c10296dd565f8..e769d6d012c4422ee905c6417375e4d629316f26 100644
*** a/src/backend/executor/nodeAgg.c
--- b/src/backend/executor/nodeAgg.c
*************** agg_retrieve_direct(AggState *aggstate)
*** 1204,1209 ****
--- 1204,1211 ----
return result;
}
}
+ else
+ InstrCountFiltered1(aggstate, 1);
}
/* No more groups */
*************** agg_retrieve_hash_table(AggState *aggsta
*** 1354,1359 ****
--- 1356,1363 ----
return result;
}
}
+ else
+ InstrCountFiltered1(aggstate, 1);
}
/* No more groups */
diff --git a/src/backend/executor/nodeBitmapAnd.c b/src/backend/executor/nodeBitmapAnd.c
index 82308cba2609251ff045089dad20d8892b67b79b..5f318c31e7796e9f477bf217da214171cfcd1231 100644
*** a/src/backend/executor/nodeBitmapAnd.c
--- b/src/backend/executor/nodeBitmapAnd.c
***************
*** 29,35 ****
#include "postgres.h"
#include "executor/execdebug.h"
- #include "executor/instrument.h"
#include "executor/nodeBitmapAnd.h"
--- 29,34 ----
diff --git a/src/backend/executor/nodeBitmapHeapscan.c b/src/backend/executor/nodeBitmapHeapscan.c
index 8e50fb1aaef4ba8a0418da5f8d077058c5a71ce2..4a8920e6ce842eb7d027f7415d3c415e7d8d00b8 100644
*** a/src/backend/executor/nodeBitmapHeapscan.c
--- b/src/backend/executor/nodeBitmapHeapscan.c
*************** BitmapHeapNext(BitmapHeapScanState *node
*** 278,283 ****
--- 278,284 ----
if (!ExecQual(node->bitmapqualorig, econtext, false))
{
/* Fails recheck, so drop it and loop back for another */
+ InstrCountFiltered2(node, 1);
ExecClearTuple(slot);
continue;
}
diff --git a/src/backend/executor/nodeBitmapIndexscan.c b/src/backend/executor/nodeBitmapIndexscan.c
index 9a56fd4b9fda06666fb3e42d6c8e7a306e81b44d..8e1df079b3728d69cdcae13b1eeec538bb469311 100644
*** a/src/backend/executor/nodeBitmapIndexscan.c
--- b/src/backend/executor/nodeBitmapIndexscan.c
***************
*** 22,28 ****
#include "postgres.h"
#include "executor/execdebug.h"
- #include "executor/instrument.h"
#include "executor/nodeBitmapIndexscan.h"
#include "executor/nodeIndexscan.h"
#include "miscadmin.h"
--- 22,27 ----
diff --git a/src/backend/executor/nodeBitmapOr.c b/src/backend/executor/nodeBitmapOr.c
index 4b064b79a96234ca44de20077936b478cef0f2b2..d2453d5a4f0a5a96df1d7041f22c14cf11027082 100644
*** a/src/backend/executor/nodeBitmapOr.c
--- b/src/backend/executor/nodeBitmapOr.c
***************
*** 29,35 ****
#include "postgres.h"
#include "executor/execdebug.h"
- #include "executor/instrument.h"
#include "executor/nodeBitmapOr.h"
#include "miscadmin.h"
--- 29,34 ----
diff --git a/src/backend/executor/nodeGroup.c b/src/backend/executor/nodeGroup.c
index fa403e5406c04f68afefcee8322ddeeb6c7dd74f..7bef8bbe8b9c074c6b8fd22dc5e7ec720020b78b 100644
*** a/src/backend/executor/nodeGroup.c
--- b/src/backend/executor/nodeGroup.c
*************** ExecGroup(GroupState *node)
*** 118,123 ****
--- 118,125 ----
return result;
}
}
+ else
+ InstrCountFiltered1(node, 1);
}
/*
*************** ExecGroup(GroupState *node)
*** 179,184 ****
--- 181,188 ----
return result;
}
}
+ else
+ InstrCountFiltered1(node, 1);
}
/* NOTREACHED */
diff --git a/src/backend/executor/nodeHash.c b/src/backend/executor/nodeHash.c
index 2ade2d7fad6b3f190cb0c9d17117b4d140c32d8d..e72a71bf51bf71e6b3c9a300e17fa8875e8e78e8 100644
*** a/src/backend/executor/nodeHash.c
--- b/src/backend/executor/nodeHash.c
***************
*** 28,34 ****
#include "commands/tablespace.h"
#include "executor/execdebug.h"
#include "executor/hashjoin.h"
- #include "executor/instrument.h"
#include "executor/nodeHash.h"
#include "executor/nodeHashjoin.h"
#include "miscadmin.h"
--- 28,33 ----
diff --git a/src/backend/executor/nodeHashjoin.c b/src/backend/executor/nodeHashjoin.c
index 3a6698105f278398a2317555cf0731a24cf9b106..c3c4db4bc2ce047d1db36b4894e6d591a0d97305 100644
*** a/src/backend/executor/nodeHashjoin.c
--- b/src/backend/executor/nodeHashjoin.c
*************** ExecHashJoin(HashJoinState *node)
*** 325,331 ****
--- 325,335 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
}
+ else
+ InstrCountFiltered1(node, 1);
break;
case HJ_FILL_OUTER_TUPLE:
*************** ExecHashJoin(HashJoinState *node)
*** 360,365 ****
--- 364,371 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
}
break;
*************** ExecHashJoin(HashJoinState *node)
*** 397,402 ****
--- 403,410 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
break;
case HJ_NEED_NEW_BATCH:
diff --git a/src/backend/executor/nodeIndexscan.c b/src/backend/executor/nodeIndexscan.c
index 955008e012d56d0a8bb42c0c78719944fe41c7d1..da25384e860df509cc40921911b5d84b95ec9f21 100644
*** a/src/backend/executor/nodeIndexscan.c
--- b/src/backend/executor/nodeIndexscan.c
*************** IndexNext(IndexScanState *node)
*** 96,102 ****
econtext->ecxt_scantuple = slot;
ResetExprContext(econtext);
if (!ExecQual(node->indexqualorig, econtext, false))
! continue; /* nope, so ask index for another one */
}
return slot;
--- 96,106 ----
econtext->ecxt_scantuple = slot;
ResetExprContext(econtext);
if (!ExecQual(node->indexqualorig, econtext, false))
! {
! /* Fails recheck, so drop it and loop back for another */
! InstrCountFiltered2(node, 1);
! continue;
! }
}
return slot;
diff --git a/src/backend/executor/nodeMergejoin.c b/src/backend/executor/nodeMergejoin.c
index e23dd6c9f540c279314a888e544310e08763d514..deaa79ed9fbddfa5397887439085f499a5981259 100644
*** a/src/backend/executor/nodeMergejoin.c
--- b/src/backend/executor/nodeMergejoin.c
*************** MJFillOuter(MergeJoinState *node)
*** 505,510 ****
--- 505,512 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
return NULL;
}
*************** MJFillInner(MergeJoinState *node)
*** 544,549 ****
--- 546,553 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
return NULL;
}
*************** ExecMergeJoin(MergeJoinState *node)
*** 893,899 ****
--- 897,907 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
}
+ else
+ InstrCountFiltered1(node, 1);
break;
/*
diff --git a/src/backend/executor/nodeNestloop.c b/src/backend/executor/nodeNestloop.c
index e98bc0f5a308bd27bd624c6342e4a22fffe530a7..49b880d0caf013e18a3a5c2e2677069bef9568d1 100644
*** a/src/backend/executor/nodeNestloop.c
--- b/src/backend/executor/nodeNestloop.c
*************** ExecNestLoop(NestLoopState *node)
*** 214,219 ****
--- 214,221 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
}
/*
*************** ExecNestLoop(NestLoopState *node)
*** 270,276 ****
--- 272,282 ----
return result;
}
}
+ else
+ InstrCountFiltered2(node, 1);
}
+ else
+ InstrCountFiltered1(node, 1);
/*
* Tuple fails qual, so free per-tuple memory and try again.
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 286cd540632258855e31ab9ae3fbd391576d4b97..22c310694365056a4aca06a3c71a5538bd9c21f7 100644
*** a/src/include/executor/instrument.h
--- b/src/include/executor/instrument.h
*************** typedef struct BufferUsage
*** 28,33 ****
--- 28,34 ----
long temp_blks_written; /* # of temp blocks written */
} BufferUsage;
+ /* Flag bits included in InstrAlloc's instrument_options bitmask */
typedef enum InstrumentOption
{
INSTRUMENT_TIMER = 1 << 0, /* needs timer */
*************** typedef enum InstrumentOption
*** 37,45 ****
typedef struct Instrumentation
{
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */
- bool needs_bufusage; /* TRUE if we need buffer usage */
instr_time starttime; /* Start time of current iteration of node */
instr_time counter; /* Accumulated runtime for this node */
double firsttuple; /* Time for first tuple of this cycle */
--- 38,47 ----
typedef struct Instrumentation
{
+ /* Parameters set at node creation: */
+ bool need_bufusage; /* TRUE if we need buffer usage data */
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */
instr_time starttime; /* Start time of current iteration of node */
instr_time counter; /* Accumulated runtime for this node */
double firsttuple; /* Time for first tuple of this cycle */
*************** typedef struct Instrumentation
*** 50,55 ****
--- 52,59 ----
double total; /* Total total time (in seconds) */
double ntuples; /* Total tuples produced */
double nloops; /* # of run cycles for this node */
+ double nfiltered1; /* # tuples removed by scanqual or joinqual */
+ double nfiltered2; /* # tuples removed by "other" quals */
BufferUsage bufusage; /* Total buffer usage */
} Instrumentation;
diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h
index b3eed7d189cb81b61c84b18157fa3fcdd5b19456..c8a0b5986457f2b4e323934ff101876766ddca59 100644
*** a/src/include/nodes/execnodes.h
--- b/src/include/nodes/execnodes.h
***************
*** 16,21 ****
--- 16,22 ----
#include "access/genam.h"
#include "access/heapam.h"
+ #include "executor/instrument.h"
#include "nodes/params.h"
#include "nodes/plannodes.h"
#include "utils/reltrigger.h"
*************** typedef struct ResultRelInfo
*** 314,320 ****
TriggerDesc *ri_TrigDesc;
FmgrInfo *ri_TrigFunctions;
List **ri_TrigWhenExprs;
! struct Instrumentation *ri_TrigInstrument;
List **ri_ConstraintExprs;
JunkFilter *ri_junkFilter;
ProjectionInfo *ri_projectReturning;
--- 315,321 ----
TriggerDesc *ri_TrigDesc;
FmgrInfo *ri_TrigFunctions;
List **ri_TrigWhenExprs;
! Instrumentation *ri_TrigInstrument;
List **ri_ConstraintExprs;
JunkFilter *ri_junkFilter;
ProjectionInfo *ri_projectReturning;
*************** typedef struct PlanState
*** 967,974 ****
* nodes point to one EState for the whole
* top-level plan */
! struct Instrumentation *instrument; /* Optional runtime stats for this
! * plan node */
/*
* Common structural data for all Plan types. These links to subsidiary
--- 968,974 ----
* nodes point to one EState for the whole
* top-level plan */
! Instrumentation *instrument; /* Optional runtime stats for this node */
/*
* Common structural data for all Plan types. These links to subsidiary
*************** typedef struct PlanState
*** 1008,1013 ****
--- 1008,1025 ----
#define innerPlanState(node) (((PlanState *)(node))->righttree)
#define outerPlanState(node) (((PlanState *)(node))->lefttree)
+ /* Macros for inline access to certain instrumentation counters */
+ #define InstrCountFiltered1(node, delta) \
+ do { \
+ if (((PlanState *)(node))->instrument) \
+ ((PlanState *)(node))->instrument->nfiltered1 += (delta); \
+ } while(0)
+ #define InstrCountFiltered2(node, delta) \
+ do { \
+ if (((PlanState *)(node))->instrument) \
+ ((PlanState *)(node))->instrument->nfiltered2 += (delta); \
+ } while(0)
+
/*
* EPQState is state for executing an EvalPlanQual recheck on a candidate
* tuple in ModifyTable or LockRows. The estate and planstate fields are
On 22.09.2011 07:51, Tom Lane wrote: > Here's a revised version of the patch that behaves in a way that seems > reasonable to me, in particular it suppresses zero filter-count rows in > text mode. I've not done anything yet about the documentation. I haven't been following this closely, so sorry if this has already been discussed, but: I find it a bit strange to print the number of lines filtered out. I think that's the only place where we would print a "negative" like that, everywhere else we print the number of lines let through a node. How about printing the number of lines that enter the filter, instead? -- Heikki Linnakangas EnterpriseDB http://www.enterprisedb.com
Heikki Linnakangas <heikki.linnakangas@enterprisedb.com> writes:
> I haven't been following this closely, so sorry if this has already been
> discussed, but:
> I find it a bit strange to print the number of lines filtered out. I
> think that's the only place where we would print a "negative" like that,
> everywhere else we print the number of lines let through a node. How
> about printing the number of lines that enter the filter, instead?
Yeah, I thought seriously about that too. The problem with it is that
you end up having to print that line all the time, whether or not it
adds any knowledge. The "filter removed N rows" approach has the saving
grace that you can leave it out when no filtering is happening. Another
point is that if you have two filters operating at a node, printing only
the starting number of rows doesn't let you disentangle which filter did
how much.
Now having said that, I could still be talked into the other way if
someone had a design that accounted for outer/semi/anti-join behavior
more clearly than this does. I thought for a little bit that printing
the starting number of rows might offer such a solution, but on
inspection it didn't really seem to help.
regards, tom lane
On Thu, Sep 22, 2011 at 02:41:12AM -0400, Tom Lane wrote: > Yeah, I thought seriously about that too. The problem with it is that > you end up having to print that line all the time, whether or not it > adds any knowledge. The "filter removed N rows" approach has the saving > grace that you can leave it out when no filtering is happening. Another > point is that if you have two filters operating at a node, printing only > the starting number of rows doesn't let you disentangle which filter did > how much. I wonder if it would be more useful to print a percentage. If 0% is filtered out you can still drop it but it gives a more useful output if the number of rows is really large. Have a nice day, -- Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/ > He who writes carelessly confesses thereby at the very outset that he does > not attach much importance to his own thoughts. -- Arthur Schopenhauer