/* * 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); }