Re: 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

Hi!

On Thu, Sep 8, 2011 at 15:11, Marko Tiikkaja
<marko(dot)tiikkaja(at)2ndquadrant(dot)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

Marko Tiikkaja <marko(dot)tiikkaja(at)2ndquadrant(dot)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(dot)tiikkaja(at)2ndquadrant(dot)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(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Marko Tiikkaja <marko(dot)tiikkaja(at)2ndquadrant(dot)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(at)gmail(dot)com> writes:
> On Tue, Sep 20, 2011 at 8:19 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)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 Scan using 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: 0
Total 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) (actual time=0.228..117.637 rows=10000 loops=1)
-> Materialize (cost=0.00..1727.20 rows=10000 width=244) (actual time=0.154..431.251 rows=100001 loops=1)
-> Index Scan using tenk1_thous_tenthous on tenk1 a (cost=0.00..1702.20 rows=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 tenk1 b (cost=0.00..1702.16 rows=10000 width=244) (actual time=0.395..110.506 rows=10000 loops=1)
-> Materialize (cost=0.00..1727.20 rows=10000 width=244) (actual time=0.165..390.867 rows=100001 loops=1)
-> Index Scan using tenk1_thous_tenthous on tenk1 a (cost=0.00..1702.20 rows=10000 width=244) (actual time=0.121..11.680 rows=1001 loops=1)
Total runtime: 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 Left Join (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) (actual time=0.234..642.645 rows=99991 loops=1)
-> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=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 Left Join (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_tenthous on 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=10000 loops=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 Semi Join (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) (actual time=0.231..208.458 rows=10000 loops=1)
-> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=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 Semi Join (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_tenthous on 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)
-> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=10000 width=8) (actual time=0.191..112.566 rows=10000 loops=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 Anti Join (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) (actual time=0.228..209.522 rows=10000 loops=1)
-> Index Scan using tenk1_hundred on tenk1 b (cost=0.00..1702.16 rows=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 and a.four = b.ten);
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------
Merge Anti Join (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_tenthous on 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=10000 loops=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

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(dot)linnakangas(at)enterprisedb(dot)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(at)svana(dot)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