On Fri, Jul 28, 2023 at 10:38:14AM -0700, Nathan Bossart wrote:
> I'm okay with simply adding the time. However, I wonder if we want to
> switch to seconds, minutes, hours, etc. if the step takes longer. This
> would add a bit of complexity, but it would improve human readability.
> Alternatively, we could keep the code simple and machine readable by always
> using milliseconds.
... or maybe we show both like psql does. Attached іs a new version of the
patch in which I've made use of the INSTR_TIME_* macros and enhanced the
output formatting (largely borrowed from PrintTiming() in
src/bin/psql/common.c).
--
Nathan Bossart
Amazon Web Services: https://aws.amazon.com
>From 6a4b836b33c3e18a57438044a10da95ec89dcb65 Mon Sep 17 00:00:00 2001
From: Nathan Bossart <nat...@postgresql.org>
Date: Thu, 27 Jul 2023 16:16:45 -0700
Subject: [PATCH v2 1/1] add timing information to pg_upgrade
---
src/bin/pg_upgrade/util.c | 55 ++++++++++++++++++++++++++++++++++++++-
1 file changed, 54 insertions(+), 1 deletion(-)
diff --git a/src/bin/pg_upgrade/util.c b/src/bin/pg_upgrade/util.c
index 21ba4c8f12..25e43a593a 100644
--- a/src/bin/pg_upgrade/util.c
+++ b/src/bin/pg_upgrade/util.c
@@ -9,14 +9,19 @@
#include "postgres_fe.h"
+#include <math.h>
#include <signal.h>
#include "common/username.h"
#include "pg_upgrade.h"
+#include "portability/instr_time.h"
LogOpts log_opts;
+static instr_time step_start;
+
static void pg_log_v(eLogType type, const char *fmt, va_list ap) pg_attribute_printf(2, 0);
+static char *get_time_str(double time_ms);
/*
@@ -137,6 +142,8 @@ prep_status(const char *fmt,...)
/* trim strings */
pg_log(PG_REPORT_NONL, "%-*s", MESSAGE_WIDTH, message);
+
+ INSTR_TIME_SET_CURRENT(step_start);
}
/*
@@ -170,6 +177,8 @@ prep_status_progress(const char *fmt,...)
pg_log(PG_REPORT, "%-*s", MESSAGE_WIDTH, message);
else
pg_log(PG_REPORT_NONL, "%-*s", MESSAGE_WIDTH, message);
+
+ INSTR_TIME_SET_CURRENT(step_start);
}
static void
@@ -280,11 +289,55 @@ pg_fatal(const char *fmt,...)
}
+static char *
+get_time_str(double time_ms)
+{
+ double seconds;
+ double minutes;
+ double hours;
+ double days;
+
+ if (time_ms < 1000.0)
+ return psprintf("%.3f ms", time_ms);
+
+ seconds = time_ms / 1000.0;
+ minutes = floor(seconds / 60.0);
+ seconds -= 60.0 * minutes;
+ if (minutes < 60.0)
+ return psprintf("%.3f ms (%02d:%06.3f)",
+ time_ms, (int) minutes, seconds);
+
+ hours = floor(minutes / 60.0);
+ minutes -= 60.0 * hours;
+ if (hours < 24.0)
+ return psprintf("%.3f ms (%02d:%02d:%06.3f)",
+ time_ms, (int) hours, (int) minutes, seconds);
+
+ days = floor(hours / 24.0);
+ hours -= 24.0 * days;
+ return psprintf("%.3f ms (%.0f d %02d:%02d:%06.3f)",
+ time_ms, days, (int) hours, (int) minutes, seconds);
+}
+
+
void
check_ok(void)
{
+ instr_time step_end;
+ char *step_time;
+
+ Assert(!INSTR_TIME_IS_ZERO(step_start));
+
+ INSTR_TIME_SET_CURRENT(step_end);
+ INSTR_TIME_SUBTRACT(step_end, step_start);
+ step_time = get_time_str(INSTR_TIME_GET_MILLISEC(step_end));
+
+ /* reset start time */
+ INSTR_TIME_SET_ZERO(step_start);
+
/* all seems well */
- report_status(PG_REPORT, "ok");
+ report_status(PG_REPORT, "ok\t%s", step_time);
+ pfree(step_time);
}
--
2.25.1
