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