From f1972723654947f70409716757aa83f3d93c8fab Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Thu, 22 Sep 2011 11:29:18 -0400 Subject: [PATCH] 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 --- src/backend/commands/explain.c | 79 +++++++++++++++++++++- src/backend/commands/trigger.c | 1 - src/backend/executor/execAmi.c | 1 - src/backend/executor/execMain.c | 1 - src/backend/executor/execProcnode.c | 1 - src/backend/executor/execScan.c | 2 + src/backend/executor/instrument.c | 14 ++-- src/backend/executor/nodeAgg.c | 4 ++ src/backend/executor/nodeBitmapAnd.c | 1 - src/backend/executor/nodeBitmapHeapscan.c | 1 + src/backend/executor/nodeBitmapIndexscan.c | 1 - src/backend/executor/nodeBitmapOr.c | 1 - src/backend/executor/nodeGroup.c | 4 ++ src/backend/executor/nodeHash.c | 1 - src/backend/executor/nodeHashjoin.c | 8 +++ src/backend/executor/nodeIndexscan.c | 6 +- src/backend/executor/nodeMergejoin.c | 8 +++ src/backend/executor/nodeNestloop.c | 6 ++ src/include/executor/instrument.h | 6 +- src/include/nodes/execnodes.h | 18 ++++- 20 files changed, 144 insertions(+), 20 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 6408d1653b3..cd9fc929232 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -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. */ diff --git a/src/backend/commands/trigger.c b/src/backend/commands/trigger.c index 680962aa444..06d368e0773 100644 --- a/src/backend/commands/trigger.c +++ b/src/backend/commands/trigger.c @@ -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" diff --git a/src/backend/executor/execAmi.c b/src/backend/executor/execAmi.c index ffdcc966ee6..711e8c77866 100644 --- a/src/backend/executor/execAmi.c +++ b/src/backend/executor/execAmi.c @@ -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" diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index 1dfe8b9ac78..fd7a9ed0339 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -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" diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c index 17788761d7f..8bdfad22223 100644 --- a/src/backend/executor/execProcnode.c +++ b/src/backend/executor/execProcnode.c @@ -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" diff --git a/src/backend/executor/execScan.c b/src/backend/executor/execScan.c index e90058847d9..d4ed2358564 100644 --- a/src/backend/executor/execScan.c +++ b/src/backend/executor/execScan.c @@ -219,6 +219,8 @@ ExecScan(ScanState *node, 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 bf9bf12ab6a..9d30200ab3c 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -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; diff --git a/src/backend/executor/nodeAgg.c b/src/backend/executor/nodeAgg.c index 13d77234801..e769d6d012c 100644 --- a/src/backend/executor/nodeAgg.c +++ b/src/backend/executor/nodeAgg.c @@ -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 */ diff --git a/src/backend/executor/nodeBitmapAnd.c b/src/backend/executor/nodeBitmapAnd.c index 82308cba260..5f318c31e77 100644 --- a/src/backend/executor/nodeBitmapAnd.c +++ b/src/backend/executor/nodeBitmapAnd.c @@ -29,7 +29,6 @@ #include "postgres.h" #include "executor/execdebug.h" -#include "executor/instrument.h" #include "executor/nodeBitmapAnd.h" diff --git a/src/backend/executor/nodeBitmapHeapscan.c b/src/backend/executor/nodeBitmapHeapscan.c index 8e50fb1aaef..4a8920e6ce8 100644 --- a/src/backend/executor/nodeBitmapHeapscan.c +++ b/src/backend/executor/nodeBitmapHeapscan.c @@ -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; } diff --git a/src/backend/executor/nodeBitmapIndexscan.c b/src/backend/executor/nodeBitmapIndexscan.c index 9a56fd4b9fd..8e1df079b37 100644 --- a/src/backend/executor/nodeBitmapIndexscan.c +++ b/src/backend/executor/nodeBitmapIndexscan.c @@ -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" diff --git a/src/backend/executor/nodeBitmapOr.c b/src/backend/executor/nodeBitmapOr.c index 4b064b79a96..d2453d5a4f0 100644 --- a/src/backend/executor/nodeBitmapOr.c +++ b/src/backend/executor/nodeBitmapOr.c @@ -29,7 +29,6 @@ #include "postgres.h" #include "executor/execdebug.h" -#include "executor/instrument.h" #include "executor/nodeBitmapOr.h" #include "miscadmin.h" diff --git a/src/backend/executor/nodeGroup.c b/src/backend/executor/nodeGroup.c index fa403e5406c..7bef8bbe8b9 100644 --- a/src/backend/executor/nodeGroup.c +++ b/src/backend/executor/nodeGroup.c @@ -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 */ diff --git a/src/backend/executor/nodeHash.c b/src/backend/executor/nodeHash.c index 2ade2d7fad6..e72a71bf51b 100644 --- a/src/backend/executor/nodeHash.c +++ b/src/backend/executor/nodeHash.c @@ -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" diff --git a/src/backend/executor/nodeHashjoin.c b/src/backend/executor/nodeHashjoin.c index 3a6698105f2..c3c4db4bc2c 100644 --- a/src/backend/executor/nodeHashjoin.c +++ b/src/backend/executor/nodeHashjoin.c @@ -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: diff --git a/src/backend/executor/nodeIndexscan.c b/src/backend/executor/nodeIndexscan.c index 955008e012d..da25384e860 100644 --- a/src/backend/executor/nodeIndexscan.c +++ b/src/backend/executor/nodeIndexscan.c @@ -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; diff --git a/src/backend/executor/nodeMergejoin.c b/src/backend/executor/nodeMergejoin.c index e23dd6c9f54..deaa79ed9fb 100644 --- a/src/backend/executor/nodeMergejoin.c +++ b/src/backend/executor/nodeMergejoin.c @@ -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; /* diff --git a/src/backend/executor/nodeNestloop.c b/src/backend/executor/nodeNestloop.c index e98bc0f5a30..49b880d0caf 100644 --- a/src/backend/executor/nodeNestloop.c +++ b/src/backend/executor/nodeNestloop.c @@ -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. diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 286cd540632..22c31069436 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -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; diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h index b3eed7d189c..c8a0b598645 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -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