v4-0001-Instrumentation-Keep-time-fields-as-instrtime-req.patch
application/octet-stream
Filename: v4-0001-Instrumentation-Keep-time-fields-as-instrtime-req.patch
Type: application/octet-stream
Part: 1
From 1e8e2d54997602cfc289d8eb850b2a8e9745040c Mon Sep 17 00:00:00 2001
From: Lukas Fittl <lukas@fittl.com>
Date: Sun, 31 Aug 2025 16:37:05 -0700
Subject: [PATCH v4 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 | 12 +++++------
src/backend/executor/instrument.c | 20 ++++++++-----------
src/include/executor/instrument.h | 6 +++---
src/include/portability/instr_time.h | 2 ++
6 files changed, 21 insertions(+), 23 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 39208f80b5b..47de4c98ae3 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 7e699f8595e..ba34cce26eb 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -1136,7 +1136,7 @@ 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 +1147,7 @@ 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 +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 9e11c662a7c..20653a5c4c4 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_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 ffe470f2b84..dfc8b3c9765 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 f71a851b18d..1c1c18f780a 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.47.1