/*------------------------------------------------------------------------- * * instrument.c * functions for instrumentation of plan execution * * * Copyright (c) 2001-2013, PostgreSQL Global Development Group * * IDENTIFICATION * src/backend/executor/instrument.c * *------------------------------------------------------------------------- */ #include "postgres.h" #include #include "executor/instrument.h" BufferUsage pgBufferUsage; static void BufferUsageAccumDiff(BufferUsage *dst, const BufferUsage *add, const BufferUsage *sub); /* Allocate new instrumentation structure(s) */ Instrumentation * InstrAlloc(int n, int instrument_options) { Instrumentation *instr; /* initialize all fields to zeroes, then modify as needed */ instr = palloc0(n * sizeof(Instrumentation)); if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER)) { int i; bool need_buffers = instrument_options & INSTRUMENT_BUFFERS; bool need_timer = instrument_options & INSTRUMENT_TIMER; for (i = 0; i < n; i++) { instr[i].need_bufusage = need_buffers; instr[i].need_timer = need_timer; } } return instr; } /* Entry to a plan node */ void InstrStartNode(Instrumentation *instr) { if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime)) INSTR_TIME_SET_CURRENT(instr->starttime); else elog(DEBUG2, "InstrStartNode called twice in a row"); /* save buffer usage totals at node entry, if needed */ if (instr->need_bufusage) instr->bufusage_start = pgBufferUsage; } /* Exit from a plan node */ void InstrStopNode(Instrumentation *instr, double nTuples) { instr_time endtime; /* count the returned tuples */ instr->tuplecount += nTuples; /* let's update the time only if the timer was requested */ if (instr->need_timer) { if (INSTR_TIME_IS_ZERO(instr->starttime)) { elog(DEBUG2, "InstrStopNode called without start"); return; } INSTR_TIME_SET_CURRENT(endtime); INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime); INSTR_TIME_SET_ZERO(instr->starttime); } /* Add delta of buffer usage since entry to node's totals */ if (instr->need_bufusage) BufferUsageAccumDiff(&instr->bufusage, &pgBufferUsage, &instr->bufusage_start); /* Is this the first tuple of this cycle? */ if (!instr->running) { instr->running = true; instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter); } } /* Finish a run cycle for a plan node */ void InstrEndLoop(Instrumentation *instr) { double totaltime; /* Skip if nothing has happened, or already shut down */ if (!instr->running) return; if (!INSTR_TIME_IS_ZERO(instr->starttime)) elog(DEBUG2, "InstrEndLoop called on running node"); /* Accumulate per-cycle statistics into totals */ totaltime = INSTR_TIME_GET_DOUBLE(instr->counter); instr->startup += instr->firsttuple; instr->total += totaltime; instr->ntuples += instr->tuplecount; instr->nloops += 1; /* Reset for next cycle (if any) */ instr->running = false; INSTR_TIME_SET_ZERO(instr->starttime); INSTR_TIME_SET_ZERO(instr->counter); instr->firsttuple = 0; instr->tuplecount = 0; } /* dst += add - sub */ static void BufferUsageAccumDiff(BufferUsage *dst, const BufferUsage *add, const BufferUsage *sub) { dst->shared_blks_hit += add->shared_blks_hit - sub->shared_blks_hit; dst->shared_blks_read += add->shared_blks_read - sub->shared_blks_read; dst->shared_blks_dirtied += add->shared_blks_dirtied - sub->shared_blks_dirtied; dst->shared_blks_written += add->shared_blks_written - sub->shared_blks_written; dst->local_blks_hit += add->local_blks_hit - sub->local_blks_hit; dst->local_blks_read += add->local_blks_read - sub->local_blks_read; dst->local_blks_dirtied += add->local_blks_dirtied - sub->local_blks_dirtied; dst->local_blks_written += add->local_blks_written - sub->local_blks_written; dst->temp_blks_read += add->temp_blks_read - sub->temp_blks_read; dst->temp_blks_written += add->temp_blks_written - sub->temp_blks_written; INSTR_TIME_ACCUM_DIFF(dst->blk_read_time, add->blk_read_time, sub->blk_read_time); INSTR_TIME_ACCUM_DIFF(dst->blk_write_time, add->blk_write_time, sub->blk_write_time); }