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 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 InstrAlloc(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. */ 53 void 54 InstrInit(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 */ 62 void 63 InstrStartNode(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 */ 75 void 76 InstrStopNode(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 */ 109 void 110 InstrEndLoop(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 */ 138 void 139 InstrAggNode(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 */ 166 void 167 InstrStartParallelQuery(void) 168 { 169 save_pgBufferUsage = pgBufferUsage; 170 } 171 172 /* report usage after parallel executor shutdown */ 173 void 174 InstrEndParallelQuery(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 */ 181 void 182 InstrAccumParallelQuery(BufferUsage *result) 183 { 184 BufferUsageAdd(&pgBufferUsage, result); 185 } 186 187 /* dst += add */ 188 static void 189 BufferUsageAdd(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 */ 206 static void 207 BufferUsageAccumDiff(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