From e5a5e0a90750d665cab417322b9f85c806430d85 Mon Sep 17 00:00:00 2001 From: Andres Freund Date: Fri, 9 Jan 2026 12:10:53 -0500 Subject: [PATCH] instrumentation: Keep time fields as instrtime, convert in callers Previously the instrumentation logic always converted to seconds, only for many of the callers to do unnecessary division to get to milliseconds. As an upcoming refactoring will split the Instrumentation struct, utilize instrtime always to keep things simpler. It's also a bit faster to not have to first convert to a double in functions like InstrEndLoop(), InstrAggNode(). Author: Lukas Fittl Reviewed-by: Andres Freund Discussion: https://postgr.es/m/CAP53PkzZ3UotnRrrnXWAv=F4avRq9MQ8zU+bxoN9tpovEu6fGQ@mail.gmail.com --- contrib/auto_explain/auto_explain.c | 2 +- .../pg_stat_statements/pg_stat_statements.c | 2 +- src/backend/commands/explain.c | 14 +++++++------ src/backend/executor/instrument.c | 21 ++++++++----------- src/include/executor/instrument.h | 6 +++--- src/include/portability/instr_time.h | 2 ++ 6 files changed, 24 insertions(+), 23 deletions(-) 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) -- 2.39.5