Make EXPLAIN ANALYZE report the numbers of rows rejected by filter steps.
authorTom Lane <tgl@sss.pgh.pa.us>
Thu, 22 Sep 2011 15:29:18 +0000 (11:29 -0400)
committerTom Lane <tgl@sss.pgh.pa.us>
Thu, 22 Sep 2011 15:30:11 +0000 (11:30 -0400)
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

20 files changed:
src/backend/commands/explain.c
src/backend/commands/trigger.c
src/backend/executor/execAmi.c
src/backend/executor/execMain.c
src/backend/executor/execProcnode.c
src/backend/executor/execScan.c
src/backend/executor/instrument.c
src/backend/executor/nodeAgg.c
src/backend/executor/nodeBitmapAnd.c
src/backend/executor/nodeBitmapHeapscan.c
src/backend/executor/nodeBitmapIndexscan.c
src/backend/executor/nodeBitmapOr.c
src/backend/executor/nodeGroup.c
src/backend/executor/nodeHash.c
src/backend/executor/nodeHashjoin.c
src/backend/executor/nodeIndexscan.c
src/backend/executor/nodeMergejoin.c
src/backend/executor/nodeNestloop.c
src/include/executor/instrument.h
src/include/nodes/execnodes.h

index 6408d1653b33706be0780aac3b4a9558d12c9056..cd9fc929232b0eb721dd68e3d7a32b9216e5df91 100644 (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.
  */
index 680962aa44499b67478075ad62cc9c0f8e079e0b..06d368e07736f73529797df31a4f143a784202b9 100644 (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"
index ffdcc966ee60a3b0edbf5ea26241e0f47d903663..711e8c778664123d996c69f62196d0e5247c28b9 100644 (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"
index 1dfe8b9ac7823f8c92468178991107931a858ff5..fd7a9ed0339eed73b1523d84cacb8e8df55eb3f5 100644 (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"
index 17788761d7f101319388f8ad7a6cb964efe140f3..8bdfad2222380c9b7c4e88919267116f231d1d20 100644 (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"
index e90058847d9de9bb8554dd5548607429b1694b1d..d4ed2358564de38201e0cef120d98b3315be794a 100644 (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.
index bf9bf12ab6a3bf9cbc764a704971cdc47dccaef2..9d30200ab3c311928e35b1748bfee037d8d097a1 100644 (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;
index 13d7723480144575103dc2efb42c10296dd565f8..e769d6d012c4422ee905c6417375e4d629316f26 100644 (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 */
index 82308cba2609251ff045089dad20d8892b67b79b..5f318c31e7796e9f477bf217da214171cfcd1231 100644 (file)
@@ -29,7 +29,6 @@
 #include "postgres.h"
 
 #include "executor/execdebug.h"
-#include "executor/instrument.h"
 #include "executor/nodeBitmapAnd.h"
 
 
index 8e50fb1aaef4ba8a0418da5f8d077058c5a71ce2..4a8920e6ce842eb7d027f7415d3c415e7d8d00b8 100644 (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;
            }
index 9a56fd4b9fda06666fb3e42d6c8e7a306e81b44d..8e1df079b3728d69cdcae13b1eeec538bb469311 100644 (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"
index 4b064b79a96234ca44de20077936b478cef0f2b2..d2453d5a4f0a5a96df1d7041f22c14cf11027082 100644 (file)
@@ -29,7 +29,6 @@
 #include "postgres.h"
 
 #include "executor/execdebug.h"
-#include "executor/instrument.h"
 #include "executor/nodeBitmapOr.h"
 #include "miscadmin.h"
 
index fa403e5406c04f68afefcee8322ddeeb6c7dd74f..7bef8bbe8b9c074c6b8fd22dc5e7ec720020b78b 100644 (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 */
index 2ade2d7fad6b3f190cb0c9d17117b4d140c32d8d..e72a71bf51bf71e6b3c9a300e17fa8875e8e78e8 100644 (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"
index 3a6698105f278398a2317555cf0731a24cf9b106..c3c4db4bc2ce047d1db36b4894e6d591a0d97305 100644 (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:
index 955008e012d56d0a8bb42c0c78719944fe41c7d1..da25384e860df509cc40921911b5d84b95ec9f21 100644 (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;
index e23dd6c9f540c279314a888e544310e08763d514..deaa79ed9fbddfa5397887439085f499a5981259 100644 (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;
 
                /*
index e98bc0f5a308bd27bd624c6342e4a22fffe530a7..49b880d0caf013e18a3a5c2e2677069bef9568d1 100644 (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.
index 286cd540632258855e31ab9ae3fbd391576d4b97..22c310694365056a4aca06a3c71a5538bd9c21f7 100644 (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;
 
index b3eed7d189cb81b61c84b18157fa3fcdd5b19456..c8a0b5986457f2b4e323934ff101876766ddca59 100644 (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