/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 | } |