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 */