Make EXPLAIN sampling smarter, to avoid excessive sampling delay.
authorBruce Momjian <bruce@momjian.us>
Tue, 30 May 2006 14:01:58 +0000 (14:01 +0000)
committerBruce Momjian <bruce@momjian.us>
Tue, 30 May 2006 14:01:58 +0000 (14:01 +0000)
Martijn van Oosterhout

src/backend/commands/trigger.c
src/backend/executor/execProcnode.c
src/backend/executor/instrument.c
src/backend/executor/nodeBitmapAnd.c
src/backend/executor/nodeBitmapIndexscan.c
src/backend/executor/nodeBitmapOr.c
src/backend/executor/nodeHash.c
src/include/executor/instrument.h

index 256b2ca411d5cd0b441eca1872be5412b6c7e637..04cd75e99fb57aeb491294a971f72981abfbf8cb 100644 (file)
@@ -7,7 +7,7 @@
  * Portions Copyright (c) 1994, Regents of the University of California
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/commands/trigger.c,v 1.201 2006/04/27 00:33:41 momjian Exp $
+ *   $PostgreSQL: pgsql/src/backend/commands/trigger.c,v 1.202 2006/05/30 14:01:57 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -1306,7 +1306,7 @@ ExecCallTriggerFunc(TriggerData *trigdata,
     * one "tuple returned" (really the number of firings).
     */
    if (instr)
-       InstrStopNode(instr + tgindx, true);
+       InstrStopNode(instr + tgindx, 1);
 
    return (HeapTuple) DatumGetPointer(result);
 }
@@ -2154,7 +2154,7 @@ AfterTriggerExecute(AfterTriggerEvent event,
     * one "tuple returned" (really the number of firings).
     */
    if (instr)
-       InstrStopNode(instr + tgindx, true);
+       InstrStopNode(instr + tgindx, 1);
 }
 
 
index 5f15f8f7965328db7c3799b1e68856340951217b..2b8bee97dd84b203bed568ba88c36a30a1b7382e 100644 (file)
@@ -12,7 +12,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.54 2006/03/05 15:58:26 momjian Exp $
+ *   $PostgreSQL: pgsql/src/backend/executor/execProcnode.c,v 1.55 2006/05/30 14:01:57 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -423,7 +423,7 @@ ExecProcNode(PlanState *node)
    }
 
    if (node->instrument)
-       InstrStopNode(node->instrument, !TupIsNull(result));
+       InstrStopNode(node->instrument, TupIsNull(result) ? 0 : 1 );
 
    return result;
 }
index 5f2b84ae98eee0b24254c0ba54938c1017f28fb5..41b061bd526c6f4129c4b0d00e5e752193844553 100644 (file)
@@ -7,16 +7,78 @@
  * Copyright (c) 2001-2006, PostgreSQL Global Development Group
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.14 2006/03/05 15:58:26 momjian Exp $
+ *   $PostgreSQL: pgsql/src/backend/executor/instrument.c,v 1.15 2006/05/30 14:01:58 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
 #include "postgres.h"
 
 #include <unistd.h>
+#include <math.h>
 
 #include "executor/instrument.h"
 
+/* This is the function that is used to determine the sampling intervals. In
+ * general, if the function is f(x), then for N tuples we will take on the
+ * order of integral(1/f(x), x=0..N) samples. Some examples follow, with the
+ * number of samples that would be collected over 1,000,000 tuples.
+
+  f(x) = x         =>   log2(N)                        20
+  f(x) = x^(1/2)   =>   2 * N^(1/2)                  2000
+  f(x) = x^(1/3)   =>   1.5 * N^(2/3)               15000
+  
+ * I've chosen the last one as it seems to provide a good compromise between
+ * low overhead but still getting a meaningful number of samples. However,
+ * not all machines have the cbrt() function so on those we substitute
+ * sqrt(). The difference is not very significant in the tests I made.
+*/ 
+#ifdef HAVE_CBRT
+#define SampleFunc cbrt
+#else
+#define SampleFunc sqrt
+#endif
+
+#define SAMPLE_THRESHOLD 50
+
+static double SampleOverhead;
+static bool SampleOverheadCalculated;
+
+static void
+CalculateSampleOverhead()
+{
+   Instrumentation instr;
+   int i;
+   
+   /* We want to determine the sampling overhead, to correct
+    * calculations later. This only needs to be done once per backend.
+    * Is this the place? A wrong value here (due to a mistimed
+    * task-switch) will cause bad calculations later.
+    *
+    * To minimize the risk we do it a few times and take the lowest.
+    */
+   
+   SampleOverhead = 1.0e6;
+   
+   for( i = 0; i<5; i++ )
+   {
+       int j;
+       double overhead;
+       
+       memset( &instr, 0, sizeof(instr) );
+   
+       /* Loop SAMPLE_THRESHOLD times or 100 microseconds, whichever is faster */
+       for( j=0; j<SAMPLE_THRESHOLD && INSTR_TIME_GET_DOUBLE(instr.counter) < 100e-6; i++ )
+       {
+           InstrStartNode( &instr );
+           InstrStopNode( &instr, 1 );
+       }
+       overhead = INSTR_TIME_GET_DOUBLE(instr.counter) / instr.samplecount;
+       if( overhead < SampleOverhead )
+           SampleOverhead = overhead;
+   }
+       
+   SampleOverheadCalculated = true;
+}
 
 /* Allocate new instrumentation structure(s) */
 Instrumentation *
@@ -25,7 +87,10 @@ InstrAlloc(int n)
    Instrumentation *instr = palloc0(n * sizeof(Instrumentation));
 
    /* we don't need to do any initialization except zero 'em */
-
+   
+   /* Calculate overhead, if not done yet */
+   if( !SampleOverheadCalculated )
+       CalculateSampleOverhead();
    return instr;
 }
 
@@ -34,49 +99,69 @@ void
 InstrStartNode(Instrumentation *instr)
 {
    if (INSTR_TIME_IS_ZERO(instr->starttime))
-       INSTR_TIME_SET_CURRENT(instr->starttime);
+   {
+       /* We always sample the first SAMPLE_THRESHOLD tuples, so small nodes are always accurate */
+       if (instr->tuplecount < SAMPLE_THRESHOLD)
+           instr->sampling = true;
+       else
+       {
+           /* Otherwise we go to sampling, see the comments on SampleFunc at the top of the file */
+           if( instr->tuplecount > instr->nextsample )
+           {
+               instr->sampling = true;
+               /* The doubling is so the random will average 1 over time */
+               instr->nextsample += 2.0 * SampleFunc(instr->tuplecount) * (double)rand() / (double)RAND_MAX;
+           }
+       }
+       if (instr->sampling)
+           INSTR_TIME_SET_CURRENT(instr->starttime);
+   }
    else
        elog(DEBUG2, "InstrStartNode called twice in a row");
 }
 
 /* Exit from a plan node */
 void
-InstrStopNode(Instrumentation *instr, bool returnedTuple)
+InstrStopNode(Instrumentation *instr, double nTuples)
 {
    instr_time  endtime;
 
    /* count the returned tuples */
-   if (returnedTuple)
-       instr->tuplecount += 1;
+   instr->tuplecount += nTuples;
 
-   if (INSTR_TIME_IS_ZERO(instr->starttime))
+   if (instr->sampling)
    {
-       elog(DEBUG2, "InstrStopNode called without start");
-       return;
-   }
+       if (INSTR_TIME_IS_ZERO(instr->starttime))
+       {
+           elog(DEBUG2, "InstrStopNode called without start");
+           return;
+       }
 
-   INSTR_TIME_SET_CURRENT(endtime);
+       INSTR_TIME_SET_CURRENT(endtime);
 
 #ifndef WIN32
-   instr->counter.tv_sec += endtime.tv_sec - instr->starttime.tv_sec;
-   instr->counter.tv_usec += endtime.tv_usec - instr->starttime.tv_usec;
-
-   /* Normalize after each add to avoid overflow/underflow of tv_usec */
-   while (instr->counter.tv_usec < 0)
-   {
-       instr->counter.tv_usec += 1000000;
-       instr->counter.tv_sec--;
-   }
-   while (instr->counter.tv_usec >= 1000000)
-   {
-       instr->counter.tv_usec -= 1000000;
-       instr->counter.tv_sec++;
-   }
+       instr->counter.tv_sec += endtime.tv_sec - instr->starttime.tv_sec;
+       instr->counter.tv_usec += endtime.tv_usec - instr->starttime.tv_usec;
+
+       /* Normalize after each add to avoid overflow/underflow of tv_usec */
+       while (instr->counter.tv_usec < 0)
+       {
+           instr->counter.tv_usec += 1000000;
+           instr->counter.tv_sec--;
+       }
+       while (instr->counter.tv_usec >= 1000000)
+       {
+           instr->counter.tv_usec -= 1000000;
+           instr->counter.tv_sec++;
+       }
 #else                          /* WIN32 */
-   instr->counter.QuadPart += (endtime.QuadPart - instr->starttime.QuadPart);
+       instr->counter.QuadPart += (endtime.QuadPart - instr->starttime.QuadPart);
 #endif
 
-   INSTR_TIME_SET_ZERO(instr->starttime);
+       INSTR_TIME_SET_ZERO(instr->starttime);
+       instr->samplecount += nTuples;
+       instr->sampling = false;
+   }
 
    /* Is this the first tuple of this cycle? */
    if (!instr->running)
@@ -86,17 +171,6 @@ InstrStopNode(Instrumentation *instr, bool returnedTuple)
    }
 }
 
-/* As above, but count multiple tuples returned at once */
-void
-InstrStopNodeMulti(Instrumentation *instr, double nTuples)
-{
-   /* count the returned tuples */
-   instr->tuplecount += nTuples;
-
-   /* delegate the rest */
-   InstrStopNode(instr, false);
-}
-
 /* Finish a run cycle for a plan node */
 void
 InstrEndLoop(Instrumentation *instr)
@@ -114,8 +188,24 @@ InstrEndLoop(Instrumentation *instr)
    totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
 
    instr->startup += instr->firsttuple;
-   instr->total += totaltime;
+
+   /* Here we take into account sampling effects. Doing it naively ends
+    * up assuming the sampling overhead applies to all tuples, even the
+    * ones we didn't measure. We've calculated an overhead, so we
+    * subtract that for all samples we didn't measure. The first tuple
+    * is also special cased, because it usually takes longer. */
+
+   if( instr->samplecount < instr->tuplecount )
+   {
+       double pertuple = (totaltime - instr->firsttuple) / (instr->samplecount - 1);
+       instr->total += instr->firsttuple + (pertuple * (instr->samplecount - 1))
+                                         + ((pertuple - SampleOverhead) * (instr->tuplecount - instr->samplecount));
+   }
+   else
+       instr->total += totaltime;
+       
    instr->ntuples += instr->tuplecount;
+   instr->nsamples += instr->samplecount;
    instr->nloops += 1;
 
    /* Reset for next cycle (if any) */
@@ -123,5 +213,6 @@ InstrEndLoop(Instrumentation *instr)
    INSTR_TIME_SET_ZERO(instr->starttime);
    INSTR_TIME_SET_ZERO(instr->counter);
    instr->firsttuple = 0;
+   instr->samplecount = 0;
    instr->tuplecount = 0;
 }
index f5914adb62b57b9ca19865a0cb1c81de44754b84..f12fa94882f392407c81be89b6a20d0a7f142738 100644 (file)
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/executor/nodeBitmapAnd.c,v 1.7 2006/05/23 15:21:52 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/executor/nodeBitmapAnd.c,v 1.8 2006/05/30 14:01:58 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -161,7 +161,7 @@ MultiExecBitmapAnd(BitmapAndState *node)
 
    /* must provide our own instrumentation support */
    if (node->ps.instrument)
-       InstrStopNodeMulti(node->ps.instrument, 0 /* XXX */ );
+       InstrStopNode(node->ps.instrument, 0 /* XXX */ );
 
    return (Node *) result;
 }
index 300edfed29d0f11ef7bd144be064249ed7dd7292..7555b5a22ca4e7776fce208acf2edfb6e1954c30 100644 (file)
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/executor/nodeBitmapIndexscan.c,v 1.18 2006/05/23 15:21:52 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/executor/nodeBitmapIndexscan.c,v 1.19 2006/05/30 14:01:58 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -112,7 +112,7 @@ MultiExecBitmapIndexScan(BitmapIndexScanState *node)
 
    /* must provide our own instrumentation support */
    if (node->ss.ps.instrument)
-       InstrStopNodeMulti(node->ss.ps.instrument, nTuples);
+       InstrStopNode(node->ss.ps.instrument, nTuples);
 
    return (Node *) tbm;
 }
index 6c870cdd17b7866d723dbc66c0598e2256c94b38..b7eabb1fe8a2026da702017b54c1af61c1f5bade 100644 (file)
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/executor/nodeBitmapOr.c,v 1.6 2006/05/23 15:21:52 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/executor/nodeBitmapOr.c,v 1.7 2006/05/30 14:01:58 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -177,7 +177,7 @@ MultiExecBitmapOr(BitmapOrState *node)
 
    /* must provide our own instrumentation support */
    if (node->ps.instrument)
-       InstrStopNodeMulti(node->ps.instrument, 0 /* XXX */ );
+       InstrStopNode(node->ps.instrument, 0 /* XXX */ );
 
    return (Node *) result;
 }
index a34e6860f862437d09552b1efc00ab9ab911fd6d..5710afb2fca8703df27d4493f8753912eb6f3b01 100644 (file)
@@ -8,7 +8,7 @@
  *
  *
  * IDENTIFICATION
- *   $PostgreSQL: pgsql/src/backend/executor/nodeHash.c,v 1.102 2006/05/23 15:21:52 tgl Exp $
+ *   $PostgreSQL: pgsql/src/backend/executor/nodeHash.c,v 1.103 2006/05/30 14:01:58 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -97,7 +97,7 @@ MultiExecHash(HashState *node)
 
    /* must provide our own instrumentation support */
    if (node->ps.instrument)
-       InstrStopNodeMulti(node->ps.instrument, hashtable->totalTuples);
+       InstrStopNode(node->ps.instrument, hashtable->totalTuples);
 
    /*
     * We do not return the hash table directly because it's not a subtype of
index e89a36f6591e1e49bfc04e6a64bbc25df105bde4..fbf578d473f8c7001f92ee633b0fa20d6ea518e6 100644 (file)
@@ -6,7 +6,7 @@
  *
  * Copyright (c) 2001-2006, PostgreSQL Global Development Group
  *
- * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.13 2006/03/05 15:58:56 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/executor/instrument.h,v 1.14 2006/05/30 14:01:58 momjian Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -61,17 +61,21 @@ typedef struct Instrumentation
    instr_time  counter;        /* Accumulated runtime for this node */
    double      firsttuple;     /* Time for first tuple of this cycle */
    double      tuplecount;     /* Tuples emitted so far this cycle */
+   double      samplecount;        /* Samples collected this cycle */
    /* Accumulated statistics across all completed cycles: */
    double      startup;        /* Total startup time (in seconds) */
    double      total;          /* Total total time (in seconds) */
    double      ntuples;        /* Total tuples produced */
    double      nloops;         /* # of run cycles for this node */
+   double      nsamples;       /* # of samples taken */
+   /* Tracking for sampling */
+   bool        sampling;       /* Are we sampling this iteration */
+   double      nextsample;     /* The next tuplecount we're going to sample */
 } Instrumentation;
 
 extern Instrumentation *InstrAlloc(int n);
 extern void InstrStartNode(Instrumentation *instr);
-extern void InstrStopNode(Instrumentation *instr, bool returnedTuple);
-extern void InstrStopNodeMulti(Instrumentation *instr, double nTuples);
+extern void InstrStopNode(Instrumentation *instr, double nTuples);
 extern void InstrEndLoop(Instrumentation *instr);
 
 #endif   /* INSTRUMENT_H */