v2_startup_process_progress.patch

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 441a912..43c4d0a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -80,6 +80,7 @@
 #include "utils/pg_rusage.h"
 #include "utils/snapmgr.h"
 #include "utils/timestamp.h"
+#include "utils/timeout.h"
 
 extern uint32 bootstrap_data_checksum_version;
 
@@ -397,6 +398,18 @@ static bool doRequestWalReceiverReply;
  */
 static XLogRecPtr RedoStartLSN = InvalidXLogRecPtr;
 
+/*
+ * It stores the start timestamp of the operation that occur during process
+ * startup.
+ */
+static TimestampTz operationStartTimestamp;
+
+/*
+ * It indicates whether the startup progress interval mentioned by the user is
+ * elapsed or not. TRUE if timeout occured. FALSE otherwise.
+ */
+static bool logStartupProgressTimeout;
+
 /*----------
  * Shared-memory data structures for XLOG control
  *
@@ -7323,6 +7336,7 @@ StartupXLOG(void)
 					(errmsg("redo starts at %X/%X",
 							LSN_FORMAT_ARGS(ReadRecPtr))));
 
+			InitCurrentOperation();
 			/*
 			 * main redo apply loop
 			 */
@@ -7330,6 +7344,8 @@ StartupXLOG(void)
 			{
 				bool		switchedTLI = false;
 
+				LogStartupProgress(RECOVERY_START, (void *) EndRecPtr);
+
 #ifdef WAL_DEBUG
 				if (XLOG_DEBUG ||
 					(rmid == RM_XACT_ID && trace_recovery_messages <= DEBUG2) ||
@@ -7540,6 +7556,7 @@ StartupXLOG(void)
 			/*
 			 * end of main redo apply loop
 			 */
+			LogStartupProgress(RECOVERY_END, NULL);
 
 			if (reachedRecoveryTarget)
 			{
@@ -12929,3 +12946,142 @@ XLogRequestWalReceiverReply(void)
 {
 	doRequestWalReceiverReply = true;
 }
+
+/*
+ * This function gets called when the signal SIGALRM is raised for the interval
+ * set for logging the progress of startup.
+ */
+void
+LogStartupProgressTimeoutHandler(void)
+{
+	logStartupProgressTimeout = true;
+}
+
+/*
+ * Sets the start timestamp of the current operation and also enables the
+ * timeout for logging the progress of startup.
+ */
+void
+InitCurrentOperation(void)
+{
+	operationStartTimestamp = GetCurrentTimestamp();
+	enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT, log_startup_progress_interval);
+}
+
+/*
+ * Fetches the start timestamp of the current operation.
+ */
+TimestampTz
+GetCurrentOperationStartTimestamp(void)
+{
+	return operationStartTimestamp;
+}
+
+/*
+ * This function returns a string which indicates the description of the
+ * operation performed during process startup.
+ */
+static char *
+get_startup_process_operation_string(StartupProcessOp operation)
+{
+	char *buf = NULL;
+
+	switch (operation)
+	{
+		case SYNCFS_START:
+			buf = "Syncing data directory (syncfs)";
+			break;
+		case FSYNC_START:
+			buf = "Syncing data directory (fsync)";
+			break;
+		case RECOVERY_START:
+			buf = "Performing crash recovery";
+			break;
+		case RESET_UNLOGGED_REL_START:
+			buf = "Resetting unlogged relations";
+			break;
+		case SYNCFS_END:
+			buf = "Data directory sync (syncfs) complete";
+			break;
+		case FSYNC_END:
+			buf = "Data directory sync (fsync) complete";
+			break;
+		case RECOVERY_END:
+			break;
+		case RESET_UNLOGGED_REL_END:
+			buf = "Unlogged relations reset";
+			break;
+	}
+	return buf;
+}
+
+/*
+ * Logs the progress of the operations performed during process startup.
+ */
+void
+LogStartupProgress(StartupProcessOp operation, void *data)
+{
+	long        secs;
+	int         usecs;
+	int         msecs;
+
+	/* If the feature is disabled, then no need to proceed further. */
+	if (log_startup_progress_interval < 0)
+		return;
+
+	/*
+	 * This block gets executed when the current opearion is completed. It logs
+	 * the details of the operation and also disables the timeout. Note that in
+	 * case of recovery, it does not log the details since enough information is
+	 * already logged.
+	 */
+	if (operation >= SYNCFS_END)
+	{
+		if (operation != RECOVERY_END)
+		{
+			TimestampDifference(GetCurrentOperationStartTimestamp(),
+								GetCurrentTimestamp(),
+								&secs, &usecs);
+			msecs = usecs / 1000;
+
+			ereport(LOG,(errmsg("%s after %ld.%03d ms",
+								get_startup_process_operation_string(operation),
+								secs * 1000 + msecs, usecs % 1000),
+						 errhidestmt(true)));
+		}
+
+		disable_timeout(LOG_STARTUP_PROGRESS_TIMEOUT, false);
+		return;
+	}
+
+	/* If the timeout has not occured, then no need to log the details. */
+	if (!logStartupProgressTimeout)
+		return;
+
+	/* Timeout has occured. Log the necessary details. */
+	TimestampDifference(GetCurrentOperationStartTimestamp(),
+						GetCurrentTimestamp(),
+						&secs, &usecs);
+	msecs = usecs / 1000;
+
+	if (operation == RECOVERY_START)
+		ereport(LOG,(errmsg("%s, elapsed time: %ld.%03d ms,  current LSN: %X/%X",
+							get_startup_process_operation_string(operation),
+							secs * 1000 + msecs, usecs % 1000,
+							LSN_FORMAT_ARGS((XLogRecPtr) data)),
+					 errhidestmt(true)));
+	else
+		ereport(LOG,(errmsg("%s, elapsed time: %ld.%03d ms,  current path: %s",
+							get_startup_process_operation_string(operation),
+							secs * 1000 + msecs, usecs % 1000, (char *) data),
+					 errhidestmt(true)));
+
+	/*
+	 * Set the flag to false and enable the timeout to log the progress if any in
+	 * the future.
+	 */
+	logStartupProgressTimeout = false;
+	enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT, log_startup_progress_interval);
+
+	return;
+}
diff --git a/src/backend/postmaster/startup.c b/src/backend/postmaster/startup.c
index 69077bd..08c271c 100644
--- a/src/backend/postmaster/startup.c
+++ b/src/backend/postmaster/startup.c
@@ -232,6 +232,7 @@ StartupProcessMain(void)
 	RegisterTimeout(STANDBY_DEADLOCK_TIMEOUT, StandbyDeadLockHandler);
 	RegisterTimeout(STANDBY_TIMEOUT, StandbyTimeoutHandler);
 	RegisterTimeout(STANDBY_LOCK_TIMEOUT, StandbyLockTimeoutHandler);
+	RegisterTimeout(LOG_STARTUP_PROGRESS_TIMEOUT, LogStartupProgressTimeoutHandler);
 
 	/*
 	 * Unblock signals (they were blocked when the postmaster forked us)
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c
index e8cd7ef..9df893d 100644
--- a/src/backend/storage/file/fd.c
+++ b/src/backend/storage/file/fd.c
@@ -100,6 +100,7 @@
 #include "storage/ipc.h"
 #include "utils/guc.h"
 #include "utils/resowner_private.h"
+#include "utils/timeout.h"
 
 /* Define PG_FLUSH_DATA_WORKS if we have an implementation for pg_flush_data */
 #if defined(HAVE_SYNC_FILE_RANGE)
@@ -3366,6 +3367,7 @@ SyncDataDirectory(void)
 		DIR		   *dir;
 		struct dirent *de;
 
+		InitCurrentOperation();
 		/*
 		 * On Linux, we don't have to open every single file one by one.  We
 		 * can use syncfs() to sync whole filesystems.  We only expect
@@ -3386,16 +3388,20 @@ SyncDataDirectory(void)
 				continue;
 
 			snprintf(path, MAXPGPATH, "pg_tblspc/%s", de->d_name);
+			LogStartupProgress(SYNCFS_START, path);
 			do_syncfs(path);
 		}
 		FreeDir(dir);
 		/* If pg_wal is a symlink, process that too. */
 		if (xlog_is_symlink)
 			do_syncfs("pg_wal");
+
+		LogStartupProgress(SYNCFS_END, NULL);
 		return;
 	}
 #endif							/* !HAVE_SYNCFS */
 
+	InitCurrentOperation();
 	/*
 	 * 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
@@ -3421,6 +3427,7 @@ SyncDataDirectory(void)
 	if (xlog_is_symlink)
 		walkdir("pg_wal", datadir_fsync_fname, false, LOG);
 	walkdir("pg_tblspc", datadir_fsync_fname, true, LOG);
+	LogStartupProgress(FSYNC_END, NULL);
 }
 
 /*
@@ -3454,6 +3461,7 @@ walkdir(const char *path,
 		char		subpath[MAXPGPATH * 2];
 
 		CHECK_FOR_INTERRUPTS();
+		LogStartupProgress(FSYNC_START, path);
 
 		if (strcmp(de->d_name, ".") == 0 ||
 			strcmp(de->d_name, "..") == 0)
diff --git a/src/backend/storage/file/reinit.c b/src/backend/storage/file/reinit.c
index 40c758d..1de34b5 100644
--- a/src/backend/storage/file/reinit.c
+++ b/src/backend/storage/file/reinit.c
@@ -22,6 +22,8 @@
 #include "storage/reinit.h"
 #include "utils/hsearch.h"
 #include "utils/memutils.h"
+#include "access/xlog.h"
+#include "utils/timeout.h"
 
 static void ResetUnloggedRelationsInTablespaceDir(const char *tsdirname,
 												  int op);
@@ -75,6 +77,7 @@ ResetUnloggedRelations(int op)
 	 */
 	spc_dir = AllocateDir("pg_tblspc");
 
+	InitCurrentOperation();
 	while ((spc_de = ReadDir(spc_dir, "pg_tblspc")) != NULL)
 	{
 		if (strcmp(spc_de->d_name, ".") == 0 ||
@@ -83,9 +86,11 @@ ResetUnloggedRelations(int op)
 
 		snprintf(temp_path, sizeof(temp_path), "pg_tblspc/%s/%s",
 				 spc_de->d_name, TABLESPACE_VERSION_DIRECTORY);
+		LogStartupProgress(RESET_UNLOGGED_REL_START, temp_path);
 		ResetUnloggedRelationsInTablespaceDir(temp_path, op);
 	}
 
+	LogStartupProgress(RESET_UNLOGGED_REL_END, NULL);
 	FreeDir(spc_dir);
 
 	/*
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 87bc688..4039713 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -663,6 +663,9 @@ static char *recovery_target_lsn_string;
 /* should be static, but commands/variable.c needs to get at this */
 char	   *role_string;
 
+/* Used to log the progress of process startup */
+int			log_startup_progress_interval = -1;
+
 
 /*
  * Displayable names for context types (enum GucContext)
@@ -3539,6 +3542,18 @@ static struct config_int ConfigureNamesInt[] =
 		check_client_connection_check_interval, NULL, NULL
 	},
 
+	{
+		{"log_startup_progress_interval", PGC_SUSET, LOGGING_WHEN,
+			gettext_noop("Sets the time interval between each progress update "
+						 "of the process startup."),
+			gettext_noop("Zero logs all messages. -1 turns this feature off."),
+			GUC_UNIT_MS
+		},
+		&log_startup_progress_interval,
+		-1, -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 ddbb6dc..6c2da80 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -521,6 +521,12 @@
 					# are logged regardless of their duration; 1.0 logs all
 					# statements from all transactions, 0.0 never logs
 
+#log_startup_progress_interval = -1	# Sets the time interval between each
+									# progress update of the process startup.
+									# -1 disables the feature, zero logs all
+									# messages, > 0 indicates the interval in
+									# milliseconds.
+
 # - What to Log -
 
 #debug_print_parse = off
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 77187c1..bb37a4d 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -287,6 +287,21 @@ typedef enum WALAvailability
 	WALAVAIL_REMOVED			/* WAL segment has been removed */
 } WALAvailability;
 
+/*
+ * Codes of the operations performed during process startup
+ */
+typedef enum StartupProcessOp
+{
+	SYNCFS_START,
+	FSYNC_START,
+	RECOVERY_START,
+	RESET_UNLOGGED_REL_START,
+	SYNCFS_END,
+	FSYNC_END,
+	RECOVERY_END,
+	RESET_UNLOGGED_REL_END,
+} StartupProcessOp;
+
 struct XLogRecData;
 
 extern XLogRecPtr XLogInsertRecord(struct XLogRecData *rdata,
@@ -391,6 +406,11 @@ extern void do_pg_abort_backup(int code, Datum arg);
 extern void register_persistent_abort_backup_handler(void);
 extern SessionBackupState get_backup_status(void);
 
+extern TimestampTz GetCurrentOperationStartTimestamp(void);
+extern void InitCurrentOperation(void);
+extern void LogStartupProgress(StartupProcessOp operation, void *data);
+extern void LogStartupProgressTimeoutHandler(void);
+
 /* File path names (all relative to $PGDATA) */
 #define RECOVERY_SIGNAL_FILE	"recovery.signal"
 #define STANDBY_SIGNAL_FILE		"standby.signal"
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index a7c3a49..7c12632 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -282,6 +282,8 @@ extern int	tcp_user_timeout;
 extern bool trace_sort;
 #endif
 
+extern int  log_startup_progress_interval;
+
 /*
  * Functions exported by guc.c
  */
diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h
index 93e6a69..ef892dd 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,
+	LOG_STARTUP_PROGRESS_TIMEOUT,
 	/* First user-definable timeout reason */
 	USER_TIMEOUT,
 	/* Maximum number of timeout reasons */