From d40f69cce15dfa10479c8be31917b33a49d01477 Mon Sep 17 00:00:00 2001 From: Lukas Fittl Date: Sun, 31 Aug 2025 16:37:05 -0700 Subject: [PATCH v3 1/7] Instrumentation: Keep time fields as instrtime, require caller to convert Previously the Instrumentation logic always converted to seconds, only for many of the callers to do unnecessary division to get to milliseconds. Since an upcoming refactoring will split the Instrumentation struct, utilize instrtime always to keep things simpler. --- contrib/auto_explain/auto_explain.c | 2 +- .../pg_stat_statements/pg_stat_statements.c | 2 +- src/backend/commands/explain.c | 8 ++++---- src/backend/executor/instrument.c | 20 ++++++++----------- src/include/executor/instrument.h | 6 +++--- src/include/portability/instr_time.h | 2 ++ 6 files changed, 19 insertions(+), 21 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index 1f4badb4928..c10f2fc0f25 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 f2187167c5c..fe987ceaf40 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 e6edae0845c..46c5bf252fc 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -1835,8 +1835,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 +1901,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 56e635f4700..1c92abe6761 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,14 @@ 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_CMP_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 03653ab6c6c..ba5c986907e 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -77,13 +77,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 f71a851b18d..646934020d1 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_CMP_LT(x,y) \ + ((x).ticks > (y).ticks) #define INSTR_TIME_GET_DOUBLE(t) \ ((double) INSTR_TIME_GET_NANOSEC(t) / NS_PER_S) -- 2.47.1