Age Owner Branch data TLA Line data Source code
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 *
55 andres@anarazel.de 36 :GNC 42813 : InstrAlloc(int instrument_options)
37 : : {
38 : 42813 : Instrumentation *instr = palloc0_object(Instrumentation);
39 : :
40 : 42813 : InstrInitOptions(instr, instrument_options);
9020 tgl@sss.pgh.pa.us 41 :CBC 42813 : return instr;
42 : : }
43 : :
44 : : void
55 andres@anarazel.de 45 :GNC 50902 : InstrInitOptions(Instrumentation *instr, int instrument_options)
46 : : {
3897 rhaas@postgresql.org 47 :CBC 50902 : instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
2247 akapila@postgresql.o 48 : 50902 : instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0;
3897 rhaas@postgresql.org 49 : 50902 : instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
50 : 50902 : }
51 : :
52 : : inline void
55 andres@anarazel.de 53 :GNC 9102715 : InstrStart(Instrumentation *instr)
54 : : {
93 55 [ + + ]: 9102715 : if (instr->need_timer)
56 : : {
57 [ - + ]: 7203748 : if (!INSTR_TIME_IS_ZERO(instr->starttime))
55 andres@anarazel.de 58 [ # # ]:UNC 0 : elog(ERROR, "InstrStart called twice in a row");
59 : : else
53 andres@anarazel.de 60 :GNC 7203748 : INSTR_TIME_SET_CURRENT_FAST(instr->starttime);
61 : : }
62 : :
63 : : /* save buffer usage totals at start, if needed */
5364 tgl@sss.pgh.pa.us 64 [ + + ]:CBC 9102715 : if (instr->need_bufusage)
6010 rhaas@postgresql.org 65 : 7151637 : instr->bufusage_start = pgBufferUsage;
66 : :
2247 akapila@postgresql.o 67 [ + + ]: 9102715 : if (instr->need_walusage)
68 : 83483 : instr->walusage_start = pgWalUsage;
9020 tgl@sss.pgh.pa.us 69 : 9102715 : }
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
55 andres@anarazel.de 76 :GNC 9101036 : InstrStopCommon(Instrumentation *instr, instr_time *accum_time)
77 : : {
78 : : instr_time endtime;
79 : :
80 : : /* update the time only if the timer was requested */
5226 rhaas@postgresql.org 81 [ + + ]:CBC 9101036 : if (instr->need_timer)
82 : : {
83 [ - + ]: 7202077 : if (INSTR_TIME_IS_ZERO(instr->starttime))
55 andres@anarazel.de 84 [ # # ]:UNC 0 : elog(ERROR, "InstrStop called without start");
85 : :
53 andres@anarazel.de 86 :GNC 7202077 : INSTR_TIME_SET_CURRENT_FAST(endtime);
55 87 : 7202077 : INSTR_TIME_ACCUM_DIFF(*accum_time, endtime, instr->starttime);
88 : :
5226 rhaas@postgresql.org 89 :CBC 7202077 : INSTR_TIME_SET_ZERO(instr->starttime);
90 : : }
91 : :
92 : : /* Add delta of buffer usage since InstrStart to the totals */
5364 tgl@sss.pgh.pa.us 93 [ + + ]: 9101036 : if (instr->need_bufusage)
6010 rhaas@postgresql.org 94 : 7149966 : BufferUsageAccumDiff(&instr->bufusage,
5937 bruce@momjian.us 95 : 7149966 : &pgBufferUsage, &instr->bufusage_start);
96 : :
2247 akapila@postgresql.o 97 [ + + ]: 9101036 : if (instr->need_walusage)
98 : 81812 : WalUsageAccumDiff(&instr->walusage,
99 : 81812 : &pgWalUsage, &instr->walusage_start);
55 andres@anarazel.de 100 :GNC 9101036 : }
101 : :
102 : : void
103 : 81834 : InstrStop(Instrumentation *instr)
104 : : {
105 : 81834 : InstrStopCommon(instr, &instr->total);
106 : 81834 : }
107 : :
108 : : /* Node instrumentation handling */
109 : :
110 : : /* Allocate new node instrumentation structure */
111 : : NodeInstrumentation *
112 : 6969 : InstrAllocNode(int instrument_options, bool async_mode)
113 : : {
114 : 6969 : NodeInstrumentation *instr = palloc_object(NodeInstrumentation);
115 : :
116 : 6969 : InstrInitNode(instr, instrument_options, async_mode);
117 : :
118 : 6969 : return instr;
119 : : }
120 : :
121 : : /* Initialize a pre-allocated instrumentation structure. */
122 : : void
123 : 8089 : InstrInitNode(NodeInstrumentation *instr, int instrument_options, bool async_mode)
124 : : {
125 : 8089 : memset(instr, 0, sizeof(NodeInstrumentation));
126 : 8089 : InstrInitOptions(&instr->instr, instrument_options);
127 : 8089 : instr->async_mode = async_mode;
128 : 8089 : }
129 : :
130 : : /* Entry to a plan node */
131 : : inline void
132 : 9019210 : InstrStartNode(NodeInstrumentation *instr)
133 : : {
134 : 9019210 : InstrStart(&instr->instr);
135 : 9019210 : }
136 : :
137 : : /* Exit from a plan node */
138 : : inline void
139 : 9019202 : InstrStopNode(NodeInstrumentation *instr, double nTuples)
140 : : {
141 : 9019202 : double save_tuplecount = instr->tuplecount;
142 : :
143 : : /* count the returned tuples */
144 : 9019202 : 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 : 9019202 : InstrStopCommon(&instr->instr, &instr->counter);
154 : :
155 : : /* Is this the first tuple of this cycle? */
9020 tgl@sss.pgh.pa.us 156 [ + + ]:CBC 9019202 : if (!instr->running)
157 : : {
158 : 34210 : instr->running = true;
141 andres@anarazel.de 159 :GNC 34210 : instr->firsttuple = instr->counter;
160 : : }
161 : : else
162 : : {
163 : : /*
164 : : * In async mode, if the plan node hadn't emitted any tuples before,
165 : : * this might be the first tuple
166 : : */
1844 efujita@postgresql.o 167 [ + + + + ]:CBC 8984992 : if (instr->async_mode && save_tuplecount < 1.0)
141 andres@anarazel.de 168 :GNC 23 : instr->firsttuple = instr->counter;
169 : : }
1844 efujita@postgresql.o 170 :CBC 9019202 : }
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 *
53 andres@anarazel.de 181 :GNC 9011900 : ExecProcNodeInstr(PlanState *node)
182 : : {
183 : : TupleTableSlot *result;
184 : :
185 : 9011900 : InstrStartNode(node->instrument);
186 : :
187 : 9011900 : result = node->ExecProcNodeReal(node);
188 : :
189 [ + + + + ]: 9011892 : InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0);
190 : :
191 : 9011892 : return result;
192 : : }
193 : :
194 : : /* Update tuple count */
195 : : void
55 196 : 2 : InstrUpdateTupleCount(NodeInstrumentation *instr, double nTuples)
197 : : {
198 : : /* count the returned tuples */
1844 efujita@postgresql.o 199 :CBC 2 : instr->tuplecount += nTuples;
7714 tgl@sss.pgh.pa.us 200 : 2 : }
201 : :
202 : : /* Finish a run cycle for a plan node */
203 : : void
55 andres@anarazel.de 204 :GNC 35560 : InstrEndLoop(NodeInstrumentation *instr)
205 : : {
206 : : /* Skip if nothing has happened, or already shut down */
9020 tgl@sss.pgh.pa.us 207 [ + + ]:CBC 35560 : if (!instr->running)
208 : 1359 : return;
209 : :
55 andres@anarazel.de 210 [ - + ]:GNC 34201 : if (!INSTR_TIME_IS_ZERO(instr->instr.starttime))
4860 tgl@sss.pgh.pa.us 211 [ # # ]:UBC 0 : elog(ERROR, "InstrEndLoop called on running node");
212 : :
213 : : /* Accumulate per-cycle statistics into totals */
141 andres@anarazel.de 214 :GNC 34201 : INSTR_TIME_ADD(instr->startup, instr->firsttuple);
55 215 : 34201 : INSTR_TIME_ADD(instr->instr.total, instr->counter);
9020 tgl@sss.pgh.pa.us 216 :CBC 34201 : instr->ntuples += instr->tuplecount;
217 : 34201 : instr->nloops += 1;
218 : :
219 : : /* Reset for next cycle (if any) */
220 : 34201 : instr->running = false;
55 andres@anarazel.de 221 :GNC 34201 : INSTR_TIME_SET_ZERO(instr->instr.starttime);
7741 tgl@sss.pgh.pa.us 222 :CBC 34201 : INSTR_TIME_SET_ZERO(instr->counter);
141 andres@anarazel.de 223 :GNC 34201 : INSTR_TIME_SET_ZERO(instr->firsttuple);
9020 tgl@sss.pgh.pa.us 224 :CBC 34201 : instr->tuplecount = 0;
225 : : }
226 : :
227 : : /*
228 : : * Aggregate instrumentation from parallel workers. Must be called after
229 : : * InstrEndLoop.
230 : : */
231 : : void
55 andres@anarazel.de 232 :GNC 2678 : InstrAggNode(NodeInstrumentation *dst, NodeInstrumentation *add)
233 : : {
234 [ - + ]: 2678 : Assert(!add->running);
235 : :
141 236 : 2678 : INSTR_TIME_ADD(dst->startup, add->startup);
55 237 : 2678 : INSTR_TIME_ADD(dst->instr.total, add->instr.total);
3897 rhaas@postgresql.org 238 :CBC 2678 : dst->ntuples += add->ntuples;
2972 alvherre@alvh.no-ip. 239 : 2678 : dst->ntuples2 += add->ntuples2;
3897 rhaas@postgresql.org 240 : 2678 : dst->nloops += add->nloops;
241 : 2678 : dst->nfiltered1 += add->nfiltered1;
242 : 2678 : dst->nfiltered2 += add->nfiltered2;
243 : :
55 andres@anarazel.de 244 [ + + ]:GNC 2678 : if (dst->instr.need_bufusage)
245 : 1272 : BufferUsageAdd(&dst->instr.bufusage, &add->instr.bufusage);
246 : :
247 [ - + ]: 2678 : if (dst->instr.need_walusage)
55 andres@anarazel.de 248 :UNC 0 : WalUsageAdd(&dst->instr.walusage, &add->instr.walusage);
3897 rhaas@postgresql.org 249 :GNC 2678 : }
250 : :
251 : : /* Trigger instrumentation handling */
252 : : TriggerInstrumentation *
55 andres@anarazel.de 253 :UNC 0 : InstrAllocTrigger(int n, int instrument_options)
254 : : {
255 : 0 : TriggerInstrumentation *tginstr = palloc0_array(TriggerInstrumentation, n);
256 : : 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 : : }
263 : :
264 : : void
265 : 0 : InstrStartTrigger(TriggerInstrumentation *tginstr)
266 : : {
267 : 0 : InstrStart(&tginstr->instr);
268 : 0 : }
269 : :
270 : : void
271 : 0 : InstrStopTrigger(TriggerInstrumentation *tginstr, int64 firings)
272 : : {
273 : 0 : InstrStop(&tginstr->instr);
274 : 0 : tginstr->firings += firings;
55 andres@anarazel.de 275 :LBC (2028) : }
276 : :
277 : : /* note current values during parallel executor startup */
278 : : void
3897 rhaas@postgresql.org 279 :CBC 2000 : InstrStartParallelQuery(void)
280 : : {
281 : 2000 : save_pgBufferUsage = pgBufferUsage;
2247 akapila@postgresql.o 282 : 2000 : save_pgWalUsage = pgWalUsage;
3897 rhaas@postgresql.org 283 : 2000 : }
284 : :
285 : : /* report usage after parallel executor shutdown */
286 : : void
2247 akapila@postgresql.o 287 : 1992 : InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
288 : : {
2242 289 : 1992 : memset(bufusage, 0, sizeof(BufferUsage));
290 : 1992 : BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage);
2247 291 : 1992 : memset(walusage, 0, sizeof(WalUsage));
292 : 1992 : WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage);
3897 rhaas@postgresql.org 293 : 1992 : }
294 : :
295 : : /* accumulate work done by workers in leader's stats */
296 : : void
2247 akapila@postgresql.o 297 : 1992 : InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage)
298 : : {
2242 299 : 1992 : BufferUsageAdd(&pgBufferUsage, bufusage);
2247 300 : 1992 : WalUsageAdd(&pgWalUsage, walusage);
3897 rhaas@postgresql.org 301 : 1992 : }
302 : :
303 : : /* dst += add */
304 : : static void
305 : 3264 : BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
306 : : {
307 : 3264 : dst->shared_blks_hit += add->shared_blks_hit;
308 : 3264 : dst->shared_blks_read += add->shared_blks_read;
309 : 3264 : dst->shared_blks_dirtied += add->shared_blks_dirtied;
310 : 3264 : dst->shared_blks_written += add->shared_blks_written;
311 : 3264 : dst->local_blks_hit += add->local_blks_hit;
312 : 3264 : dst->local_blks_read += add->local_blks_read;
313 : 3264 : dst->local_blks_dirtied += add->local_blks_dirtied;
314 : 3264 : dst->local_blks_written += add->local_blks_written;
315 : 3264 : dst->temp_blks_read += add->temp_blks_read;
316 : 3264 : dst->temp_blks_written += add->temp_blks_written;
954 michael@paquier.xyz 317 : 3264 : INSTR_TIME_ADD(dst->shared_blk_read_time, add->shared_blk_read_time);
318 : 3264 : INSTR_TIME_ADD(dst->shared_blk_write_time, add->shared_blk_write_time);
319 : 3264 : INSTR_TIME_ADD(dst->local_blk_read_time, add->local_blk_read_time);
320 : 3264 : INSTR_TIME_ADD(dst->local_blk_write_time, add->local_blk_write_time);
1513 321 : 3264 : INSTR_TIME_ADD(dst->temp_blk_read_time, add->temp_blk_read_time);
322 : 3264 : INSTR_TIME_ADD(dst->temp_blk_write_time, add->temp_blk_write_time);
3897 rhaas@postgresql.org 323 : 3264 : }
324 : :
325 : : /* dst += add - sub */
326 : : inline void
6010 327 : 7179756 : BufferUsageAccumDiff(BufferUsage *dst,
328 : : const BufferUsage *add,
329 : : const BufferUsage *sub)
330 : : {
331 : 7179756 : dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
332 : 7179756 : dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
5211 333 : 7179756 : dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
6010 334 : 7179756 : dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
335 : 7179756 : dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
336 : 7179756 : dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
5211 337 : 7179756 : dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
6010 338 : 7179756 : dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
339 : 7179756 : dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
340 : 7179756 : dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
954 michael@paquier.xyz 341 : 7179756 : INSTR_TIME_ACCUM_DIFF(dst->shared_blk_read_time,
342 : : add->shared_blk_read_time, sub->shared_blk_read_time);
343 : 7179756 : INSTR_TIME_ACCUM_DIFF(dst->shared_blk_write_time,
344 : : add->shared_blk_write_time, sub->shared_blk_write_time);
345 : 7179756 : INSTR_TIME_ACCUM_DIFF(dst->local_blk_read_time,
346 : : add->local_blk_read_time, sub->local_blk_read_time);
347 : 7179756 : INSTR_TIME_ACCUM_DIFF(dst->local_blk_write_time,
348 : : add->local_blk_write_time, sub->local_blk_write_time);
1513 349 : 7179756 : INSTR_TIME_ACCUM_DIFF(dst->temp_blk_read_time,
350 : : add->temp_blk_read_time, sub->temp_blk_read_time);
351 : 7179756 : INSTR_TIME_ACCUM_DIFF(dst->temp_blk_write_time,
352 : : add->temp_blk_write_time, sub->temp_blk_write_time);
6010 rhaas@postgresql.org 353 : 7179756 : }
354 : :
355 : : /* helper functions for WAL usage accumulation */
356 : : static inline void
2247 akapila@postgresql.o 357 : 1992 : WalUsageAdd(WalUsage *dst, WalUsage *add)
358 : : {
359 : 1992 : dst->wal_bytes += add->wal_bytes;
360 : 1992 : dst->wal_records += add->wal_records;
2216 361 : 1992 : dst->wal_fpi += add->wal_fpi;
214 michael@paquier.xyz 362 :GNC 1992 : dst->wal_fpi_bytes += add->wal_fpi_bytes;
467 michael@paquier.xyz 363 :CBC 1992 : dst->wal_buffers_full += add->wal_buffers_full;
2247 akapila@postgresql.o 364 : 1992 : }
365 : :
366 : : inline void
367 : 134147 : WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub)
368 : : {
369 : 134147 : dst->wal_bytes += add->wal_bytes - sub->wal_bytes;
370 : 134147 : dst->wal_records += add->wal_records - sub->wal_records;
2216 371 : 134147 : dst->wal_fpi += add->wal_fpi - sub->wal_fpi;
214 michael@paquier.xyz 372 :GNC 134147 : dst->wal_fpi_bytes += add->wal_fpi_bytes - sub->wal_fpi_bytes;
467 michael@paquier.xyz 373 :CBC 134147 : dst->wal_buffers_full += add->wal_buffers_full - sub->wal_buffers_full;
2247 akapila@postgresql.o 374 : 134147 : }
375 : :
376 : : /* GUC hooks for timing_clock_source */
377 : :
378 : : bool
53 andres@anarazel.de 379 :GNC 1292 : check_timing_clock_source(int *newval, void **extra, GucSource source)
380 : : {
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 [ - + ]: 1292 : Assert(timing_initialized);
393 : : #endif
394 : :
395 : : #if PG_INSTR_TSC_CLOCK
396 : 1292 : pg_initialize_timing_tsc();
397 : :
398 [ - + - - ]: 1292 : if (*newval == TIMING_CLOCK_SOURCE_TSC && timing_tsc_frequency_khz <= 0)
399 : : {
53 andres@anarazel.de 400 :UNC 0 : GUC_check_errdetail("TSC is not supported as timing clock source");
401 : 0 : return false;
402 : : }
403 : : #endif
404 : :
53 andres@anarazel.de 405 :GNC 1292 : return true;
406 : : }
407 : :
408 : : void
409 : 1292 : assign_timing_clock_source(int newval, void *extra)
410 : : {
411 : : #ifdef EXEC_BACKEND
412 : : if (!timing_initialized)
413 : : return;
414 : : #else
415 [ - + ]: 1292 : Assert(timing_initialized);
416 : : #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 : 1292 : pg_set_timing_clock_source(newval);
423 : 1292 : }
424 : :
425 : : const char *
426 : 1891 : show_timing_clock_source(void)
427 : : {
428 [ + - - - ]: 1891 : switch (timing_clock_source)
429 : : {
430 : 1891 : case TIMING_CLOCK_SOURCE_AUTO:
431 : : #if PG_INSTR_TSC_CLOCK
432 [ + - ]: 1891 : if (pg_current_timing_clock_source() == TIMING_CLOCK_SOURCE_TSC)
433 : 1891 : return "auto (tsc)";
434 : : #endif
53 andres@anarazel.de 435 :UNC 0 : return "auto (system)";
436 : 0 : case TIMING_CLOCK_SOURCE_SYSTEM:
437 : 0 : return "system";
438 : : #if PG_INSTR_TSC_CLOCK
439 : 0 : case TIMING_CLOCK_SOURCE_TSC:
440 : 0 : return "tsc";
441 : : #endif
442 : : }
443 : :
444 : : /* unreachable */
445 : 0 : return "?";
446 : : }
|
