/*
* 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
}
void opt_BufFileInstr(BufFile *file){
printf("BufFile, number of load file: %ld times \n", file->fileLoadNum);
file->fileLoadNum = 0;
printf("BufFile, load file: %f seconds \n", INSTR_TIME_GET_DOUBLE(file->instr_fileload->counter));
INSTR_TIME_SET_ZERO(file->instr_fileload->counter);
printf("BufFile, number of dump file: %ld times \n", file->fileDumpNum);
file->fileDumpNum = 0;
printf("BufFile, dump file: %f seconds \n", INSTR_TIME_GET_DOUBLE(file->instr_filedump->counter));
INSTR_TIME_SET_ZERO(file->instr_filedump->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;
}
/* 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);
}
static uint64
test_timing(int32 duration)
{
uint64 total_time;
int64 time_elapsed = 0;
uint64 loop_count = 0;
uint64 prev,
cur;
instr_time start_time,
end_time,
temp;
total_time = duration > 0 ? duration * 1000000 : 0;
INSTR_TIME_SET_CURRENT(start_time);
cur = INSTR_TIME_GET_MICROSEC(start_time);
while (time_elapsed < total_time)
{
int32 diff,
bits = 0;
prev = cur;
INSTR_TIME_SET_CURRENT(temp);
cur = INSTR_TIME_GET_MICROSEC(temp);
diff = cur - prev;
/* Did time go backwards? */
if (diff < 0)
{
printf("Detected clock going backwards in time.\n");
printf("Time warp: %d microseconds\n", diff);
exit(1);
}
/* What is the highest bit in the time diff? */
while (diff)
{
diff >>= 1;
bits++;
}
/* Update appropriate duration bucket */
histogram[bits]++;
loop_count++;
INSTR_TIME_SUBTRACT(temp, start_time);
time_elapsed = INSTR_TIME_GET_MICROSEC(temp);
}
INSTR_TIME_SET_CURRENT(end_time);
INSTR_TIME_SUBTRACT(end_time, start_time);
printf("Per loop time including overhead: %0.2f nsec\n",
INSTR_TIME_GET_DOUBLE(end_time) * 1e9 / loop_count);
return loop_count;
}
/*
* ProcessUtility hook
*/
static void
pg_record_ProcessUtility(Node *parsetree, const char *queryString,
ParamListInfo params, bool isTopLevel,
DestReceiver *dest, char *completionTag)
{
if ((nesting_level == 0) && collect)
{
instr_time start;
instr_time duration;
float seconds;
INSTR_TIME_SET_CURRENT(start);
nesting_level++;
PG_TRY();
{
if (prev_ProcessUtility)
prev_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
else
standard_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
nesting_level--;
}
PG_CATCH();
{
nesting_level--;
PG_RE_THROW();
}
PG_END_TRY();
INSTR_TIME_SET_CURRENT(duration);
INSTR_TIME_SUBTRACT(duration, start);
seconds = INSTR_TIME_GET_DOUBLE(duration);
buffer_add_query(seconds, queryString);
}
else
{
if (prev_ProcessUtility)
prev_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
else
standard_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
}
}
/* 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;
}
/*
* ProcessUtility hook
*/
static void
pgss_ProcessUtility(Node *parsetree, const char *queryString,
ParamListInfo params, bool isTopLevel,
DestReceiver *dest, char *completionTag)
{
if (pgss_track_utility && pgss_enabled())
{
instr_time start;
instr_time duration;
uint64 rows = 0;
BufferUsage bufusage;
bufusage = pgBufferUsage;
INSTR_TIME_SET_CURRENT(start);
nested_level++;
PG_TRY();
{
if (prev_ProcessUtility)
prev_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
else
standard_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
nested_level--;
}
PG_CATCH();
{
nested_level--;
PG_RE_THROW();
}
PG_END_TRY();
INSTR_TIME_SET_CURRENT(duration);
INSTR_TIME_SUBTRACT(duration, start);
/* parse command tag to retrieve the number of affected rows. */
if (completionTag &&
sscanf(completionTag, "COPY " UINT64_FORMAT, &rows) != 1)
rows = 0;
/* calc differences of buffer counters. */
bufusage.shared_blks_hit =
pgBufferUsage.shared_blks_hit - bufusage.shared_blks_hit;
bufusage.shared_blks_read =
pgBufferUsage.shared_blks_read - bufusage.shared_blks_read;
bufusage.shared_blks_written =
pgBufferUsage.shared_blks_written - bufusage.shared_blks_written;
bufusage.local_blks_hit =
pgBufferUsage.local_blks_hit - bufusage.local_blks_hit;
bufusage.local_blks_read =
pgBufferUsage.local_blks_read - bufusage.local_blks_read;
bufusage.local_blks_written =
pgBufferUsage.local_blks_written - bufusage.local_blks_written;
bufusage.temp_blks_read =
pgBufferUsage.temp_blks_read - bufusage.temp_blks_read;
bufusage.temp_blks_written =
pgBufferUsage.temp_blks_written - bufusage.temp_blks_written;
pgss_store(queryString, INSTR_TIME_GET_DOUBLE(duration), rows,
&bufusage);
}
else
{
if (prev_ProcessUtility)
prev_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
else
standard_ProcessUtility(parsetree, queryString, params,
isTopLevel, dest, completionTag);
}
}
/**
* @brief Output the result of profile check.
*/
static void
BULKLOAD_PROFILE_PRINT()
{
int i;
double seconds[10];
const char *GLOBALs[] = { "INIT", "READER", "WRITER", "RESET", "FLUSH", "MERGE", "INDEX", "REINDEX", "FINI" };
const char *READERs[] = { "SOURCE", "PARSER" };
const char *WRITERs[] = { "TOAST", "TABLE", "INDEX" };
const char *MERGEs[] = { "UNIQUE", "INSERT", "TERM" };
/* GLOBAL */
i = 0;
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_init);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_reader);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_writer);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_reset);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_flush);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_merge);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_index);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_reindex);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_fini);
print_profiles("GLOBAL", i, GLOBALs, seconds);
/* READER */
i = 0;
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_reader_source);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_reader_parser);
print_profiles("READER", i, READERs, seconds);
/* WRITER */
i = 0;
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_writer_toast);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_writer_table);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_writer_index);
print_profiles("WRITER", i, WRITERs, seconds);
/* MERGE */
i = 0;
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_merge_unique);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_merge_insert);
seconds[i++] = INSTR_TIME_GET_DOUBLE(prof_merge_term);
print_profiles("MERGE", i, MERGEs, seconds);
}
