Coverage Report

Created: 2026-11-12 07:20

next uncovered line (L), next uncovered region (R), next uncovered branch (B)
/src/postgres/src/backend/executor/instrument.c
Line
Count
Source
1
/*-------------------------------------------------------------------------
2
 *
3
 * instrument.c
4
 *   functions for instrumentation of plan execution
5
 *
6
 *
7
 * Copyright (c) 2001-2026, 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/executor.h"
19
#include "executor/instrument.h"
20
#include "executor/tuptable.h"
21
#include "nodes/execnodes.h"
22
#include "portability/instr_time.h"
23
#include "utils/guc_hooks.h"
24
25
BufferUsage pgBufferUsage;
26
static BufferUsage save_pgBufferUsage;
27
WalUsage  pgWalUsage;
28
static WalUsage save_pgWalUsage;
29
30
static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add);
31
static void WalUsageAdd(WalUsage *dst, WalUsage *add);
32
33
34
/* General purpose instrumentation handling */
35
Instrumentation *
36
InstrAlloc(int instrument_options)
37
0
{
38
0
  Instrumentation *instr = palloc0_object(Instrumentation);
39
40
0
  InstrInitOptions(instr, instrument_options);
41
0
  return instr;
42
0
}
43
44
void
45
InstrInitOptions(Instrumentation *instr, int instrument_options)
46
0
{
47
0
  instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
48
0
  instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
49
0
  instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
50
0
}
51
52
inline void
53
InstrStart(Instrumentation *instr)
54
0
{
55
0
  if (instr->need_timer)
56
0
  {
57
0
    if (!INSTR_TIME_IS_ZERO(instr->starttime))
58
0
      elog(ERROR, "InstrStart called twice in a row");
59
0
    else
60
0
      INSTR_TIME_SET_CURRENT_FAST(instr->starttime);
61
0
  }
62
63
  /* save buffer usage totals at start, if needed */
64
0
  if (instr->need_bufusage)
65
0
    instr->bufusage_start = pgBufferUsage;
66
67
0
  if (instr->need_walusage)
68
0
    instr->walusage_start = pgWalUsage;
69
0
}
70
71
/*
72
 * Helper for InstrStop() and InstrStopNode(), to avoid code duplication
73
 * despite slightly different needs about how time is accumulated.
74
 */
75
static inline void
76
InstrStopCommon(Instrumentation *instr, instr_time *accum_time)
77
0
{
78
0
  instr_time  endtime;
79
80
  /* update the time only if the timer was requested */
81
0
  if (instr->need_timer)
82
0
  {
83
0
    if (INSTR_TIME_IS_ZERO(instr->starttime))
84
0
      elog(ERROR, "InstrStop called without start");
85
86
0
    INSTR_TIME_SET_CURRENT_FAST(endtime);
87
0
    INSTR_TIME_ACCUM_DIFF(*accum_time, endtime, instr->starttime);
88
89
0
    INSTR_TIME_SET_ZERO(instr->starttime);
90
0
  }
91
92
  /* Add delta of buffer usage since InstrStart to the totals */
93
0
  if (instr->need_bufusage)
94
0
    BufferUsageAccumDiff(&instr->bufusage,
95
0
               &pgBufferUsage, &instr->bufusage_start);
96
97
0
  if (instr->need_walusage)
98
0
    WalUsageAccumDiff(&instr->walusage,
99
0
              &pgWalUsage, &instr->walusage_start);
100
0
}
101
102
void
103
InstrStop(Instrumentation *instr)
104
0
{
105
0
  InstrStopCommon(instr, &instr->total);
106
0
}
107
108
/* Node instrumentation handling */
109
110
/* Allocate new node instrumentation structure */
111
NodeInstrumentation *
112
InstrAllocNode(int instrument_options, bool async_mode)
113
0
{
114
0
  NodeInstrumentation *instr = palloc_object(NodeInstrumentation);
115
116
0
  InstrInitNode(instr, instrument_options, async_mode);
117
118
0
  return instr;
119
0
}
120
121
/* Initialize a pre-allocated instrumentation structure. */
122
void
123
InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mode)
124
0
{
125
0
  memset(instr, 0, sizeof(NodeInstrumentation));
126
0
  InstrInitOptions(&instr->instr, instrument_options);
127
0
  instr->async_mode = async_mode;
128
0
}
129
130
/* Entry to a plan node */
131
inline void
132
InstrStartNode(NodeInstrumentation *instr)
133
0
{
134
0
  InstrStart(&instr->instr);
135
0
}
136
137
/* Exit from a plan node */
138
inline void
139
InstrStopNode(NodeInstrumentation *instr, double nTuples)
140
0
{
141
0
  double    save_tuplecount = instr->tuplecount;
142
143
  /* count the returned tuples */
144
0
  instr->tuplecount += nTuples;
145
146
  /*
147
   * Note that in contrast to InstrStop() the time is accumulated into
148
   * NodeInstrumentation->counter, with total only getting updated in
149
   * InstrEndLoop.  We need the separate counter variable because we need to
150
   * calculate start-up time for the first tuple in each cycle, and then
151
   * accumulate it together.
152
   */
153
0
  InstrStopCommon(&instr->instr, &instr->counter);
154
155
  /* Is this the first tuple of this cycle? */
156
0
  if (!instr->running)
157
0
  {
158
0
    instr->running = true;
159
0
    instr->firsttuple = instr->counter;
160
0
  }
161
0
  else
162
0
  {
163
    /*
164
     * In async mode, if the plan node hadn't emitted any tuples before,
165
     * this might be the first tuple
166
     */
167
0
    if (instr->async_mode && save_tuplecount < 1.0)
168
0
      instr->firsttuple = instr->counter;
169
0
  }
170
0
}
171
172
/*
173
 * ExecProcNode wrapper that performs instrumentation calls.  By keeping
174
 * this a separate function, we avoid overhead in the normal case where
175
 * no instrumentation is wanted.
176
 *
177
 * This is implemented in instrument.c as all the functions it calls directly
178
 * are here, allowing them to be inlined even when not using LTO.
179
 */
180
TupleTableSlot *
181
ExecProcNodeInstr(PlanState *node)
182
0
{
183
0
  TupleTableSlot *result;
184
185
0
  InstrStartNode(node->instrument);
186
187
0
  result = node->ExecProcNodeReal(node);
188
189
0
  InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0);
190
191
0
  return result;
192
0
}
193
194
/* Update tuple count */
195
void
196
InstrUpdateTupleCount(NodeInstrumentation *instr, double nTuples)
197
0
{
198
  /* count the returned tuples */
199
0
  instr->tuplecount += nTuples;
200
0
}
201
202
/* Finish a run cycle for a plan node */
203
void
204
InstrEndLoop(NodeInstrumentation *instr)
205
0
{
206
  /* Skip if nothing has happened, or already shut down */
207
0
  if (!instr->running)
208
0
    return;
209
210
0
  if (!INSTR_TIME_IS_ZERO(instr->instr.starttime))
211
0
    elog(ERROR, "InstrEndLoop called on running node");
212
213
  /* Accumulate per-cycle statistics into totals */
214
0
  INSTR_TIME_ADD(instr->startup, instr->firsttuple);
215
0
  INSTR_TIME_ADD(instr->instr.total, instr->counter);
216
0
  instr->ntuples += instr->tuplecount;
217
0
  instr->nloops += 1;
218
219
  /* Reset for next cycle (if any) */
220
0
  instr->running = false;
221
0
  INSTR_TIME_SET_ZERO(instr->instr.starttime);
222
0
  INSTR_TIME_SET_ZERO(instr->counter);
223
0
  INSTR_TIME_SET_ZERO(instr->firsttuple);
224
0
  instr->tuplecount = 0;
225
0
}
226
227
/*
228
 * Aggregate instrumentation from parallel workers. Must be called after
229
 * InstrEndLoop.
230
 */
231
void
232
InstrAggNode(NodeInstrumentation *dst, NodeInstrumentation *add)
233
0
{
234
0
  Assert(!add->running);
235
236
0
  INSTR_TIME_ADD(dst->startup, add->startup);
237
0
  INSTR_TIME_ADD(dst->instr.total, add->instr.total);
238
0
  dst->ntuples += add->ntuples;
239
0
  dst->ntuples2 += add->ntuples2;
240
0
  dst->nloops += add->nloops;
241
0
  dst->nfiltered1 += add->nfiltered1;
242
0
  dst->nfiltered2 += add->nfiltered2;
243
244
0
  if (dst->instr.need_bufusage)
245
0
    BufferUsageAdd(&dst->instr.bufusage, &add->instr.bufusage);
246
247
0
  if (dst->instr.need_walusage)
248
0
    WalUsageAdd(&dst->instr.walusage, &add->instr.walusage);
249
0
}
250
251
/* Trigger instrumentation handling */
252
TriggerInstrumentation *
253
InstrAllocTrigger(int n, int instrument_options)
254
0
{
255
0
  TriggerInstrumentation *tginstr = palloc0_array(TriggerInstrumentation, n);
256
0
  int     i;
257
258
0
  for (i = 0; i < n; i++)
259
0
    InstrInitOptions(&tginstr[i].instr, instrument_options);
260
261
0
  return tginstr;
262
0
}
263
264
void
265
InstrStartTrigger(TriggerInstrumentation *tginstr)
266
0
{
267
0
  InstrStart(&tginstr->instr);
268
0
}
269
270
void
271
InstrStopTrigger(TriggerInstrumentation *tginstr, int64 firings)
272
0
{
273
0
  InstrStop(&tginstr->instr);
274
0
  tginstr->firings += firings;
275
0
}
276
277
/* note current values during parallel executor startup */
278
void
279
InstrStartParallelQuery(void)
280
0
{
281
0
  save_pgBufferUsage = pgBufferUsage;
282
0
  save_pgWalUsage = pgWalUsage;
283
0
}
284
285
/* report usage after parallel executor shutdown */
286
void
287
InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
288
0
{
289
0
  memset(bufusage, 0, sizeof(BufferUsage));
290
0
  BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage);
291
0
  memset(walusage, 0, sizeof(WalUsage));
292
0
  WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage);
293
0
}
294
295
/* accumulate work done by workers in leader's stats */
296
void
297
InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
298
0
{
299
0
  BufferUsageAdd(&pgBufferUsage, bufusage);
300
0
  WalUsageAdd(&pgWalUsage, walusage);
301
0
}
302
303
/* dst += add */
304
static void
305
BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
306
0
{
307
0
  dst->shared_blks_hit += add->shared_blks_hit;
308
0
  dst->shared_blks_read += add->shared_blks_read;
309
0
  dst->shared_blks_dirtied += add->shared_blks_dirtied;
310
0
  dst->shared_blks_written += add->shared_blks_written;
311
0
  dst->local_blks_hit += add->local_blks_hit;
312
0
  dst->local_blks_read += add->local_blks_read;
313
0
  dst->local_blks_dirtied += add->local_blks_dirtied;
314
0
  dst->local_blks_written += add->local_blks_written;
315
0
  dst->temp_blks_read += add->temp_blks_read;
316
0
  dst->temp_blks_written += add->temp_blks_written;
317
0
  INSTR_TIME_ADD(dst->shared_blk_read_time, add->shared_blk_read_time);
318
0
  INSTR_TIME_ADD(dst->shared_blk_write_time, add->shared_blk_write_time);
319
0
  INSTR_TIME_ADD(dst->local_blk_read_time, add->local_blk_read_time);
320
0
  INSTR_TIME_ADD(dst->local_blk_write_time, add->local_blk_write_time);
321
0
  INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
322
0
  INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
323
0
}
324
325
/* dst += add - sub */
326
inline void
327
BufferUsageAccumDiff(BufferUsage *dst,
328
           const BufferUsage *add,
329
           const BufferUsage *sub)
330
0
{
331
0
  dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
332
0
  dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
333
0
  dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
334
0
  dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
335
0
  dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
336
0
  dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
337
0
  dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
338
0
  dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
339
0
  dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
340
0
  dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
341
0
  INSTR_TIME_ACCUM_DIFF(dst->shared_blk_read_time,
342
0
              add->shared_blk_read_time, sub->shared_blk_read_time);
343
0
  INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time,
344
0
              add->shared_blk_write_time, sub->shared_blk_write_time);
345
0
  INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time,
346
0
              add->local_blk_read_time, sub->local_blk_read_time);
347
0
  INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time,
348
0
              add->local_blk_write_time, sub->local_blk_write_time);
349
0
  INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
350
0
              add->temp_blk_read_time, sub->temp_blk_read_time);
351
0
  INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,
352
0
              add->temp_blk_write_time, sub->temp_blk_write_time);
353
0
}
354
355
/* helper functions for WAL usage accumulation */
356
static inline void
357
WalUsageAdd(WalUsage *dst, WalUsage *add)
358
0
{
359
0
  dst->wal_bytes += add->wal_bytes;
360
0
  dst->wal_records += add->wal_records;
361
0
  dst->wal_fpi += add->wal_fpi;
362
0
  dst->wal_fpi_bytes += add->wal_fpi_bytes;
363
0
  dst->wal_buffers_full += add->wal_buffers_full;
364
0
}
365
366
inline void
367
WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
368
0
{
369
0
  dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
370
0
  dst->wal_records += add->wal_records - sub->wal_records;
371
0
  dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
372
0
  dst->wal_fpi_bytes += add->wal_fpi_bytes - sub->wal_fpi_bytes;
373
0
  dst->wal_buffers_full += add->wal_buffers_full - sub->wal_buffers_full;
374
0
}
375
376
/* GUC hooks for timing_clock_source */
377
378
bool
379
check_timing_clock_source(int *newval, void **extra, GucSource source)
380
2
{
381
  /*
382
   * Do nothing if timing is not initialized. This is only expected on child
383
   * processes in EXEC_BACKEND builds, as GUC hooks can be called during
384
   * InitializeGUCOptions() before InitProcessGlobals() has had a chance to
385
   * run pg_initialize_timing(). Instead, TSC will be initialized via
386
   * restore_backend_variables.
387
   */
388
#ifdef EXEC_BACKEND
389
  if (!timing_initialized)
390
    return true;
391
#else
392
2
  Assert(timing_initialized);
393
2
#endif
394
395
2
#if PG_INSTR_TSC_CLOCK
396
2
  pg_initialize_timing_tsc();
397
398
2
  if (*newval == TIMING_CLOCK_SOURCE_TSC && timing_tsc_frequency_khz <= 0)
399
0
  {
400
0
    GUC_check_errdetail("TSC is not supported as timing clock source");
401
0
    return false;
402
0
  }
403
2
#endif
404
405
2
  return true;
406
2
}
407
408
void
409
assign_timing_clock_source(int newval, void *extra)
410
2
{
411
#ifdef EXEC_BACKEND
412
  if (!timing_initialized)
413
    return;
414
#else
415
2
  Assert(timing_initialized);
416
2
#endif
417
418
  /*
419
   * Ignore the return code since the check hook already verified TSC is
420
   * usable if it's explicitly requested.
421
   */
422
2
  pg_set_timing_clock_source(newval);
423
2
}
424
425
const char *
426
show_timing_clock_source(void)
427
0
{
428
0
  switch (timing_clock_source)
429
0
  {
430
0
    case TIMING_CLOCK_SOURCE_AUTO:
431
0
#if PG_INSTR_TSC_CLOCK
432
0
      if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
433
0
        return "auto (tsc)";
434
0
#endif
435
0
      return "auto (system)";
436
0
    case TIMING_CLOCK_SOURCE_SYSTEM:
437
0
      return "system";
438
0
#if PG_INSTR_TSC_CLOCK
439
0
    case TIMING_CLOCK_SOURCE_TSC:
440
0
      return "tsc";
441
0
#endif
442
0
  }
443
444
  /* unreachable */
445
0
  return "?";
446
0
}