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