v12-0001-startup-process-progress.patch

From 8394e2f7d20cc37a29b45a51937cc28dd3ac3e73 Mon Sep 17 00:00:00 2001
From: Nitin <nitin.jadhav@enterprisedb.com>
Date: Thu, 12 Aug 2021 17:08:00 +0530
Subject: [PATCH] Shows the progress of the operations performed during startup
 process. The interval between each progress update is configurable and it
 should be mentioned in seconds

---
 doc/src/sgml/config.sgml                      |  22 ++++++
 src/backend/access/transam/xlog.c             |   9 +++
 src/backend/postmaster/startup.c              | 100 ++++++++++++++++++++++++++
 src/backend/storage/file/fd.c                 |  30 +++++++-
 src/backend/storage/file/reinit.c             |  15 ++++
 src/backend/utils/init/postinit.c             |   2 +
 src/backend/utils/misc/guc.c                  |  14 +++-
 src/backend/utils/misc/postgresql.conf.sample |   6 ++
 src/include/postmaster/startup.h              |  21 ++++++
 src/include/utils/timeout.h                   |   1 +
 10 files changed, 218 insertions(+), 2 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 610372b..b1ae53a 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6543,6 +6543,28 @@ local0.*    /var/log/postgresql
        </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-log-startup-progress-interval" xreflabel="log_startup_progress_interval">
+      <term><varname>log_startup_progress_interval</varname> (<type>integer</type>)
+      <indexterm>
+       <primary><varname>log_startup_progress_interval</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+       <listitem>
+        <para>
+         Sets the time interval between each progress update of the operations
+         performed during startup process. This produces the log message after
+         every interval of time for the operations that take longer time. The unit
+         used to specify the value is seconds. For example, if you set it to
+         <literal> 10s </literal>, then after every <literal> 10s </literal> there
+         is a log message indicating which operation is going on and what is the
+         elapsed time from beginning. If the value is set to <literal> 0 </literal>,
+         then it logs all the available messages for such operations. <literal> -1
+         </literal> disables the feature. The default value is set to <literal> 10s
+         </literal>
+        </para>
+       </listitem>
+     </varlistentry>
+
      </variablelist>
 
     <para>
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 8b39a2f..80ec116 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -7355,12 +7355,21 @@ StartupXLOG(void)
 							LSN_FORMAT_ARGS(ReadRecPtr))));
 
 			/*
+			 * Begin the startup progress phase to report the progress of redo
+			 * operation.
+			 */
+			begin_startup_progress_phase();
+
+			/*
 			 * main redo apply loop
 			 */
 			do
 			{
 				bool		switchedTLI = false;
 
+				ereport_startup_progress("redo in progress, elapsed time: %ld.%02d s, current LSN: %X/%X",
+										 LSN_FORMAT_ARGS(ReadRecPtr));
+
 #ifdef WAL_DEBUG
 				if (XLOG_DEBUG ||
 					(rmid == RM_XACT_ID && trace_recovery_messages <= DEBUG2) ||
diff --git a/src/backend/postmaster/startup.c b/src/backend/postmaster/startup.c
index 0f4f00d..fa177d6 100644
--- a/src/backend/postmaster/startup.c
+++ b/src/backend/postmaster/startup.c
@@ -59,6 +59,29 @@ static volatile sig_atomic_t promote_signaled = false;
  */
 static volatile sig_atomic_t in_restore_command = false;
 
+/*
+ * Start timestamp of the operation that occur during startup process.
+ */
+static TimestampTz startup_progress_phase_start_time;
+
+/*
+ * Indicates the timestamp at which the timer was supposed to expire.
+ */
+static TimestampTz scheduled_startup_progress_timeout;
+
+/*
+ * Indicates whether the startup progress interval mentioned by the user is
+ * elapsed or not. TRUE if timeout occurred, FALSE otherwise.
+ */
+static volatile sig_atomic_t startup_progress_timer_expired = false;
+
+/*
+ * The interval between each progress update of the operations that occur
+ * during startup process.
+ */
+int log_startup_progress_interval;
+
+
 /* Signal handlers */
 static void StartupProcTriggerHandler(SIGNAL_ARGS);
 static void StartupProcSigHupHandler(SIGNAL_ARGS);
@@ -233,6 +256,7 @@ StartupProcessMain(void)
 	RegisterTimeout(STANDBY_DEADLOCK_TIMEOUT, StandbyDeadLockHandler);
 	RegisterTimeout(STANDBY_TIMEOUT, StandbyTimeoutHandler);
 	RegisterTimeout(STANDBY_LOCK_TIMEOUT, StandbyLockTimeoutHandler);
+	RegisterTimeout(STARTUP_PROGRESS_TIMEOUT, startup_progress_timeout_handler);
 
 	/*
 	 * Unblock signals (they were blocked when the postmaster forked us)
@@ -282,3 +306,79 @@ ResetPromoteSignaled(void)
 {
 	promote_signaled = false;
 }
+
+/*
+ * Schedule a wakeup call for logging the progress of startup process.
+ */
+void
+startup_progress_timeout_handler(void)
+{
+	startup_progress_timer_expired = true;
+}
+
+/*
+ * Sets the start timestamp of the current operation and also enables the
+ * timeout for logging the progress of startup process.
+ */
+void
+begin_startup_progress_phase(void)
+{
+	scheduled_startup_progress_timeout = 0;
+	startup_progress_phase_start_time = GetCurrentTimestamp();
+	reset_startup_progress_timeout(startup_progress_phase_start_time);
+}
+
+/*
+ * Decides whether to log the startup progress or not based on whether the
+ * timer is expired or not. Returns FALSE if the timer is not expired, otherwise
+ * calculates the elapsed time and sets the respective out parameters secs and
+ * usecs. Enables the timer for the next log message and returns TRUE.
+ */
+bool
+startup_progress_timeout_has_expired(long *secs, int *usecs)
+{
+	long		seconds;
+	int			useconds;
+	TimestampTz now;
+
+	/* If the timeout has not occurred, then no need to log the details. */
+	if (!startup_progress_timer_expired)
+		return false;
+
+	/* Calculate the elapsed time. */
+	now = GetCurrentTimestamp();
+	TimestampDifference(startup_progress_phase_start_time, now, &seconds, &useconds);
+
+	*secs = seconds;
+	*usecs = useconds;
+
+	reset_startup_progress_timeout(now);
+	return true;
+}
+
+/*
+ * Calculates the timestamp at which the next timer should expire and enables
+ * the timer accordingly.
+ */
+void
+reset_startup_progress_timeout(TimestampTz now)
+{
+	TimestampTz next_timeout;
+	int         interval_in_ms;
+
+	interval_in_ms = log_startup_progress_interval * 1000;
+	next_timeout = TimestampTzPlusMilliseconds(scheduled_startup_progress_timeout,
+											   interval_in_ms);
+	if (next_timeout < now)
+	{
+		/*
+		 * Either the timeout was processed so late that we missed an
+		 * entire cycle or system clock was set backwards.
+		 */
+		next_timeout = TimestampTzPlusMilliseconds(now, interval_in_ms);
+	}
+
+	enable_timeout_at(STARTUP_PROGRESS_TIMEOUT, next_timeout);
+	scheduled_startup_progress_timeout = next_timeout;
+	startup_progress_timer_expired = false;
+}
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c
index 5d5e8ae..a41342a 100644
--- a/src/backend/storage/file/fd.c
+++ b/src/backend/storage/file/fd.c
@@ -96,6 +96,7 @@
 #include "pgstat.h"
 #include "port/pg_iovec.h"
 #include "portability/mem.h"
+#include "postmaster/startup.h"
 #include "storage/fd.h"
 #include "storage/ipc.h"
 #include "utils/guc.h"
@@ -3334,6 +3335,9 @@ do_syncfs(const char *path)
 {
 	int			fd;
 
+	ereport_startup_progress("syncing data directory (syncfs), elapsed time: %ld.%02d s, current path: %s",
+							 path);
+
 	fd = OpenTransientFile(path, O_RDONLY);
 	if (fd < 0)
 	{
@@ -3418,6 +3422,12 @@ SyncDataDirectory(void)
 		 * directories.
 		 */
 
+		/*
+		 * Begin the startup progress phase to report the progress of syncing
+		 * data directory (syncfs).
+		 */
+		begin_startup_progress_phase();
+
 		/* Sync the top level pgdata directory. */
 		do_syncfs(".");
 		/* If any tablespaces are configured, sync each of those. */
@@ -3440,12 +3450,18 @@ SyncDataDirectory(void)
 	}
 #endif							/* !HAVE_SYNCFS */
 
+#ifdef PG_FLUSH_DATA_WORKS
+	/*
+	 * Begin the startup progress phase to report the progress of syncing
+	 * data directory (pre-fsync).
+	 */
+	begin_startup_progress_phase();
+
 	/*
 	 * If possible, hint to the kernel that we're soon going to fsync the data
 	 * directory and its contents.  Errors in this step are even less
 	 * interesting than normal, so log them only at DEBUG1.
 	 */
-#ifdef PG_FLUSH_DATA_WORKS
 	walkdir(".", pre_sync_fname, false, DEBUG1);
 	if (xlog_is_symlink)
 		walkdir("pg_wal", pre_sync_fname, false, DEBUG1);
@@ -3453,6 +3469,12 @@ SyncDataDirectory(void)
 #endif
 
 	/*
+	 * Begin the startup progress phase to report the progress of syncing
+	 * data directory (fsync).
+	 */
+	begin_startup_progress_phase();
+
+	/*
 	 * Now we do the fsync()s in the same order.
 	 *
 	 * The main call ignores symlinks, so in addition to specially processing
@@ -3554,6 +3576,9 @@ pre_sync_fname(const char *fname, bool isdir, int elevel)
 	if (isdir)
 		return;
 
+	ereport_startup_progress("syncing data directory (pre-fsync), elapsed time: %ld.%02d s, current path: %s",
+							 fname);
+
 	fd = OpenTransientFile(fname, O_RDONLY | PG_BINARY);
 
 	if (fd < 0)
@@ -3583,6 +3608,9 @@ pre_sync_fname(const char *fname, bool isdir, int elevel)
 static void
 datadir_fsync_fname(const char *fname, bool isdir, int elevel)
 {
+	ereport_startup_progress("syncing data directory (fsync), elapsed time: %ld.%02d s, current path: %s",
+							 fname);
+
 	/*
 	 * We want to silently ignoring errors about unreadable files.  Pass that
 	 * desire on to fsync_fname_ext().
diff --git a/src/backend/storage/file/reinit.c b/src/backend/storage/file/reinit.c
index 40c758d..1e4ee99 100644
--- a/src/backend/storage/file/reinit.c
+++ b/src/backend/storage/file/reinit.c
@@ -17,6 +17,7 @@
 #include <unistd.h>
 
 #include "common/relpath.h"
+#include "postmaster/startup.h"
 #include "storage/copydir.h"
 #include "storage/fd.h"
 #include "storage/reinit.h"
@@ -66,6 +67,12 @@ ResetUnloggedRelations(int op)
 	oldctx = MemoryContextSwitchTo(tmpctx);
 
 	/*
+	 * Begin the startup progress phase to report the progress of resetting
+	 * unlogged relations.
+	 */
+	begin_startup_progress_phase();
+
+	/*
 	 * First process unlogged files in pg_default ($PGDATA/base)
 	 */
 	ResetUnloggedRelationsInTablespaceDir("base", op);
@@ -136,6 +143,14 @@ ResetUnloggedRelationsInTablespaceDir(const char *tsdirname, int op)
 
 		snprintf(dbspace_path, sizeof(dbspace_path), "%s/%s",
 				 tsdirname, de->d_name);
+
+		if (op & UNLOGGED_RELATION_INIT)
+			ereport_startup_progress("resetting unlogged relations (init), elapsed time: %ld.%02d s, current path: %s",
+									 dbspace_path);
+		else if (op & UNLOGGED_RELATION_CLEANUP)
+			ereport_startup_progress("resetting unlogged relations (cleanup), elapsed time: %ld.%02d s, current path: %s",
+									 dbspace_path);
+
 		ResetUnloggedRelationsInDbspaceDir(dbspace_path, op);
 	}
 
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 51d1bbe..1676bc1 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -40,6 +40,7 @@
 #include "pgstat.h"
 #include "postmaster/autovacuum.h"
 #include "postmaster/postmaster.h"
+#include "postmaster/startup.h"
 #include "replication/walsender.h"
 #include "storage/bufmgr.h"
 #include "storage/fd.h"
@@ -622,6 +623,7 @@ InitPostgres(const char *in_dbname, Oid dboid, const char *username,
 						IdleInTransactionSessionTimeoutHandler);
 		RegisterTimeout(IDLE_SESSION_TIMEOUT, IdleSessionTimeoutHandler);
 		RegisterTimeout(CLIENT_CONNECTION_CHECK_TIMEOUT, ClientCheckTimeoutHandler);
+		RegisterTimeout(STARTUP_PROGRESS_TIMEOUT, startup_progress_timeout_handler);
 	}
 
 	/*
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index a2e0f8d..c9c877c 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -71,6 +71,7 @@
 #include "postmaster/bgworker_internals.h"
 #include "postmaster/bgwriter.h"
 #include "postmaster/postmaster.h"
+#include "postmaster/startup.h"
 #include "postmaster/syslogger.h"
 #include "postmaster/walwriter.h"
 #include "replication/logicallauncher.h"
@@ -679,7 +680,6 @@ static char *recovery_target_lsn_string;
 /* should be static, but commands/variable.c needs to get at this */
 char	   *role_string;
 
-
 /*
  * Displayable names for context types (enum GucContext)
  *
@@ -3546,6 +3546,18 @@ static struct config_int ConfigureNamesInt[] =
 		check_client_connection_check_interval, NULL, NULL
 	},
 
+	{
+		{"log_startup_progress_interval", PGC_SIGHUP, LOGGING_WHEN,
+			gettext_noop("Sets the time interval between each progress update "
+						 "of the startup process."),
+			gettext_noop("0 logs all messages. -1 turns this feature off."),
+			GUC_UNIT_MS,
+		},
+		&log_startup_progress_interval,
+		10, -1, INT_MAX,
+		NULL, NULL, NULL
+	},
+
 	/* End-of-list marker */
 	{
 		{NULL, 0, 0, NULL, NULL}, NULL, 0, 0, 0, NULL, NULL, NULL
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index b242a7f..4cc1993 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -523,6 +523,12 @@
 					# are logged regardless of their duration; 1.0 logs all
 					# statements from all transactions, 0.0 never logs
 
+#log_startup_progress_interval = 10	# Sets the time interval between each
+									# progress update of the startup process.
+									# -1 disables the feature, 0 logs all
+									# messages, > 0 indicates the interval in
+									# seconds.
+
 # - What to Log -
 
 #debug_print_parse = off
diff --git a/src/include/postmaster/startup.h b/src/include/postmaster/startup.h
index bf6adf1..e3f6300 100644
--- a/src/include/postmaster/startup.h
+++ b/src/include/postmaster/startup.h
@@ -12,6 +12,21 @@
 #ifndef _STARTUP_H
 #define _STARTUP_H
 
+#include "datatype/timestamp.h"
+
+/*
+ * Logs the startup progress message if the timer has expired.
+ */
+#define ereport_startup_progress(msg, ...) \
+	do { \
+		long    secs; \
+		int     usecs; \
+		if (startup_progress_timeout_has_expired(&secs, &usecs)) \
+			ereport(LOG, errmsg(msg, secs, (usecs / 10000),  __VA_ARGS__ )); \
+	} while(0)
+
+extern int  log_startup_progress_interval;
+
 extern void HandleStartupProcInterrupts(void);
 extern void StartupProcessMain(void) pg_attribute_noreturn();
 extern void PreRestoreCommand(void);
@@ -19,4 +34,10 @@ extern void PostRestoreCommand(void);
 extern bool IsPromoteSignaled(void);
 extern void ResetPromoteSignaled(void);
 
+extern void begin_startup_progress_phase(void);
+extern void startup_progress_timeout_handler(void);
+extern bool startup_progress_timeout_has_expired(long *secs, int *usecs);
+extern void reset_startup_progress_timeout(TimestampTz now);
+
+
 #endif							/* _STARTUP_H */
diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h
index 93e6a69..29ea7f6 100644
--- a/src/include/utils/timeout.h
+++ b/src/include/utils/timeout.h
@@ -33,6 +33,7 @@ typedef enum TimeoutId
 	IDLE_IN_TRANSACTION_SESSION_TIMEOUT,
 	IDLE_SESSION_TIMEOUT,
 	CLIENT_CONNECTION_CHECK_TIMEOUT,
+	STARTUP_PROGRESS_TIMEOUT,
 	/* First user-definable timeout reason */
 	USER_TIMEOUT,
 	/* Maximum number of timeout reasons */
-- 
1.8.3.1