Date: Thu, 27 Jul 2023 16:51:34 -0700
From: Nathan Bossart <nathandbossart@gmail.com>
To: pgsql-hackers@postgresql.org
Subject: add timing information to pg_upgrade
Message-ID: <20230727235134.GA3658499@nathanxps13>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="gBBFr7Ir9EOA20Yy"
Content-Disposition: inline
Archived-At: <https://www.postgresql.org/message-id/20230727235134.GA3658499%40nathanxps13>
Precedence: bulk


--gBBFr7Ir9EOA20Yy
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

I've been looking into some options for reducing the amount of downtime
required for pg_upgrade, and $SUBJECT seemed like something that would be
worthwhile independent of that effort.  The attached work-in-progress patch
adds the elapsed time spent in each step, which looks like this:

  Performing Consistency Checks
  -----------------------------
  Checking cluster versions                                   ok (took 0 ms)
  Checking database user is the install user                  ok (took 3 ms)
  Checking database connection settings                       ok (took 4 ms)
  Checking for prepared transactions                          ok (took 2 ms)
  Checking for system-defined composite types in user tables  ok (took 82 ms)
  Checking for reg* data types in user tables                 ok (took 55 ms)
  ...

This information can be used to better understand where the time is going
and to validate future improvements.  I'm open to suggestions on formatting
the timing information, assuming folks are interested in this idea.

Thoughts?

-- 
Nathan Bossart
Amazon Web Services: https://aws.amazon.com

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

From bd3fa72e58d7e9de5a4a0248895531b955ae99b4 Mon Sep 17 00:00:00 2001
From: Nathan Bossart <nathan@postgresql.org>
Date: Thu, 27 Jul 2023 16:16:45 -0700
Subject: [PATCH v1 1/1] add timing information to pg_upgrade

---
 src/bin/pg_upgrade/util.c | 19 ++++++++++++++++++-
 1 file changed, 18 insertions(+), 1 deletion(-)

diff --git a/src/bin/pg_upgrade/util.c b/src/bin/pg_upgrade/util.c
index 21ba4c8f12..d1b506a741 100644
--- a/src/bin/pg_upgrade/util.c
+++ b/src/bin/pg_upgrade/util.c
@@ -16,6 +16,8 @@
 
 LogOpts		log_opts;
 
+static struct timeval step_start;
+
 static void pg_log_v(eLogType type, const char *fmt, va_list ap) pg_attribute_printf(2, 0);
 
 
@@ -137,6 +139,8 @@ prep_status(const char *fmt,...)
 
 	/* trim strings */
 	pg_log(PG_REPORT_NONL, "%-*s", MESSAGE_WIDTH, message);
+
+	gettimeofday(&step_start, NULL);
 }
 
 /*
@@ -170,6 +174,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);
+
+	gettimeofday(&step_start, NULL);
 }
 
 static void
@@ -283,8 +289,19 @@ pg_fatal(const char *fmt,...)
 void
 check_ok(void)
 {
+	struct timeval step_end;
+	int64		elapsed_ms;
+	int64		start_ms;
+	int64		end_ms;
+
+	gettimeofday(&step_end, NULL);
+
+	start_ms = (step_start.tv_sec * 1000L) + (step_start.tv_usec / 1000L);
+	end_ms = (step_end.tv_sec * 1000L) + (step_end.tv_usec / 1000L);
+	elapsed_ms = end_ms - start_ms;
+
 	/* all seems well */
-	report_status(PG_REPORT, "ok");
+	report_status(PG_REPORT, "ok (took %ld ms)", elapsed_ms);
 }
 
 
-- 
2.25.1


--gBBFr7Ir9EOA20Yy--