pg_upgrade: Add setup to log timing for check and upgrade steps

contrib/pg_upgrade/greenplum/pg_upgrade_greenplum.h

@@ -9,10 +9,16 @@
 
 
 #include "pg_upgrade.h"
+#include <portability/instr_time.h>
 
 
 #define PG_OPTIONS_UTILITY_MODE " PGOPTIONS='-c gp_session_role=utility' "
 
+typedef struct {
+	instr_time start_time;
+	instr_time end_time;
+} step_timer;
+static step_timer timer;
 
 /*
  * Enumeration for operations in the progress report
@@ -118,6 +124,8 @@ void check_greenplum(void);
 void report_progress(ClusterInfo *cluster, progress_type op, char *fmt,...)
 pg_attribute_printf(3, 4);
 void close_progress(void);
+void log_with_timing(step_timer *timer, const char *msg);
+void duration(instr_time duration, char *buf, size_t len);
 
 /* tablespace_gp.c */
 

contrib/pg_upgrade/greenplum/reporting.c

@@ -126,3 +126,39 @@ close_progress(void)
 	progress_counter = 0;
 	progress_prev = epoch_us();
 }
+
+void
+duration(instr_time duration, char *buf, size_t len)
+{
+	int seconds = INSTR_TIME_GET_DOUBLE(duration);
+	// convert total seconds to hour, minute and seconds
+	int h = (seconds / 3600);
+	int m = (seconds - (3600 * h)) / 60;
+	int s = (seconds - (3600 * h) - (60 * m));
+	if (h > 0) {
+		snprintf(buf, len, "%dh%dm%ds", h, m, s);
+	} else if (m > 0) {
+		snprintf(buf, len, "%dm%ds", m, s);
+	} else if (s > 0){
+		snprintf(buf, len, "%ds", s);
+	} else {
+		snprintf(buf, len, "%.3fms", INSTR_TIME_GET_MILLISEC(duration));
+	}
+}
+
+void
+log_with_timing(step_timer *st, const char *msg)
+{
+	size_t len=20;
+	char elapsed_time[len];
+	Assert(st->start_time.tv_sec != 0);
+	INSTR_TIME_SET_CURRENT(st->end_time);
+	INSTR_TIME_SUBTRACT(st->end_time, st->start_time);
+	duration(st->end_time, elapsed_time, len);
+
+	report_status(PG_REPORT, "%s %s", msg, elapsed_time);
+	fflush(stdout);
+
+	INSTR_TIME_SET_ZERO(st->start_time);
+	INSTR_TIME_SET_ZERO(st->end_time);
+}

contrib/pg_upgrade/pg_upgrade.c

@@ -108,12 +108,15 @@ main(int argc, char **argv)
 	char	   *analyze_script_file_name = NULL;
 	char	   *deletion_script_file_name = NULL;
 	bool		live_check = false;
+	step_timer 	t;
 
 	/* Ensure that all files created by pg_upgrade are non-world-readable */
 	umask(S_IRWXG | S_IRWXO);
 
 	parseCommandLine(argc, argv);
 
+	INSTR_TIME_SET_CURRENT(t.start_time);
+
 	get_restricted_token(os_info.progname);
 
 	adjust_data_dir(&old_cluster);
@@ -138,11 +141,14 @@ main(int argc, char **argv)
 	start_postmaster(&new_cluster, true);
 
 	check_new_cluster();
+	log_with_timing(&t, "\nPerforming Consistency Checks took");
 	report_clusters_compatible();
 
 	pg_log(PG_REPORT, "\nPerforming Upgrade\n");
 	pg_log(PG_REPORT, "------------------\n");
 
+	INSTR_TIME_SET_CURRENT(t.start_time);
+
 	prepare_new_cluster();
 
 	stop_postmaster(false);
@@ -260,6 +266,8 @@ main(int argc, char **argv)
 
 	issue_warnings_and_set_wal_level(sequence_script_file_name);
 
+	log_with_timing(&t, "\nPerforming Upgrade took");
+
 	pg_log(PG_REPORT, "\nUpgrade Complete\n");
 	pg_log(PG_REPORT, "----------------\n");
 

contrib/pg_upgrade/relfilenode.c

@@ -38,7 +38,7 @@ void
 transfer_all_new_tablespaces(DbInfoArr *old_db_arr, DbInfoArr *new_db_arr,
 							 char *old_pgdata, char *new_pgdata)
 {
-	pg_log(PG_REPORT, "%s user relation files\n",
+	prep_status("%s user relation files\n",
 	  user_opts.transfer_mode == TRANSFER_MODE_LINK ? "Linking" : "Copying");
 
 	/*

contrib/pg_upgrade/test/integration/init_file

@@ -3,7 +3,13 @@
 -- Individual tests can contain additional patterns specific to the test.
 
 -- start_matchignore
-m/^Checking.*\s+ok$/
+m/^Checking.*\s+ok\s\d.*/
+-- end_matchignore
+-- start_matchignore
+m/Creating a dump of all tablespace metadata.*ok\s\d.*/
+-- end_matchignore
+-- start_matchignore
+m/Performing Consistency Checks took\s\d.*/
 -- end_matchignore
 -- start_matchsubs
 m/\d+ public.table_part_1_prt_part1/

contrib/pg_upgrade/test/integration/output/different_name_index_backed_constraint.source

@@ -33,7 +33,6 @@ INSERT 1
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for unique or primary key constraints              fatal
 
 | Your installation contains unique or primary key constraints

contrib/pg_upgrade/test/integration/output/exchange_partition_heap_table.source

@@ -16,7 +16,6 @@ CREATE
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking array types derived from partitions                fatal
 
 Array types derived from partitions of a partitioned table must not have dependants.

contrib/pg_upgrade/test/integration/output/foreign_key_constraint.source

@@ -20,8 +20,6 @@ INSERT 2
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Checking cluster versions                                   ok
-Creating a dump of all tablespace metadata.                 ok
 Checking for foreign key constraints on root partitions     fatal
 
 Your installation contains foreign key constraint on root 

contrib/pg_upgrade/test/integration/output/gphdfs.source

@@ -4,7 +4,6 @@ CREATE
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for users assigned the gphdfs role                 fatal
 
 | Your installation contains roles that have gphdfs privileges.

contrib/pg_upgrade/test/integration/output/indexes.source

@@ -107,7 +107,6 @@ RESET
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for invalid indexes                                fatal
 
 Your installation contains invalid indexes.  These indexes either 

contrib/pg_upgrade/test/integration/output/large_objects.source

@@ -16,7 +16,6 @@ SELECT count(*) FROM pg_largeobject;
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for large objects                                  fatal
 
 Your installation contains large objects.  These objects are not supported
@@ -41,7 +40,7 @@ SELECT lo_unlink(loid) FROM pg_largeobject;
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
+
 
 *Clusters are compatible*
 

contrib/pg_upgrade/test/integration/output/mismatched_aopartition_indexes.source

@@ -14,7 +14,6 @@ INSERT 2
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for non-covering indexes on partitioned AO tables  fatal
 
 | Your installation contains partitioned append-only tables

contrib/pg_upgrade/test/integration/output/mismatched_partition_schemas.source

@@ -18,7 +18,6 @@ ALTER
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking schemas on partitioned tables                      fatal
 
 Your installation contains partitioned tables where one or more

contrib/pg_upgrade/test/integration/output/partitioned_heap_table_with_differently_aligned_dropped_columns.source

@@ -26,7 +26,6 @@ ALTER
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for heterogeneous partitioned tables               fatal
 
 | Your installation contains heterogenous partitioned tables

contrib/pg_upgrade/test/integration/output/partitioned_heap_table_with_differently_aligned_varlen_dropped_columns.source

@@ -24,7 +24,6 @@ ALTER
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for heterogeneous partitioned tables               fatal
 
 | Your installation contains heterogenous partitioned tables

contrib/pg_upgrade/test/integration/output/partitioned_heap_table_with_differently_sized_dropped_columns.source

@@ -19,7 +19,6 @@ ALTER
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for heterogeneous partitioned tables               fatal
 
 | Your installation contains heterogenous partitioned tables

contrib/pg_upgrade/test/integration/output/unsupported_dist_coltypes.source

@@ -25,7 +25,6 @@ INSERT 1
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for abstime, reltime, tinterval user data types    fatal
 
 Your installation contains a user table, that uses a 'abstime',

contrib/pg_upgrade/test/integration/output/unsupported_name_col.source

@@ -8,7 +8,6 @@ INSERT 1
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for invalid "name" user columns                    fatal
 
 Your installation contains the "name" data type in user tables.  This

contrib/pg_upgrade/test/integration/output/unsupported_tsquery_col.source

@@ -9,7 +9,6 @@ INSERT 4
 ! ./gpdb6/bin/pg_upgrade --mode=dispatcher --old-gp-dbid=1 --new-gp-dbid=1 --check --old-bindir=@upgrade_test_path@/gpdb5/bin --new-bindir=@upgrade_test_path@/gpdb6/bin --old-datadir=@upgrade_test_path@/gpdb5-data/qddir/demoDataDir-1 --new-datadir=@upgrade_test_path@/gpdb6-data/qddir/demoDataDir-1 --old-port=@old_port@;
 Performing Consistency Checks on Old Live Server
 ------------------------------------------------
-Creating a dump of all tablespace metadata.                 ok
 Checking for tsquery user columns                           fatal
 
 Your installation contains the "tsquery" data type.    This data type

contrib/pg_upgrade/test/unit/Makefile

@@ -10,14 +10,16 @@ OBJS = tablespace_test.o \
 	check_gp_test.o \
 	mock_server.o \
 	mock_util.o \
-	info_gp_test.o
+	info_gp_test.o \
+	reporting_test.o
 
 TARGETS = tablespace_test \
 	old_tablespace_file_contents_test \
 	old_tablespace_file_parser_test \
 	tablespace_gp_test \
 	check_gp_test \
-	info_gp_test
+	info_gp_test \
+	reporting_test
 
 include $(top_srcdir)/src/Makefile.global
 include $(top_srcdir)/src/Makefile.mock
@@ -55,5 +57,8 @@ check_gp_test.t: mock_util.o \
 	$(pg_upgrade_greenplum_directory)/option_gp.o
 	$(compile_test)
 
+reporting_test.t: reporting_test.o $(pg_upgrade_greenplum_directory)/reporting.o $(test_dependencies)
+	$(compile_test)
+
 clean:
-	rm -f *.t *.o
\ No newline at end of file
+	rm -f *.t *.o

contrib/pg_upgrade/test/unit/reporting_test.c

+#include "cmockery_gp.h"
+
+#include "pg_upgrade.h"
+#include "portability/instr_time.h"
+
+#include "greenplum/pg_upgrade_greenplum.h"
+#include "pg_upgrade_dummies.c"
+
+
+ClusterInfo new_cluster;
+ClusterInfo old_cluster;
+
+bool
+is_show_progress_mode(void)
+{
+	return false;
+}
+
+void
+pg_log(eLogType type, const char *fmt,...)
+{
+
+}
+
+static void
+test_duration_ms(void **state) {
+	size_t len=20;
+	char elapsed_time[len];
+	instr_time t = {0, 908234};
+	duration(t, elapsed_time, len);
+	assert_string_equal(elapsed_time, "908.234ms");
+}
+
+static void
+test_duration_second(void **state) {
+	size_t len=20;
+	char elapsed_time[len];
+	instr_time t = {0, 9082340};
+	duration(t, elapsed_time, len);
+	assert_string_equal(elapsed_time, "9s");
+}
+
+static void
+test_duration_minute_second(void **state) {
+	size_t len=20;
+	char elapsed_time[len];
+	instr_time t = {90, 9082340};
+	duration(t, elapsed_time, len);
+	assert_string_equal(elapsed_time, "1m39s");
+}
+
+static void
+test_duration_hour_minute_second(void **state) {
+	size_t len=20;
+	char elapsed_time[len];
+	instr_time t = {9000, 9082340};
+	duration(t, elapsed_time, len);
+	assert_string_equal(elapsed_time, "2h30m9s");
+}
+
+int
+main(int argc, char *argv[])
+{
+	const UnitTest tests[] = {
+			unit_test(test_duration_ms),
+			unit_test(test_duration_second),
+			unit_test(test_duration_minute_second),
+			unit_test(test_duration_hour_minute_second),
+	};
+	return run_tests(tests);
+}
\ No newline at end of file

contrib/pg_upgrade/util.c

@@ -70,6 +70,12 @@ prep_status(const char *fmt,...)
 	va_list		args;
 	char		message[MAX_STRING];
 
+	/*
+	 * If the start time is not set, it means a new step is being started.
+	 */
+	if (INSTR_TIME_IS_ZERO(timer.start_time))
+		INSTR_TIME_SET_CURRENT(timer.start_time);
+
 	va_start(args, fmt);
 	vsnprintf(message, sizeof(message), fmt, args);
 	va_end(args);
@@ -172,9 +178,7 @@ pg_fatal(const char *fmt,...)
 void
 check_ok(void)
 {
-	/* all seems well */
-	report_status(PG_REPORT, "ok");
-	fflush(stdout);
+	log_with_timing(&timer, "ok");
 }