/* 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;
}
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);
}
/* 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);
}
}
/*
* 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);
/* 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);
}
QueryExecutor *
executormgr_create_executor(void)
{
QueryExecutor *executor = palloc0(sizeof(QueryExecutor));
INSTR_TIME_SET_ZERO(executor->time_dispatch_begin);
INSTR_TIME_SET_ZERO(executor->time_dispatch_end);
INSTR_TIME_SET_ZERO(executor->time_connect_begin);
INSTR_TIME_SET_ZERO(executor->time_connect_end);
INSTR_TIME_SET_ZERO(executor->time_consume_begin);
INSTR_TIME_SET_ZERO(executor->time_consume_end);
INSTR_TIME_SET_ZERO(executor->time_free_begin);
INSTR_TIME_SET_ZERO(executor->time_free_end);
return executor;
}
/* 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;
}
/*
* Create a new cache instance, or attach to an existing one in shared
* memory.
*
* The cache descriptor is allocated in the top memory context since
* we need it for entry cleanup in case of error
*/
Cache *
Cache_Create(CacheCtl *cacheCtl)
{
Assert(NULL != cacheCtl);
Assert(0 != cacheCtl->maxSize);
Assert(0 != cacheCtl->keySize);
Assert(0 != cacheCtl->entrySize);
Assert(NULL != cacheCtl->keyCopy);
Assert(NULL != cacheCtl->hash);
Assert(NULL != cacheCtl->match);
Assert(NULL != cacheCtl->equivalentEntries);
Assert(NULL != cacheCtl->cleanupEntry);
MemoryContext oldcxt;
/*
* Create Cache in the TopMemoryContext since this memory context
* is still available when calling the transaction callback at the
* time when the transaction aborts
*/
oldcxt = MemoryContextSwitchTo(TopMemoryContext);
Cache *cache = (Cache *) palloc0(sizeof(Cache));
cache->keyCopy = cacheCtl->keyCopy;
cache->hash = cacheCtl->hash;
cache->match = cacheCtl->match;
cache->equivalentEntries = cacheCtl->equivalentEntries;
cache->cleanupEntry = cacheCtl->cleanupEntry;
cache->populateEntry = cacheCtl->populateEntry;
/* Create new linked lists in top memory context for cleanup */
cache->ownedEntries = DLNewList();
cache->cacheName = pstrdup(cacheCtl->cacheName);
Cache_InitHashtable(cacheCtl, cache);
Cache_InitSharedMem(cacheCtl, cache);
INSTR_TIME_SET_ZERO(timedOpStart);
oldcxt = MemoryContextSwitchTo(oldcxt);
return cache;
}
static void
call_graph_fmgr_hook(FmgrHookEventType event,
FmgrInfo *flinfo, Datum *args)
{
bool aborted = false;
EdgeHashKey key;
EdgeHashElem *elem;
instr_time current_time;
if (next_fmgr_hook)
(*next_fmgr_hook) (event, flinfo, args);
INSTR_TIME_SET_CURRENT(current_time);
switch (event)
{
case FHET_START:
{
bool found;
if (call_stack == NIL)
{
top_level_function_oid = flinfo->fn_oid;
/* We're about to enter the top level function; check whether we've been disabled */
if (!enable_call_graph)
{
tracking_current_graph = false;
recursion_depth = 1;
return;
}
/* Start tracking the call graph; we need to create the hash table */
create_edge_hash_table();
tracking_current_graph = true;
/* If we're tracking table usage, take a stat snapshot now */
if (track_table_usage)
table_stat_snapshot = get_table_stat_snapshot();
/* Use InvalidOid for the imaginary edge into the top level function */
key.caller = InvalidOid;
}
else
{
if (!tracking_current_graph)
{
/*
* Not tracking this graph, just see whether we've recursed into the top level function
* (see the comments near the beginning of the file)
*/
if (flinfo->fn_oid == top_level_function_oid)
recursion_depth++;
return;
}
elem = linitial(call_stack);
/* Calculate the self time we spent in the previous function (elem->key.callee in this case). */
INSTR_TIME_ACCUM_DIFF(elem->self_time, current_time, current_self_time_start);
key.caller = elem->key.callee;
}
key.callee = flinfo->fn_oid;
elem = hash_search(edge_hash_table, (void *) &key, HASH_ENTER, &found);
if (found)
elem->num_calls++;
else
{
elem->key = key;
elem->num_calls = 1;
INSTR_TIME_SET_ZERO(elem->total_time);
INSTR_TIME_SET_ZERO(elem->self_time);
}
call_stack = lcons(elem, call_stack);
INSTR_TIME_SET_CURRENT(elem->total_time_start);
memcpy(¤t_self_time_start, &elem->total_time_start, sizeof(instr_time));
}
break;
/*
* In both ABORT and END cases we pop off the last element from the call stack, and if the stack
* is empty, we process the data we gathered.
*
* XXX for some reason if the top level function aborted SPI won't work correctly.
*/
case FHET_ABORT:
aborted = true;
case FHET_END:
/*
* If we're not tracking this particular graph, we only need to see whether we're done
* with the graph or not.
*/
if (!tracking_current_graph)
{
if (top_level_function_oid == flinfo->fn_oid)
{
recursion_depth--;
if (recursion_depth == 0)
top_level_function_oid = InvalidOid;
}
Assert(table_stat_snapshot == NULL);
return;
}
Assert(((EdgeHashElem *) linitial(call_stack))->key.callee == flinfo->fn_oid);
elem = linitial(call_stack);
INSTR_TIME_ACCUM_DIFF(elem->self_time, current_time, current_self_time_start);
INSTR_TIME_ACCUM_DIFF(elem->total_time, current_time, elem->total_time_start);
call_stack = list_delete_first(call_stack);
if (call_stack != NIL)
{
/* we're going back to the previous node, start recording its self_time */
INSTR_TIME_SET_CURRENT(current_self_time_start);
break;
}
/*
* At this point we're done with the graph. If the top level function exited cleanly, we can
* process the data we've gathered in the hash table and add that data into the buffer table.
*/
if (!aborted)
{
/*
* It is in some cases possible that process_edge_data() throws an exception. We really need to
* clean up our state in case that happens.
*/
PG_TRY();
{
Datum buffer_id = assign_callgraph_buffer_id();
/* Better check both conditions here */
if (table_stat_snapshot && track_table_usage)
insert_snapshot_delta(buffer_id, table_stat_snapshot);
process_edge_data(buffer_id);
}
PG_CATCH();
{
if (table_stat_snapshot)
{
release_table_stat_snapshot(table_stat_snapshot);
table_stat_snapshot = NULL;
}
destroy_edge_hash_table();
top_level_function_oid = InvalidOid;
PG_RE_THROW();
}
PG_END_TRY();
}
if (table_stat_snapshot)
{
release_table_stat_snapshot(table_stat_snapshot);
table_stat_snapshot = NULL;
}
destroy_edge_hash_table();
top_level_function_oid = InvalidOid;
break;
default:
elog(ERROR, "Unknown FmgrHookEventType %d", event);
return;
}
}
