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 <lukas@fittl.com>
Reviewed-by: Andres Freund <andres@anarazel.de>
Discussion: https://postgr.es/m/CAP53PkzZ3UotnRrrnXWAv=F4avRq9MQ8zU+bxoN9tpovEu6fGQ@mail.gmail.com

diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 620cd63b376fb65c7026f14bdc9b7b07ad6ab48f..e856cd35a6f0fb2d906d253dcf2bd6df956bd40a 100644 (file)
--- 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 04c3c4599c90f49c8892225d2d65fa0f02cb8092..adc493e9850e44dd8be4af19bf943c473260c24e 100644 (file)
--- 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 1e68ad1565fd71da47029bcc28eaef051c8027b6..b7bb111688cec06aafa4ed27b466d493a44faedd 100644 (file)
--- 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 9eb6bcb9a8d051619331f86a568cb38a725a0239..edab92a0ebeda14946564e2642a727b43c69276b 100644 (file)
--- 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 95ab372eb87ff358a992f7f3e2608f731367f27a..9759f3ea5d8d90eb7a6c4504badfd83b72dd11df 100644 (file)
--- 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 6257786aaa6e11a2f3bc9fcd8e183c1eb82d73bd..490593d182512e80bc232cad34d6c0679b5f5f44 100644 (file)
--- 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)