Date: Fri, 28 Jul 2023 11:47:35 -0700
From: Nathan Bossart <nathandbossart@gmail.com>
To: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Cc: PostgreSQL-development <pgsql-hackers@postgresql.org>
Subject: Re: add timing information to pg_upgrade
Message-ID: <20230728184735.GC3661419@nathanxps13>
References: <20230727235134.GA3658499@nathanxps13>
 <CALj2ACUT86rjj5Vf5gt-bceUx4C43vcML7zbNW4NyGyo-iN3xw@mail.gmail.com>
 <20230728173814.GA3765390@nathanxps13>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="vtzGhvizbBRQ85DL"
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20230728173814.GA3765390@nathanxps13>
Archived-At: 
 <https://www.postgresql.org/message-id/20230728184735.GC3661419%40nathanxps13>
Precedence: bulk


--vtzGhvizbBRQ85DL
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit

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

--vtzGhvizbBRQ85DL
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="v2-0001-add-timing-information-to-pg_upgrade.patch"

From 6a4b836b33c3e18a57438044a10da95ec89dcb65 Mon Sep 17 00:00:00 2001
From: Nathan Bossart <nathan@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


--vtzGhvizbBRQ85DL--