Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-22 Thread Martijn van Oosterhout 
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  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


signature.asc
Description: Digital signature

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-21 Thread Tom Lane 
Heikki Linnakangas  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

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

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-21 Thread Heikki Linnakangas 

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

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

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-21 Thread 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, e

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-21 Thread Tom Lane 
Robert Haas  writes:
> On Tue, Sep 20, 2011 at 8:19 PM, Tom Lane  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=10 width=488) (actual 
time=0.449..1678.464 rows=10 loops=1)
   Merge Cond: (b.hundred = a.thousand)
   ->  Index Scan using tenk1_hundred on tenk1 b  (cost=0.00..1702.16 
rows=1 width=244) (actual time=0.228..117.637 rows=1 loops=1)
   ->  Materialize  (cost=0.00..1727.20 rows=1 width=244) (actual 
time=0.154..431.251 rows=11 loops=1)
 ->  Index Scan using tenk1_thous_tenthous on tenk1 a  
(cost=0.00..1702.20 rows=1 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=1 width=488) (actual 
time=0.657..1314.394 rows=2 loops=1)
   Merge Cond: (b.hundred = a.thousand)
   Join Filter: (a.four = b.ten)
   Rows Removed by Join Filter: 8
   ->  Index Scan using tenk1_hundred on tenk1 b  (cost=0.00..1702.16 
rows=1 width=244) (actual time=0.395..110.506 rows=1 loops=1)
   ->  Materialize  (cost=0.00..1727.20 rows=1 width=244) (actual 
time=0.165..390.867 rows=11 loops=1)
 ->  Index Scan using tenk1_thous_tenthous on tenk1 a  
(cost=0.00..1702.20 rows=1 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  
   
---

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-20 Thread Robert Haas 
On Tue, Sep 20, 2011 at 8:19 PM, Tom Lane  wrote:
> Marko Tiikkaja  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

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

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-20 Thread Tom Lane 
Marko Tiikkaja  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

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

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-20 Thread Tom Lane 
Marko Tiikkaja  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

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

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-12 Thread Marko Tiikkaja 

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 Tiikkajahttp://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 6408d16..1f42f46 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -64,9 +64,15 @@ static void show_qual(List *qual, const char *qlabel,
 static void show_scan_qual(List *qual, const char *qlabel,
   PlanState *planstate, List *ancestors,
   ExplainState *es);
+static void show_instrumented_scan_qual(List *qual, const char *qlabel,
+   PlanState *planstate, double nremoved,
+   List *ancestors, ExplainState *es);
 static void show_upper_qual(List *qual, const char *qlabel,
PlanState *planstate, List *ancestors,
ExplainState *es);
+static void show_instrumented_upper_qual(List *qual, const char *qlabel,
+   PlanState *planstate, double nremoved,
+   List *ancestors, ExplainState *es);
 static void show_sort_keys(SortState *sortstate, List *ancestors,
   ExplainState *es);
 static void show_merge_append_keys(MergeAppendState *mstate, List *ancestors,
@@ -1002,29 +1008,37 @@ ExplainNode(PlanState *planstate, List *ancestors,
   "Index Cond", planstate, 
ancestors, es);
show_scan_qual(((IndexScan *) plan)->indexorderbyorig,
   "Order By", planstate, 
ancestors, es);
-   show_scan_qual(plan->qual, "Filter", planstate, 
ancestors, es);
+   show_instrumented_scan_qual(plan->qual, "Filter", 
planstate,
+   
((ScanState *) planstate)->ss_qualnremoved,
+   
ancestors, es);
break;
case T_BitmapIndexScan:
show_scan_qual(((BitmapIndexScan *) 
plan)->indexqualorig,
   "Index Cond", planstate, 
ancestors, es);
break;
case T_BitmapHeapScan:
-   show_scan_qual(((BitmapHeapScan *) 
plan)->bitmapqualorig,
-  "Recheck Cond", planstate, 
ancestors, es);
+   show_instrumented_scan_qual(((BitmapHeapScan *) 
plan)->bitmapqualorig,
+   
"Recheck Cond", planstate,
+   
((BitmapHeapScanState *) planstate)->bqonremoved,
+   
ancestors, es);
/* FALL THRU */
case T_SeqScan:
case T_ValuesScan:
case T_CteScan:
case T_WorkTableScan:
case T_SubqueryScan:
-   show_scan_qual(plan->qual, "Filter", planstate, 
ancestors, es);
+   show_instrumented_scan_qual(plan->qual, "Filter", 
planstate,
+   
((ScanState *) planstate)->ss_qualnremoved,
+   
ancestors, es);
break;
case T_FunctionScan:
if (es->verbose)
show_expression(((FunctionScan *) 
plan)->funcexpr,
"Function 
Call", planstate, ancestors,
es->verbose, 
es);
-   show_scan_qual(plan->qual, "Filter", planstate, 
ancestors, es);
+   show_instrumented_scan_qual(plan->qual, "Filter", 
planstate,
+   
((ScanState *) planstate)->ss_qualnremoved,
+   
ancestors, es);
break;

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-12 Thread Marko Tiikkaja 

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 Tiikkajahttp://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

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

Re: [HACKERS] EXPLAIN and nfiltered, take two

2011-09-10 Thread Marti Raudsepp 
Hi!

On Thu, Sep 8, 2011 at 15:11, Marko Tiikkaja
 wrote:
> Here's a patch for $SUBJECT based on the feedback here:
> http://archives.postgresql.org/message-id/9053.1295888...@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

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

[HACKERS] EXPLAIN and nfiltered, take two

2011-09-08 Thread Marko Tiikkaja 

Hi,

Here's a patch for $SUBJECT based on the feedback here:
http://archives.postgresql.org/message-id/9053.1295888...@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 Tiikkajahttp://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
BEGIN
CREATE TABLE
CREATE TABLE
CREATE TABLE
INSERT 0 20
INSERT 0 10
INSERT 0 10
CREATE INDEX
CREATE SERVER
CREATE FOREIGN TABLE
CREATE FUNCTION
SET
SET
SET
SET
SET
SET
SET
SET
SET
   QUERY PLAN   
 
-
 Index Scan using foo_a_index on big_table  (cost=0.00..2588.27 rows=333 
width=8) (actual time=1.488..47.456 rows=65000 loops=1)
   Index Cond: (a = 2)
   Filter: (b > 5000)
   Rows Removed by Filter: 1667
 Total runtime: 57.127 ms
(5 rows)

SET
SET
SET
  QUERY PLAN
  
--
 Bitmap Heap Scan on big_table  (cost=19.86..961.93 rows=333 width=8) (actual 
time=13.673..67.979 rows=65000 loops=1)
   Recheck Cond: (a = 2)
   Rows Removed by Recheck Cond: 62526
   Filter: (b > 5000)
   Rows Removed by Filter: 1667
   ->  Bitmap Index Scan on foo_a_index  (cost=0.00..19.77 rows=1000 width=0) 
(actual time=12.309..12.309 rows=7 loops=1)
 Index Cond: (a = 2)
 Total runtime: 78.757 ms
(8 rows)

RESET
SET
SET
   QUERY PLAN   


 Seq Scan on foo  (cost=0.00..36.75 rows=713 width=8) (actual time=0.008..0.010 
rows=5 loops=1)
   Filter: (a > 5)
   Rows Removed by Filter: 5
 Total runtime: 0.031 ms
(4 rows)

  QUERY PLAN
   
---
 Values Scan on "*VALUES*"  (cost=0.00..0.15 rows=3 width=4) (actual 
time=0.021..0.080 rows=5 loops=1)
   Filter: (column1 > 5)
   Rows Removed by Filter: 5
 Total runtime: 0.189 ms
(4 rows)

QUERY PLAN  
  
--
 CTE Scan on t  (cost=3279.93..4052.35 rows=11443 width=4) (actual 
time=0.020..0.033 rows=5 loops=1)
   Filter: (a > 5)
   Rows Removed by Filter: 5
   CTE t
 ->  Recursive Union  (cost=0.00..3279.93 rows=34330 width=4) (actual 
time=0.009..0.025 rows=10 loops=1)
   ->  Function Scan on generate_series i  (cost=0.00..10.00 rows=1000 
width=4) (actual time=0.009..0.009 rows=5 loops=1)
   ->  WorkTable Scan on t  (cost=0.00..258.33 rows= width=4) 
(actual time=0.002..0.003 rows=2 loops=2)
 Filter: ((a + 5) <= 10)
 Rows Removed by Filter: 2
 Total runtime: 0.080 ms
(10 rows)

  QUERY PLAN
  
--
 Subquery Scan on ss  (cost=0.00..58.15 rows=713 width=8) (actual 
time=0.008..0.010 rows=5 loops=1)
   Filter: (ss.i > 5)
   Rows Removed by Filter: 5
   ->  Limit  (cost=0.00..31.40 rows=2140 width=8) (actual time=0.004..0.004 
rows=10 loops=1)
 ->  Seq Scan on foo  (cost=0.00..31.40 rows=2140 width=8) (actual 
time=0.003..0.003 rows=10 loops=1)
 Total runtime: 0.056 ms
(6 rows)

QUERY PLAN  
   
---
 Function Scan on generate_series i  (cost=0.00..12.50 ro