/* 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; }
/* * Records elapsed since the last Cache_TimedOperationStart. * * Accumulated total time goes in totalTime, maximum time goes into maxTime. * * Used in conjunction with Cache_TimedOperationStart */ void Cache_TimedOperationRecord(instr_time *totalTime, instr_time *maxTime) { Assert(!INSTR_TIME_IS_ZERO(timedOpStart)); instr_time elapsedTime; INSTR_TIME_SET_CURRENT(elapsedTime); INSTR_TIME_SUBTRACT(elapsedTime, timedOpStart); /* Add difference to totalTime */ /* FIXME This is not atomic */ INSTR_TIME_ADD(*totalTime, elapsedTime); /* Compare elapsed time with current maximum and record if new maximum */ if (INSTR_TIME_GET_DOUBLE(elapsedTime) > INSTR_TIME_GET_DOUBLE(*maxTime)) { /* FIXME This is not atomic */ INSTR_TIME_ASSIGN(*maxTime, elapsedTime); } #ifdef USE_ASSERT_CHECKING INSTR_TIME_SET_ZERO(timedOpStart); #endif }
/* Exit from a plan node */ void InstrStopNode(Instrumentation *instr, double nTuples) { instr_time endtime; /* count the returned tuples */ instr->tuplecount += nTuples; 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); } }
/* Exit from a plan node */ void InstrStopNode(Instrumentation *instr, double nTuples) { instr_time endtime; /* count the returned tuples */ instr->tuplecount += nTuples; 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); /* Is this the first tuple of this cycle? */ if (!instr->running) { instr->running = true; instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter); /* CDB: save this start time as the first start */ instr->firststart = instr->starttime; } INSTR_TIME_SET_ZERO(instr->starttime); }
/* Entry to a plan node */ void InstrStartNode(Instrumentation *instr) { if (INSTR_TIME_IS_ZERO(instr->starttime)) INSTR_TIME_SET_CURRENT(instr->starttime); else elog(DEBUG2, "InstrStartNode called twice in a row"); }
/* Entry to a plan node */ void InstrStartNode(Instrumentation *instr) { if (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; }
/* Entry to a plan node */ void InstrStartNode(Instrumentation *instr) { if (INSTR_TIME_IS_ZERO(instr->starttime)) INSTR_TIME_SET_CURRENT(instr->starttime); else elog(DEBUG2, "InstrStartNode called twice in a row"); /* initialize buffer usage per plan node */ if (instr->needs_bufusage) instr->bufusage_start = pgBufferUsage; }
/* 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); /* CDB: Report startup time from only the first cycle. */ if (instr->nloops == 0) instr->startup = instr->firsttuple; instr->total += totaltime; instr->totalLast += totaltime; instr->ntuples += instr->tuplecount; instr->nloops += 1; if (Debug_print_execution_detail) { elog(DEBUG1,"instr->total: %.3f ms, instr->ntuples: %.3f, instr->nloops: %.3f", 1000.0 * instr->total, instr->ntuples, instr->nloops); } /* 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; }