EXPLAIN and nfiltered
Hi,
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input. The output looks like this:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------
Subquery Scan on ss (cost=0.00..50.00 rows=267 width=4) (actual
time=0.035..0.088 rows=5 filtered=3 loops=1)
Filter: (ss.a < 6)
-> Limit (cost=0.00..40.00 rows=800 width=4) (actual
time=0.031..0.067 rows=8 filtered=0 loops=1)
-> Seq Scan on foo (cost=0.00..40.00 rows=800 width=4)
(actual time=0.027..0.040 rows=8 filtered=2 loops=1)
Filter: (a < 9)
Total runtime: 0.146 ms
(6 rows)
It might be better if the output was on the Filter: line but this was
just the result of a quick idea and I wanted to see how much work the
actual implementation would be.
Any suggestions and comments on the output format, the patch and the
idea are welcome.
Regards,
Marko Tiikkaja
Attachments:
filter.patchtext/plain; charset=iso-8859-1; name=filter.patch; x-mac-creator=0; x-mac-type=0Download
*** a/src/backend/commands/explain.c
--- b/src/backend/commands/explain.c
***************
*** 975,992 **** ExplainNode(PlanState *planstate, List *ancestors,
double startup_sec = 1000.0 * planstate->instrument->startup / nloops;
double total_sec = 1000.0 * planstate->instrument->total / nloops;
double rows = planstate->instrument->ntuples / nloops;
if (es->format == EXPLAIN_FORMAT_TEXT)
{
appendStringInfo(es->str,
! " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
! startup_sec, total_sec, rows, nloops);
}
else
{
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
ExplainPropertyFloat("Actual Rows", rows, 0, es);
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
}
}
--- 975,994 ----
double startup_sec = 1000.0 * planstate->instrument->startup / nloops;
double total_sec = 1000.0 * planstate->instrument->total / nloops;
double rows = planstate->instrument->ntuples / nloops;
+ double filtered = planstate->instrument->nfiltered / nloops;
if (es->format == EXPLAIN_FORMAT_TEXT)
{
appendStringInfo(es->str,
! " (actual time=%.3f..%.3f rows=%.0f filtered=%.0f loops=%.0f)",
! startup_sec, total_sec, rows, filtered, nloops);
}
else
{
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
ExplainPropertyFloat("Actual Rows", rows, 0, es);
+ ExplainPropertyFloat("Rows Filtered", rows, 0, es);
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
}
}
***************
*** 999,1004 **** ExplainNode(PlanState *planstate, List *ancestors,
--- 1001,1007 ----
ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
+ ExplainPropertyFloat("Rows Filtered", 0.0, 0, es);
ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
}
}
*** a/src/backend/executor/execScan.c
--- b/src/backend/executor/execScan.c
***************
*** 19,24 ****
--- 19,25 ----
#include "postgres.h"
#include "executor/executor.h"
+ #include "executor/instrument.h"
#include "miscadmin.h"
#include "utils/memutils.h"
***************
*** 221,226 **** ExecScan(ScanState *node,
--- 222,229 ----
* Tuple fails qual, so free per-tuple memory and try again.
*/
ResetExprContext(econtext);
+ if (node->ps.instrument)
+ node->ps.instrument->nfiltered += 1;;
}
}
*** a/src/include/executor/instrument.h
--- b/src/include/executor/instrument.h
***************
*** 49,54 **** typedef struct Instrumentation
--- 49,55 ----
double startup; /* Total startup time (in seconds) */
double total; /* Total total time (in seconds) */
double ntuples; /* Total tuples produced */
+ double nfiltered; /* Total tuples filtered by qual */
double nloops; /* # of run cycles for this node */
BufferUsage bufusage; /* Total buffer usage */
} Instrumentation;
Marko Tiikkaja <marko.tiikkaja@cs.helsinki.fi> writes:
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input.
I don't like this a whole lot. It's unclear what "filtered" means,
or why it's worth expending precious EXPLAIN ANALYZE output space for.
Also, you've not implemented it for any except scan nodes; and I
think it's not going to be entirely well-defined for join nodes,
since it's somewhat arbitrary which conditions are considered part
of the join qual versus the filter. (That problem will get worse
not better with the planned generalization of inner indexscans,
since there may be join quals in scan nodes.)
regards, tom lane
On 2010-11-18 6:26 PM +0200, Tom Lane wrote:
Marko Tiikkaja<marko.tiikkaja@cs.helsinki.fi> writes:
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input.I don't like this a whole lot. It's unclear what "filtered" means,
or why it's worth expending precious EXPLAIN ANALYZE output space for.
The name can be changed, of course. But I think the idea is good; I
find myself constantly manually finding out how many rows were actually
filtered.
Also, you've not implemented it for any except scan nodes;
That was intentional.
and I
think it's not going to be entirely well-defined for join nodes,
since it's somewhat arbitrary which conditions are considered part
of the join qual versus the filter. (That problem will get worse
not better with the planned generalization of inner indexscans,
since there may be join quals in scan nodes.)
Hmm.. Maybe I'm misunderstanding something, but I don't see that as a
huge problem.
Regards,
Marko Tiikkaja
On Thursday 18 November 2010 16:45:23 Marko Tiikkaja wrote:
Hi,
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input. The output looks like this:
If it supports the same for index-scans I *really* like it and even proposed a
patch earlier (4A16A8AF.2080508@anarazel.de)
I still find myself constantly wishing to have something like that...
Especially when wondering if it might be worthwile to add another column
(which is implemented as an additional qual atm) should get included in a
multiicolumn index.
It was shot down at the time because it might break some explain-parsers
expectations. Imho that argument is less valid these days.
Andres
On 2010-11-18 6:44 PM +0200, Andres Freund wrote:
On Thursday 18 November 2010 16:45:23 Marko Tiikkaja wrote:
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input. The output looks like this:If it supports the same for index-scans I *really* like it and even proposed a
patch earlier (4A16A8AF.2080508@anarazel.de)
I still find myself constantly wishing to have something like that...
Especially when wondering if it might be worthwile to add another column
(which is implemented as an additional qual atm) should get included in a
multiicolumn index.It was shot down at the time because it might break some explain-parsers
expectations. Imho that argument is less valid these days.
I have to admit, I didn't query the archives before looking at this. I
guess I should have. This patch supports all Scan nodes, and I think
that's the right thing to do.
I agree 100% that breaking the parseability (is that a word?) of the
EXPLAIN output is not really an argument these days, so we might want to
give this some thought.
Regards,
Marko Tiikkaja
On Thursday 18 November 2010 17:48:43 Marko Tiikkaja wrote:
On 2010-11-18 6:44 PM +0200, Andres Freund wrote:
On Thursday 18 November 2010 16:45:23 Marko Tiikkaja wrote:
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input. The output looks like this:
If it supports the same for index-scans I *really* like it and even
proposed a patch earlier (4A16A8AF.2080508@anarazel.de)
I still find myself constantly wishing to have something like that...
Especially when wondering if it might be worthwile to add another column
(which is implemented as an additional qual atm) should get included in a
multiicolumn index.It was shot down at the time because it might break some explain-parsers
expectations. Imho that argument is less valid these days.I have to admit, I didn't query the archives before looking at this. I
guess I should have. This patch supports all Scan nodes, and I think
that's the right thing to do.
Uh. No worries. That was my first pg-patch, I doubt it was well-done ;-)
I agree 100% that breaking the parseability (is that a word?) of the
EXPLAIN output is not really an argument these days, so we might want to
give this some thought.
Yes.
Andres
On Thu, Nov 18, 2010 at 10:45 AM, Marko Tiikkaja
<marko.tiikkaja@cs.helsinki.fi> wrote:
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan qual
filtered from a node's input. The output looks like this:
I have wished for this many, MANY times.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
On 2010-11-18 5:45 PM +0200, Marko Tiikkaja wrote:
Here's a patch for showing in EXPLAIN ANALYZE the number of rows a plan
qual filtered from a node's input.
Rebased against master.
Regards,
Marko Tiikkaja
Attachments:
nfiltered.patchtext/plain; charset=iso-8859-1; name=nfiltered.patch; x-mac-creator=0; x-mac-type=0Download
*** a/src/backend/commands/explain.c
--- b/src/backend/commands/explain.c
***************
*** 975,992 **** ExplainNode(PlanState *planstate, List *ancestors,
double startup_sec = 1000.0 * planstate->instrument->startup / nloops;
double total_sec = 1000.0 * planstate->instrument->total / nloops;
double rows = planstate->instrument->ntuples / nloops;
if (es->format == EXPLAIN_FORMAT_TEXT)
{
appendStringInfo(es->str,
! " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
! startup_sec, total_sec, rows, nloops);
}
else
{
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
ExplainPropertyFloat("Actual Rows", rows, 0, es);
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
}
}
--- 975,994 ----
double startup_sec = 1000.0 * planstate->instrument->startup / nloops;
double total_sec = 1000.0 * planstate->instrument->total / nloops;
double rows = planstate->instrument->ntuples / nloops;
+ double filtered = planstate->instrument->nfiltered / nloops;
if (es->format == EXPLAIN_FORMAT_TEXT)
{
appendStringInfo(es->str,
! " (actual time=%.3f..%.3f rows=%.0f filtered=%.0f loops=%.0f)",
! startup_sec, total_sec, rows, filtered, nloops);
}
else
{
ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
ExplainPropertyFloat("Actual Rows", rows, 0, es);
+ ExplainPropertyFloat("Rows Filtered", rows, 0, es);
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
}
}
***************
*** 999,1004 **** ExplainNode(PlanState *planstate, List *ancestors,
--- 1001,1007 ----
ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
+ ExplainPropertyFloat("Rows Filtered", 0.0, 0, es);
ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
}
}
*** a/src/backend/executor/execScan.c
--- b/src/backend/executor/execScan.c
***************
*** 19,24 ****
--- 19,25 ----
#include "postgres.h"
#include "executor/executor.h"
+ #include "executor/instrument.h"
#include "miscadmin.h"
#include "utils/memutils.h"
***************
*** 221,226 **** ExecScan(ScanState *node,
--- 222,229 ----
* Tuple fails qual, so free per-tuple memory and try again.
*/
ResetExprContext(econtext);
+ if (node->ps.instrument)
+ node->ps.instrument->nfiltered += 1;
}
}
*** a/src/include/executor/instrument.h
--- b/src/include/executor/instrument.h
***************
*** 49,54 **** typedef struct Instrumentation
--- 49,55 ----
double startup; /* Total startup time (in seconds) */
double total; /* Total total time (in seconds) */
double ntuples; /* Total tuples produced */
+ double nfiltered; /* Total tuples filtered by qual */
double nloops; /* # of run cycles for this node */
BufferUsage bufusage; /* Total buffer usage */
} Instrumentation;