1/*-------------------------------------------------------------------------
2 *
3 * instrument.c
4 * functions for instrumentation of plan execution
5 *
6 *
7 * Copyright (c) 2001-2019, 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
20BufferUsage pgBufferUsage;
21static BufferUsage save_pgBufferUsage;
22
23static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add);
24static void BufferUsageAccumDiff(BufferUsage *dst,
25 const BufferUsage *add, const BufferUsage *sub);
26
27
28/* Allocate new instrumentation structure(s) */
29Instrumentation *
30InstrAlloc(int n, int instrument_options)
31{
32 Instrumentation *instr;
33
34 /* initialize all fields to zeroes, then modify as needed */
35 instr = palloc0(n * sizeof(Instrumentation));
36 if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
37 {
38 bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0;
39 bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
40 int i;
41
42 for (i = 0; i < n; i++)
43 {
44 instr[i].need_bufusage = need_buffers;
45 instr[i].need_timer = need_timer;
46 }
47 }
48
49 return instr;
50}
51
52/* Initialize a pre-allocated instrumentation structure. */
53void
54InstrInit(Instrumentation *instr, int instrument_options)
55{
56 memset(instr, 0, sizeof(Instrumentation));
57 instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0;
58 instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0;
59}
60
61/* Entry to a plan node */
62void
63InstrStartNode(Instrumentation *instr)
64{
65 if (instr->need_timer &&
66 !INSTR_TIME_SET_CURRENT_LAZY(instr->starttime))
67 elog(ERROR, "InstrStartNode called twice in a row");
68
69 /* save buffer usage totals at node entry, if needed */
70 if (instr->need_bufusage)
71 instr->bufusage_start = pgBufferUsage;
72}
73
74/* Exit from a plan node */
75void
76InstrStopNode(Instrumentation *instr, double nTuples)
77{
78 instr_time endtime;
79
80 /* count the returned tuples */
81 instr->tuplecount += nTuples;
82
83 /* let's update the time only if the timer was requested */
84 if (instr->need_timer)
85 {
86 if (INSTR_TIME_IS_ZERO(instr->starttime))
87 elog(ERROR, "InstrStopNode called without start");
88
89 INSTR_TIME_SET_CURRENT(endtime);
90 INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
91
92 INSTR_TIME_SET_ZERO(instr->starttime);
93 }
94
95 /* Add delta of buffer usage since entry to node's totals */
96 if (instr->need_bufusage)
97 BufferUsageAccumDiff(&instr->bufusage,
98 &pgBufferUsage, &instr->bufusage_start);
99
100 /* Is this the first tuple of this cycle? */
101 if (!instr->running)
102 {
103 instr->running = true;
104 instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
105 }
106}
107
108/* Finish a run cycle for a plan node */
109void
110InstrEndLoop(Instrumentation *instr)
111{
112 double totaltime;
113
114 /* Skip if nothing has happened, or already shut down */
115 if (!instr->running)
116 return;
117
118 if (!INSTR_TIME_IS_ZERO(instr->starttime))
119 elog(ERROR, "InstrEndLoop called on running node");
120
121 /* Accumulate per-cycle statistics into totals */
122 totaltime = INSTR_TIME_GET_DOUBLE(instr->counter);
123
124 instr->startup += instr->firsttuple;
125 instr->total += totaltime;
126 instr->ntuples += instr->tuplecount;
127 instr->nloops += 1;
128
129 /* Reset for next cycle (if any) */
130 instr->running = false;
131 INSTR_TIME_SET_ZERO(instr->starttime);
132 INSTR_TIME_SET_ZERO(instr->counter);
133 instr->firsttuple = 0;
134 instr->tuplecount = 0;
135}
136
137/* aggregate instrumentation information */
138void
139InstrAggNode(Instrumentation *dst, Instrumentation *add)
140{
141 if (!dst->running && add->running)
142 {
143 dst->running = true;
144 dst->firsttuple = add->firsttuple;
145 }
146 else if (dst->running && add->running && dst->firsttuple > add->firsttuple)
147 dst->firsttuple = add->firsttuple;
148
149 INSTR_TIME_ADD(dst->counter, add->counter);
150
151 dst->tuplecount += add->tuplecount;
152 dst->startup += add->startup;
153 dst->total += add->total;
154 dst->ntuples += add->ntuples;
155 dst->ntuples2 += add->ntuples2;
156 dst->nloops += add->nloops;
157 dst->nfiltered1 += add->nfiltered1;
158 dst->nfiltered2 += add->nfiltered2;
159
160 /* Add delta of buffer usage since entry to node's totals */
161 if (dst->need_bufusage)
162 BufferUsageAdd(&dst->bufusage, &add->bufusage);
163}
164
165/* note current values during parallel executor startup */
166void
167InstrStartParallelQuery(void)
168{
169 save_pgBufferUsage = pgBufferUsage;
170}
171
172/* report usage after parallel executor shutdown */
173void
174InstrEndParallelQuery(BufferUsage *result)
175{
176 memset(result, 0, sizeof(BufferUsage));
177 BufferUsageAccumDiff(result, &pgBufferUsage, &save_pgBufferUsage);
178}
179
180/* accumulate work done by workers in leader's stats */
181void
182InstrAccumParallelQuery(BufferUsage *result)
183{
184 BufferUsageAdd(&pgBufferUsage, result);
185}
186
187/* dst += add */
188static void
189BufferUsageAdd(BufferUsage *dst, const BufferUsage *add)
190{
191 dst->shared_blks_hit += add->shared_blks_hit;
192 dst->shared_blks_read += add->shared_blks_read;
193 dst->shared_blks_dirtied += add->shared_blks_dirtied;
194 dst->shared_blks_written += add->shared_blks_written;
195 dst->local_blks_hit += add->local_blks_hit;
196 dst->local_blks_read += add->local_blks_read;
197 dst->local_blks_dirtied += add->local_blks_dirtied;
198 dst->local_blks_written += add->local_blks_written;
199 dst->temp_blks_read += add->temp_blks_read;
200 dst->temp_blks_written += add->temp_blks_written;
201 INSTR_TIME_ADD(dst->blk_read_time, add->blk_read_time);
202 INSTR_TIME_ADD(dst->blk_write_time, add->blk_write_time);
203}
204
205/* dst += add - sub */
206static void
207BufferUsageAccumDiff(BufferUsage *dst,
208 const BufferUsage *add,
209 const BufferUsage *sub)
210{
211 dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit;
212 dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read;
213 dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied;
214 dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written;
215 dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit;
216 dst->local_blks_read += add->local_blks_read - sub->local_blks_read;
217 dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied;
218 dst->local_blks_written += add->local_blks_written - sub->local_blks_written;
219 dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read;
220 dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written;
221 INSTR_TIME_ACCUM_DIFF(dst->blk_read_time,
222 add->blk_read_time, sub->blk_read_time);
223 INSTR_TIME_ACCUM_DIFF(dst->blk_write_time,
224 add->blk_write_time, sub->blk_write_time);
225}
226