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
>From bd3fa72e58d7e9de5a4a0248895531b955ae99b4 Mon Sep 17 00:00:00 2001 From: Nathan Bossart <nat...@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