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