granicus.if.org Git - postgresql/blob - src/backend/executor/instrument.c

   1 /*-------------------------------------------------------------------------
   2  *
   3  * instrument.c
   4  *       functions for instrumentation of plan execution
   5  *
   6  *
   7  * Copyright (c) 2001-2017, PostgreSQL Global Development Group
   8  *
   9  * IDENTIFICATION
  10  *        src/backend/executor/instrument.c
  11  *
  12  *-------------------------------------------------------------------------
  13  */
  14 #include "postgres.h"
  15
  16 #include <unistd.h>
  17
  18 #include "executor/instrument.h"
  19
  20 BufferUsage pgBufferUsage;
  21 static BufferUsage save_pgBufferUsage;
  22
  23 static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add);
  24 static void BufferUsageAccumDiff(BufferUsage *dst,
  25                                          const BufferUsage *add, const BufferUsage *sub);
  26
  27
  28 /* Allocate new instrumentation structure(s) */
  29 Instrumentation *
  30 InstrAlloc(int n, int instrument_options)
  31 {
  32         Instrumentation *instr;
  33
  34         /* initialize all fields to zeroes, then modify as needed */
  35         instr = palloc0(n * sizeof(Instrumentation));
  36         if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
  37         {
  38                 bool            need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
  39                 bool            need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
  40                 int                     i;
  41
  42                 for (i = 0; i < n; i++)
  43                 {
  44                         instr[i].need_bufusage = need_buffers;
  45                         instr[i].need_timer = need_timer;
  46                 }
  47         }
  48
  49         return instr;
  50 }
  51
  52 /* Initialize an pre-allocated instrumentation structure. */
  53 void
  54 InstrInit(Instrumentation *instr, int instrument_options)
  55 {
  56         memset(instr, 0, sizeof(Instrumentation));
  57         instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
  58         instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
  59 }
  60
  61 /* Entry to a plan node */
  62 void
  63 InstrStartNode(Instrumentation *instr)
  64 {
  65         if (instr->need_timer)
  66         {
  67                 if (INSTR_TIME_IS_ZERO(instr->starttime))
  68                         INSTR_TIME_SET_CURRENT(instr->starttime);
  69                 else
  70                         elog(ERROR, "InstrStartNode called twice in a row");
  71         }
  72
  73         /* save buffer usage totals at node entry, if needed */
  74         if (instr->need_bufusage)
  75                 instr->bufusage_start = pgBufferUsage;
  76 }
  77
  78 /* Exit from a plan node */
  79 void
  80 InstrStopNode(Instrumentation *instr, double nTuples)
  81 {
  82         instr_time      endtime;
  83
  84         /* count the returned tuples */
  85         instr->tuplecount += nTuples;
  86
  87         /* let's update the time only if the timer was requested */
  88         if (instr->need_timer)
  89         {
  90                 if (INSTR_TIME_IS_ZERO(instr->starttime))
  91                         elog(ERROR, "InstrStopNode called without start");
  92
  93                 INSTR_TIME_SET_CURRENT(endtime);
  94                 INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
  95
  96                 INSTR_TIME_SET_ZERO(instr->starttime);
  97         }
  98
  99         /* Add delta of buffer usage since entry to node's totals */
 100         if (instr->need_bufusage)
 101                 BufferUsageAccumDiff(&instr->bufusage,
 102                                                          &pgBufferUsage, &instr->bufusage_start);
 103
 104         /* Is this the first tuple of this cycle? */
 105         if (!instr->running)
 106         {
 107                 instr->running = true;
 108                 instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
 109         }
 110 }
 111
 112 /* Finish a run cycle for a plan node */
 113 void
 114 InstrEndLoop(Instrumentation *instr)
 115 {
 116         double          totaltime;
 117
 118         /* Skip if nothing has happened, or already shut down */
 119         if (!instr->running)
 120                 return;
 121
 122         if (!INSTR_TIME_IS_ZERO(instr->starttime))
 123                 elog(ERROR, "InstrEndLoop called on running node");
 124
 125         /* Accumulate per-cycle statistics into totals */
 126         totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
 127
 128         instr->startup += instr->firsttuple;
 129         instr->total += totaltime;
 130         instr->ntuples += instr->tuplecount;
 131         instr->nloops += 1;
 132
 133         /* Reset for next cycle (if any) */
 134         instr->running = false;
 135         INSTR_TIME_SET_ZERO(instr->starttime);
 136         INSTR_TIME_SET_ZERO(instr->counter);
 137         instr->firsttuple = 0;
 138         instr->tuplecount = 0;
 139 }
 140
 141 /* aggregate instrumentation information */
 142 void
 143 InstrAggNode(Instrumentation *dst, Instrumentation *add)
 144 {
 145         if (!dst->running && add->running)
 146         {
 147                 dst->running = true;
 148                 dst->firsttuple = add->firsttuple;
 149         }
 150         else if (dst->running && add->running && dst->firsttuple > add->firsttuple)
 151                 dst->firsttuple = add->firsttuple;
 152
 153         INSTR_TIME_ADD(dst->counter, add->counter);
 154
 155         dst->tuplecount += add->tuplecount;
 156         dst->startup += add->startup;
 157         dst->total += add->total;
 158         dst->ntuples += add->ntuples;
 159         dst->nloops += add->nloops;
 160         dst->nfiltered1 += add->nfiltered1;
 161         dst->nfiltered2 += add->nfiltered2;
 162
 163         /* Add delta of buffer usage since entry to node's totals */
 164         if (dst->need_bufusage)
 165                 BufferUsageAdd(&dst->bufusage, &add->bufusage);
 166 }
 167
 168 /* note current values during parallel executor startup */
 169 void
 170 InstrStartParallelQuery(void)
 171 {
 172         save_pgBufferUsage = pgBufferUsage;
 173 }
 174
 175 /* report usage after parallel executor shutdown */
 176 void
 177 InstrEndParallelQuery(BufferUsage *result)
 178 {
 179         memset(result, 0, sizeof(BufferUsage));
 180         BufferUsageAccumDiff(result, &pgBufferUsage, &save_pgBufferUsage);
 181 }
 182
 183 /* accumulate work done by workers in leader's stats */
 184 void
 185 InstrAccumParallelQuery(BufferUsage *result)
 186 {
 187         BufferUsageAdd(&pgBufferUsage, result);
 188 }
 189
 190 /* dst += add */
 191 static void
 192 BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
 193 {
 194         dst->shared_blks_hit += add->shared_blks_hit;
 195         dst->shared_blks_read += add->shared_blks_read;
 196         dst->shared_blks_dirtied += add->shared_blks_dirtied;
 197         dst->shared_blks_written += add->shared_blks_written;
 198         dst->local_blks_hit += add->local_blks_hit;
 199         dst->local_blks_read += add->local_blks_read;
 200         dst->local_blks_dirtied += add->local_blks_dirtied;
 201         dst->local_blks_written += add->local_blks_written;
 202         dst->temp_blks_read += add->temp_blks_read;
 203         dst->temp_blks_written += add->temp_blks_written;
 204         INSTR_TIME_ADD(dst->blk_read_time, add->blk_read_time);
 205         INSTR_TIME_ADD(dst->blk_write_time, add->blk_write_time);
 206 }
 207
 208 /* dst += add - sub */
 209 static void
 210 BufferUsageAccumDiff(BufferUsage *dst,
 211                                          const BufferUsage *add,
 212                                          const BufferUsage *sub)
 213 {
 214         dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
 215         dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
 216         dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
 217         dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
 218         dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
 219         dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
 220         dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
 221         dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
 222         dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
 223         dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
 224         INSTR_TIME_ACCUM_DIFF(dst->blk_read_time,
 225                                                   add->blk_read_time, sub->blk_read_time);
 226         INSTR_TIME_ACCUM_DIFF(dst->blk_write_time,
 227                                                   add->blk_write_time, sub->blk_write_time);
 228 }