src/backend/executor/instrument.c

   1 /*-------------------------------------------------------------------------
   2  *
   3  * instrument.c
   4  *       functions for instrumentation of plan execution
   5  *
   6  *
   7  * Copyright (c) 2001-2024, 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 WalUsage        pgWalUsage;
  23 static WalUsage save_pgWalUsage;
  24
  25 static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add);
  26 static void WalUsageAdd(WalUsage *dst, WalUsage *add);
  27
  28
  29 /* Allocate new instrumentation structure(s) */
  30 Instrumentation *
  31 InstrAlloc(int n, int instrument_options, bool async_mode)
  32 {
  33         Instrumentation *instr;
  34
  35         /* initialize all fields to zeroes, then modify as needed */
  36         instr = palloc0(n * sizeof(Instrumentation));
  37         if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL))
  38         {
  39                 bool            need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
  40                 bool            need_wal = (instrument_options & INSTRUMENT_WAL) != 0;
  41                 bool            need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
  42                 int                     i;
  43
  44                 for (i = 0; i < n; i++)
  45                 {
  46                         instr[i].need_bufusage = need_buffers;
  47                         instr[i].need_walusage = need_wal;
  48                         instr[i].need_timer = need_timer;
  49                         instr[i].async_mode = async_mode;
  50                 }
  51         }
  52
  53         return instr;
  54 }
  55
  56 /* Initialize a pre-allocated instrumentation structure. */
  57 void
  58 InstrInit(Instrumentation *instr, int instrument_options)
  59 {
  60         memset(instr, 0, sizeof(Instrumentation));
  61         instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
  62         instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
  63         instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
  64 }
  65
  66 /* Entry to a plan node */
  67 void
  68 InstrStartNode(Instrumentation *instr)
  69 {
  70         if (instr->need_timer &&
  71                 !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime))
  72                 elog(ERROR, "InstrStartNode called twice in a row");
  73
  74         /* save buffer usage totals at node entry, if needed */
  75         if (instr->need_bufusage)
  76                 instr->bufusage_start = pgBufferUsage;
  77
  78         if (instr->need_walusage)
  79                 instr->walusage_start = pgWalUsage;
  80 }
  81
  82 /* Exit from a plan node */
  83 void
  84 InstrStopNode(Instrumentation *instr, double nTuples)
  85 {
  86         double          save_tuplecount = instr->tuplecount;
  87         instr_time      endtime;
  88
  89         /* count the returned tuples */
  90         instr->tuplecount += nTuples;
  91
  92         /* let's update the time only if the timer was requested */
  93         if (instr->need_timer)
  94         {
  95                 if (INSTR_TIME_IS_ZERO(instr->starttime))
  96                         elog(ERROR, "InstrStopNode called without start");
  97
  98                 INSTR_TIME_SET_CURRENT(endtime);
  99                 INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
 100
 101                 INSTR_TIME_SET_ZERO(instr->starttime);
 102         }
 103
 104         /* Add delta of buffer usage since entry to node's totals */
 105         if (instr->need_bufusage)
 106                 BufferUsageAccumDiff(&instr->bufusage,
 107                                                          &pgBufferUsage, &instr->bufusage_start);
 108
 109         if (instr->need_walusage)
 110                 WalUsageAccumDiff(&instr->walusage,
 111                                                   &pgWalUsage, &instr->walusage_start);
 112
 113         /* Is this the first tuple of this cycle? */
 114         if (!instr->running)
 115         {
 116                 instr->running = true;
 117                 instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
 118         }
 119         else
 120         {
 121                 /*
 122                  * In async mode, if the plan node hadn't emitted any tuples before,
 123                  * this might be the first tuple
 124                  */
 125                 if (instr->async_mode && save_tuplecount < 1.0)
 126                         instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
 127         }
 128 }
 129
 130 /* Update tuple count */
 131 void
 132 InstrUpdateTupleCount(Instrumentation *instr, double nTuples)
 133 {
 134         /* count the returned tuples */
 135         instr->tuplecount += nTuples;
 136 }
 137
 138 /* Finish a run cycle for a plan node */
 139 void
 140 InstrEndLoop(Instrumentation *instr)
 141 {
 142         double          totaltime;
 143
 144         /* Skip if nothing has happened, or already shut down */
 145         if (!instr->running)
 146                 return;
 147
 148         if (!INSTR_TIME_IS_ZERO(instr->starttime))
 149                 elog(ERROR, "InstrEndLoop called on running node");
 150
 151         /* Accumulate per-cycle statistics into totals */
 152         totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
 153
 154         instr->startup += instr->firsttuple;
 155         instr->total += totaltime;
 156         instr->ntuples += instr->tuplecount;
 157         instr->nloops += 1;
 158
 159         /* Reset for next cycle (if any) */
 160         instr->running = false;
 161         INSTR_TIME_SET_ZERO(instr->starttime);
 162         INSTR_TIME_SET_ZERO(instr->counter);
 163         instr->firsttuple = 0;
 164         instr->tuplecount = 0;
 165 }
 166
 167 /* aggregate instrumentation information */
 168 void
 169 InstrAggNode(Instrumentation *dst, Instrumentation *add)
 170 {
 171         if (!dst->running && add->running)
 172         {
 173                 dst->running = true;
 174                 dst->firsttuple = add->firsttuple;
 175         }
 176         else if (dst->running && add->running && dst->firsttuple > add->firsttuple)
 177                 dst->firsttuple = add->firsttuple;
 178
 179         INSTR_TIME_ADD(dst->counter, add->counter);
 180
 181         dst->tuplecount += add->tuplecount;
 182         dst->startup += add->startup;
 183         dst->total += add->total;
 184         dst->ntuples += add->ntuples;
 185         dst->ntuples2 += add->ntuples2;
 186         dst->nloops += add->nloops;
 187         dst->nfiltered1 += add->nfiltered1;
 188         dst->nfiltered2 += add->nfiltered2;
 189
 190         /* Add delta of buffer usage since entry to node's totals */
 191         if (dst->need_bufusage)
 192                 BufferUsageAdd(&dst->bufusage, &add->bufusage);
 193
 194         if (dst->need_walusage)
 195                 WalUsageAdd(&dst->walusage, &add->walusage);
 196 }
 197
 198 /* note current values during parallel executor startup */
 199 void
 200 InstrStartParallelQuery(void)
 201 {
 202         save_pgBufferUsage = pgBufferUsage;
 203         save_pgWalUsage = pgWalUsage;
 204 }
 205
 206 /* report usage after parallel executor shutdown */
 207 void
 208 InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
 209 {
 210         memset(bufusage, 0, sizeof(BufferUsage));
 211         BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage);
 212         memset(walusage, 0, sizeof(WalUsage));
 213         WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage);
 214 }
 215
 216 /* accumulate work done by workers in leader's stats */
 217 void
 218 InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
 219 {
 220         BufferUsageAdd(&pgBufferUsage, bufusage);
 221         WalUsageAdd(&pgWalUsage, walusage);
 222 }
 223
 224 /* dst += add */
 225 static void
 226 BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
 227 {
 228         dst->shared_blks_hit += add->shared_blks_hit;
 229         dst->shared_blks_read += add->shared_blks_read;
 230         dst->shared_blks_dirtied += add->shared_blks_dirtied;
 231         dst->shared_blks_written += add->shared_blks_written;
 232         dst->local_blks_hit += add->local_blks_hit;
 233         dst->local_blks_read += add->local_blks_read;
 234         dst->local_blks_dirtied += add->local_blks_dirtied;
 235         dst->local_blks_written += add->local_blks_written;
 236         dst->temp_blks_read += add->temp_blks_read;
 237         dst->temp_blks_written += add->temp_blks_written;
 238         INSTR_TIME_ADD(dst->shared_blk_read_time, add->shared_blk_read_time);
 239         INSTR_TIME_ADD(dst->shared_blk_write_time, add->shared_blk_write_time);
 240         INSTR_TIME_ADD(dst->local_blk_read_time, add->local_blk_read_time);
 241         INSTR_TIME_ADD(dst->local_blk_write_time, add->local_blk_write_time);
 242         INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
 243         INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
 244 }
 245
 246 /* dst += add - sub */
 247 void
 248 BufferUsageAccumDiff(BufferUsage *dst,
 249                                          const BufferUsage *add,
 250                                          const BufferUsage *sub)
 251 {
 252         dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
 253         dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
 254         dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
 255         dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
 256         dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
 257         dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
 258         dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
 259         dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
 260         dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
 261         dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
 262         INSTR_TIME_ACCUM_DIFF(dst->shared_blk_read_time,
 263                                                   add->shared_blk_read_time, sub->shared_blk_read_time);
 264         INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time,
 265                                                   add->shared_blk_write_time, sub->shared_blk_write_time);
 266         INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time,
 267                                                   add->local_blk_read_time, sub->local_blk_read_time);
 268         INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time,
 269                                                   add->local_blk_write_time, sub->local_blk_write_time);
 270         INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
 271                                                   add->temp_blk_read_time, sub->temp_blk_read_time);
 272         INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,
 273                                                   add->temp_blk_write_time, sub->temp_blk_write_time);
 274 }
 275
 276 /* helper functions for WAL usage accumulation */
 277 static void
 278 WalUsageAdd(WalUsage *dst, WalUsage *add)
 279 {
 280         dst->wal_bytes += add->wal_bytes;
 281         dst->wal_records += add->wal_records;
 282         dst->wal_fpi += add->wal_fpi;
 283 }
 284
 285 void
 286 WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
 287 {
 288         dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
 289         dst->wal_records += add->wal_records - sub->wal_records;
 290         dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
 291 }