From 026556e2e4b1077a8238e3c92a47c40cd75b5623 Mon Sep 17 00:00:00 2001 From: Nitin Date: Fri, 3 Sep 2021 12:20:04 +0530 Subject: [PATCH] startup process progress 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 | 13 ++++ src/backend/utils/misc/postgresql.conf.sample | 6 ++ src/include/postmaster/startup.h | 17 +++++ src/include/utils/timeout.h | 1 + 10 files changed, 214 insertions(+), 1 deletion(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 2c31c35..00e50dc 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -6549,6 +6549,28 @@ local0.* /var/log/postgresql + + log_startup_progress_interval (integer) + + log_startup_progress_interval configuration parameter + + + + + 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 + 10s , then after every 10s 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 0 , + then it logs all the available messages for such operations. -1 + disables the feature. The default value is set to 10s + + + + + diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 24165ab..c991e05 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -7548,12 +7548,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..68758bd 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; } + +/* + * Calculates the timestamp at which the next timer should expire and enables + * the timer accordingly. + */ +static 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; +} + +/* + * 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; +} diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c index f9cda69..2bc6ce9 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" @@ -3381,6 +3382,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) { @@ -3465,6 +3469,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. */ @@ -3487,12 +3497,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); @@ -3500,6 +3516,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 @@ -3601,6 +3623,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) @@ -3630,6 +3655,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 #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 78bc646..984a5a0 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" @@ -615,6 +616,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 467b0fd..a53fbdf 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" @@ -3546,6 +3547,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 3fe9a53..a2192a9 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..5dfad76 100644 --- a/src/include/postmaster/startup.h +++ b/src/include/postmaster/startup.h @@ -12,6 +12,19 @@ #ifndef _STARTUP_H #define _STARTUP_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 +32,8 @@ 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); + #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