diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 620cd63b376..e856cd35a6f 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -388,7 +388,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) InstrEndLoop(queryDesc->totaltime); /* Log plan if duration is exceeded. */ - msec = queryDesc->totaltime->total * 1000.0; + msec = INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total); if (msec >= auto_explain_log_min_duration) { ExplainState *es = NewExplainState(); diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 04c3c4599c9..adc493e9850 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -1093,7 +1093,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) queryDesc->plannedstmt->stmt_location, queryDesc->plannedstmt->stmt_len, PGSS_EXEC, - queryDesc->totaltime->total * 1000.0, /* convert to msec */ + INSTR_TIME_GET_MILLISEC(queryDesc->totaltime->total), queryDesc->estate->es_total_processed, &queryDesc->totaltime->bufusage, &queryDesc->totaltime->walusage, diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 1e68ad1565f..b7bb111688c 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1136,7 +1136,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) appendStringInfo(es->str, " on %s", relname); if (es->timing) appendStringInfo(es->str, ": time=%.3f calls=%.0f\n", - 1000.0 * instr->total, instr->ntuples); + INSTR_TIME_GET_MILLISEC(instr->total), + instr->ntuples); else appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples); } @@ -1147,7 +1148,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es) ExplainPropertyText("Constraint Name", conname, es); ExplainPropertyText("Relation", relname, es); if (es->timing) - ExplainPropertyFloat("Time", "ms", 1000.0 * instr->total, 3, + ExplainPropertyFloat("Time", "ms", + INSTR_TIME_GET_MILLISEC(instr->total), 3, es); ExplainPropertyFloat("Calls", NULL, instr->ntuples, 0, es); } @@ -1835,8 +1837,8 @@ ExplainNode(PlanState *planstate, List *ancestors, planstate->instrument && planstate->instrument->nloops > 0) { double nloops = planstate->instrument->nloops; - double startup_ms = 1000.0 * planstate->instrument->startup / nloops; - double total_ms = 1000.0 * planstate->instrument->total / nloops; + double startup_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->startup) / nloops; + double total_ms = INSTR_TIME_GET_MILLISEC(planstate->instrument->total) / nloops; double rows = planstate->instrument->ntuples / nloops; if (es->format == EXPLAIN_FORMAT_TEXT) @@ -1901,8 +1903,8 @@ ExplainNode(PlanState *planstate, List *ancestors, if (nloops <= 0) continue; - startup_ms = 1000.0 * instrument->startup / nloops; - total_ms = 1000.0 * instrument->total / nloops; + startup_ms = INSTR_TIME_GET_MILLISEC(instrument->startup) / nloops; + total_ms = INSTR_TIME_GET_MILLISEC(instrument->total) / nloops; rows = instrument->ntuples / nloops; ExplainOpenWorker(n, es); diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index 9eb6bcb9a8d..edab92a0ebe 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -114,7 +114,7 @@ InstrStopNode(Instrumentation *instr, double nTuples) if (!instr->running) { instr->running = true; - instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter); + instr->firsttuple = instr->counter; } else { @@ -123,7 +123,7 @@ InstrStopNode(Instrumentation *instr, double nTuples) * this might be the first tuple */ if (instr->async_mode && save_tuplecount < 1.0) - instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter); + instr->firsttuple = instr->counter; } } @@ -139,8 +139,6 @@ InstrUpdateTupleCount(Instrumentation *instr, double nTuples) void InstrEndLoop(Instrumentation *instr) { - double totaltime; - /* Skip if nothing has happened, or already shut down */ if (!instr->running) return; @@ -149,10 +147,8 @@ InstrEndLoop(Instrumentation *instr) elog(ERROR, "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_TIME_ADD(instr->startup, instr->firsttuple); + INSTR_TIME_ADD(instr->total, instr->counter); instr->ntuples += instr->tuplecount; instr->nloops += 1; @@ -160,7 +156,7 @@ InstrEndLoop(Instrumentation *instr) instr->running = false; INSTR_TIME_SET_ZERO(instr->starttime); INSTR_TIME_SET_ZERO(instr->counter); - instr->firsttuple = 0; + INSTR_TIME_SET_ZERO(instr->firsttuple); instr->tuplecount = 0; } @@ -173,14 +169,15 @@ InstrAggNode(Instrumentation *dst, Instrumentation *add) dst->running = true; dst->firsttuple = add->firsttuple; } - else if (dst->running && add->running && dst->firsttuple > add->firsttuple) + else if (dst->running && add->running && + INSTR_TIME_LT(dst->firsttuple, add->firsttuple)) dst->firsttuple = add->firsttuple; INSTR_TIME_ADD(dst->counter, add->counter); dst->tuplecount += add->tuplecount; - dst->startup += add->startup; - dst->total += add->total; + INSTR_TIME_ADD(dst->startup, add->startup); + INSTR_TIME_ADD(dst->total, add->total); dst->ntuples += add->ntuples; dst->ntuples2 += add->ntuples2; dst->nloops += add->nloops; diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 95ab372eb87..9759f3ea5d8 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -78,13 +78,13 @@ typedef struct Instrumentation bool running; /* true if we've completed first tuple */ instr_time starttime; /* start time of current iteration of node */ instr_time counter; /* accumulated runtime for this node */ - double firsttuple; /* time for first tuple of this cycle */ + instr_time firsttuple; /* time for first tuple of this cycle */ double tuplecount; /* # of tuples emitted so far this cycle */ BufferUsage bufusage_start; /* buffer usage at start */ WalUsage walusage_start; /* WAL usage at start */ /* Accumulated statistics across all completed cycles: */ - double startup; /* total startup time (in seconds) */ - double total; /* total time (in seconds) */ + instr_time startup; /* total startup time */ + instr_time total; /* total time */ double ntuples; /* total tuples produced */ double ntuples2; /* secondary node-specific tuple counter */ double nloops; /* # of run cycles for this node */ diff --git a/src/include/portability/instr_time.h b/src/include/portability/instr_time.h index 6257786aaa6..490593d1825 100644 --- a/src/include/portability/instr_time.h +++ b/src/include/portability/instr_time.h @@ -184,6 +184,8 @@ GetTimerFrequency(void) #define INSTR_TIME_ACCUM_DIFF(x,y,z) \ ((x).ticks += (y).ticks - (z).ticks) +#define INSTR_TIME_LT(x,y) \ + ((x).ticks > (y).ticks) #define INSTR_TIME_GET_DOUBLE(t) \ ((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S)