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