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