Make EXPLAIN ANALYZE report the numbers of rows rejected by filter steps.

This provides information about the numbers of tuples that were visited
but not returned by table scans, as well as the numbers of join tuples
that were considered and discarded within a join plan node.

There is still some discussion going on about the best way to report counts
for outer-join situations, but I think most of what's in the patch would
not change if we revise that, so I'm going to go ahead and commit it as-is.

Documentation changes to follow (they weren't in the submitted patch
either).

Marko Tiikkaja, reviewed by Marc Cousin, somewhat revised by Tom
This commit is contained in:
Tom Lane 2011-09-22 11:29:18 -04:00
parent 4893552e21
commit f197272365
20 changed files with 144 additions and 20 deletions

View File

@ -18,7 +18,6 @@
#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"
@ -76,6 +75,8 @@ static void show_sort_keys_common(PlanState *planstate,
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);
@ -1000,9 +1001,15 @@ ExplainNode(PlanState *planstate, List *ancestors,
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,
@ -1011,6 +1018,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
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:
@ -1018,6 +1028,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
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)
@ -1025,6 +1038,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
"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:
{
@ -1038,34 +1054,61 @@ ExplainNode(PlanState *planstate, List *ancestors,
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);
@ -1079,6 +1122,9 @@ ExplainNode(PlanState *planstate, List *ancestors,
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);
@ -1508,6 +1554,37 @@ show_hash_info(HashState *hashstate, ExplainState *es)
}
}
/*
* 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.
*/

View File

@ -29,7 +29,6 @@
#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"

View File

@ -13,7 +13,6 @@
#include "postgres.h"
#include "executor/execdebug.h"
#include "executor/instrument.h"
#include "executor/nodeAgg.h"
#include "executor/nodeAppend.h"
#include "executor/nodeBitmapAnd.h"

View File

@ -47,7 +47,6 @@
#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"

View File

@ -77,7 +77,6 @@
#include "postgres.h"
#include "executor/executor.h"
#include "executor/instrument.h"
#include "executor/nodeAgg.h"
#include "executor/nodeAppend.h"
#include "executor/nodeBitmapAnd.h"

View File

@ -219,6 +219,8 @@ ExecScan(ScanState *node,
return slot;
}
}
else
InstrCountFiltered1(node, 1);
/*
* Tuple fails qual, so free per-tuple memory and try again.

View File

@ -22,6 +22,7 @@ BufferUsage pgBufferUsage;
static void BufferUsageAccumDiff(BufferUsage *dst,
const BufferUsage *add, const BufferUsage *sub);
/* Allocate new instrumentation structure(s) */
Instrumentation *
InstrAlloc(int n, int instrument_options)
@ -31,13 +32,14 @@ InstrAlloc(int n, int instrument_options)
/* 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].needs_bufusage = true;
instr[i].need_bufusage = true;
}
return instr;
@ -52,8 +54,8 @@ InstrStartNode(Instrumentation *instr)
else
elog(DEBUG2, "InstrStartNode called twice in a row");
/* initialize buffer usage per plan node */
if (instr->needs_bufusage)
/* save buffer usage totals at node entry, if needed */
if (instr->need_bufusage)
instr->bufusage_start = pgBufferUsage;
}
@ -77,8 +79,8 @@ InstrStopNode(Instrumentation *instr, double nTuples)
INSTR_TIME_SET_ZERO(instr->starttime);
/* Adds delta of buffer usage to node's count. */
if (instr->needs_bufusage)
/* Add delta of buffer usage since entry to node's totals */
if (instr->need_bufusage)
BufferUsageAccumDiff(&instr->bufusage,
&pgBufferUsage, &instr->bufusage_start);
@ -119,12 +121,12 @@ InstrEndLoop(Instrumentation *instr)
instr->tuplecount = 0;
}
/* dst += add - sub */
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;

View File

@ -1204,6 +1204,8 @@ agg_retrieve_direct(AggState *aggstate)
return result;
}
}
else
InstrCountFiltered1(aggstate, 1);
}
/* No more groups */
@ -1354,6 +1356,8 @@ agg_retrieve_hash_table(AggState *aggstate)
return result;
}
}
else
InstrCountFiltered1(aggstate, 1);
}
/* No more groups */

View File

@ -29,7 +29,6 @@
#include "postgres.h"
#include "executor/execdebug.h"
#include "executor/instrument.h"
#include "executor/nodeBitmapAnd.h"

View File

@ -278,6 +278,7 @@ BitmapHeapNext(BitmapHeapScanState *node)
if (!ExecQual(node->bitmapqualorig, econtext, false))
{
/* Fails recheck, so drop it and loop back for another */
InstrCountFiltered2(node, 1);
ExecClearTuple(slot);
continue;
}

View File

@ -22,7 +22,6 @@
#include "postgres.h"
#include "executor/execdebug.h"
#include "executor/instrument.h"
#include "executor/nodeBitmapIndexscan.h"
#include "executor/nodeIndexscan.h"
#include "miscadmin.h"

View File

@ -29,7 +29,6 @@
#include "postgres.h"
#include "executor/execdebug.h"
#include "executor/instrument.h"
#include "executor/nodeBitmapOr.h"
#include "miscadmin.h"

View File

@ -118,6 +118,8 @@ ExecGroup(GroupState *node)
return result;
}
}
else
InstrCountFiltered1(node, 1);
}
/*
@ -179,6 +181,8 @@ ExecGroup(GroupState *node)
return result;
}
}
else
InstrCountFiltered1(node, 1);
}
/* NOTREACHED */

View File

@ -28,7 +28,6 @@
#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"

View File

@ -325,7 +325,11 @@ ExecHashJoin(HashJoinState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
}
else
InstrCountFiltered1(node, 1);
break;
case HJ_FILL_OUTER_TUPLE:
@ -360,6 +364,8 @@ ExecHashJoin(HashJoinState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
}
break;
@ -397,6 +403,8 @@ ExecHashJoin(HashJoinState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
break;
case HJ_NEED_NEW_BATCH:

View File

@ -96,7 +96,11 @@ IndexNext(IndexScanState *node)
econtext->ecxt_scantuple = slot;
ResetExprContext(econtext);
if (!ExecQual(node->indexqualorig, econtext, false))
continue; /* nope, so ask index for another one */
{
/* Fails recheck, so drop it and loop back for another */
InstrCountFiltered2(node, 1);
continue;
}
}
return slot;

View File

@ -505,6 +505,8 @@ MJFillOuter(MergeJoinState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
return NULL;
}
@ -544,6 +546,8 @@ MJFillInner(MergeJoinState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
return NULL;
}
@ -893,7 +897,11 @@ ExecMergeJoin(MergeJoinState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
}
else
InstrCountFiltered1(node, 1);
break;
/*

View File

@ -214,6 +214,8 @@ ExecNestLoop(NestLoopState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
}
/*
@ -270,7 +272,11 @@ ExecNestLoop(NestLoopState *node)
return result;
}
}
else
InstrCountFiltered2(node, 1);
}
else
InstrCountFiltered1(node, 1);
/*
* Tuple fails qual, so free per-tuple memory and try again.

View File

@ -28,6 +28,7 @@ typedef struct BufferUsage
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 */
@ -37,9 +38,10 @@ typedef enum InstrumentOption
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 */
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 */
@ -50,6 +52,8 @@ typedef struct Instrumentation
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;

View File

@ -16,6 +16,7 @@
#include "access/genam.h"
#include "access/heapam.h"
#include "executor/instrument.h"
#include "nodes/params.h"
#include "nodes/plannodes.h"
#include "utils/reltrigger.h"
@ -314,7 +315,7 @@ typedef struct ResultRelInfo
TriggerDesc *ri_TrigDesc;
FmgrInfo *ri_TrigFunctions;
List **ri_TrigWhenExprs;
struct Instrumentation *ri_TrigInstrument;
Instrumentation *ri_TrigInstrument;
List **ri_ConstraintExprs;
JunkFilter *ri_junkFilter;
ProjectionInfo *ri_projectReturning;
@ -967,8 +968,7 @@ typedef struct PlanState
* nodes point to one EState for the whole
* top-level plan */
struct Instrumentation *instrument; /* Optional runtime stats for this
* plan node */
Instrumentation *instrument; /* Optional runtime stats for this node */
/*
* Common structural data for all Plan types. These links to subsidiary
@ -1008,6 +1008,18 @@ typedef struct PlanState
#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