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