From b15abdd1bcc86bb8c27062147ea5e24a06d0993c Mon Sep 17 00:00:00 2001 From: Nitin Date: Wed, 29 Sep 2021 19:22:56 +0530 Subject: [PATCH] startup process progress Shows the progress of the operations performed by the startup process. The interval between each progress update is configurable and the unit used to mention the value is in milliseconds. --- doc/src/sgml/config.sgml | 24 +++++++ src/backend/access/transam/xlog.c | 11 +++ src/backend/nls.mk | 6 +- 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 | 3 + src/backend/utils/misc/guc.c | 13 ++++ src/backend/utils/misc/postgresql.conf.sample | 5 ++ src/include/postmaster/startup.h | 17 +++++ src/include/utils/timeout.h | 1 + 11 files changed, 222 insertions(+), 3 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 0a8e35c..28c24d4 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -6549,6 +6549,30 @@ local0.* /var/log/postgresql + + log_startup_progress_interval (integer) + + log_startup_progress_interval configuration parameter + + + + + Sets the amount of time after which the startup process will log + a message about a long-running operation that is still in progress, + as well as the interval between further progress messages for that + operation. This setting is applied separately to each operation. + For example, if syncing the data directory takes 25 seconds and + thereafter resetting unlogged relations takes 8 seconds, and if this + setting has the default value of 10 seconds, then a messages will be + logged for syncing the data directory after it has been in progress + for 10 seconds and again after it has been in progress for 20 seconds, + but nothing will be logged for resetting unlogged operations. + A setting of 0 disables the feature. If this value + is specified without units, it is taken as milliseconds. + + + + diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index e51a7a7..782f5c0 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -7364,12 +7364,23 @@ StartupXLOG(void) LSN_FORMAT_ARGS(ReadRecPtr)))); /* + * Begin the startup progress phase to report the progress of redo + * operation. + */ + if (!StandbyMode) + begin_startup_progress_phase(); + + /* * main redo apply loop */ do { bool switchedTLI = false; + if (!StandbyMode) + 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/nls.mk b/src/backend/nls.mk index 771b58d..3552998 100644 --- a/src/backend/nls.mk +++ b/src/backend/nls.mk @@ -10,13 +10,15 @@ GETTEXT_TRIGGERS = $(BACKEND_COMMON_GETTEXT_TRIGGERS) \ yyerror \ parser_yyerror \ scanner_yyerror \ - report_invalid_record:2 + report_invalid_record:2 \ + ereport_startup_progress GETTEXT_FLAGS = $(BACKEND_COMMON_GETTEXT_FLAGS) \ GUC_check_errmsg:1:c-format \ GUC_check_errdetail:1:c-format \ GUC_check_errhint:1:c-format \ write_stderr:1:c-format \ - report_invalid_record:2:c-format + report_invalid_record:2:c-format \ + ereport_startup_progress:1:c-format gettext-files: distprep find $(srcdir) $(srcdir)/../common $(srcdir)/../port -name '*.c' -print | LC_ALL=C sort >$@ diff --git a/src/backend/postmaster/startup.c b/src/backend/postmaster/startup.c index 0f4f00d..68b5d5d 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 = 10000; /* 10 sec */ + + /* 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; + + next_timeout = TimestampTzPlusMilliseconds(scheduled_startup_progress_timeout, + log_startup_progress_interval); + 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, log_startup_progress_interval); + } + + 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) +{ + /* Feature is disabled. */ + if (log_startup_progress_interval == 0) + return; + + scheduled_startup_progress_timeout = 0; + startup_progress_phase_start_time = GetCurrentTimestamp(); + reset_startup_progress_timeout(startup_progress_phase_start_time); +} + +/* + * Report whether startup progress timeout has occurred. Return true and reset + * the timer if it did, otheriwse return false. + */ +bool +has_startup_progress_timeout_expired(long *secs, int *usecs) +{ + long seconds; + int useconds; + TimestampTz now; + + /* No timeout has occurred. */ + 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..7a8854d 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,8 @@ InitPostgres(const char *in_dbname, Oid dboid, const char *username, IdleInTransactionSessionTimeoutHandler); RegisterTimeout(IDLE_SESSION_TIMEOUT, IdleSessionTimeoutHandler); RegisterTimeout(CLIENT_CONNECTION_CHECK_TIMEOUT, ClientCheckTimeoutHandler); + if (!IsPostmasterEnvironment) + 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 d2ce4a8..4889e5b 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" @@ -3570,6 +3571,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 turns this feature off."), + GUC_UNIT_MS, + }, + &log_startup_progress_interval, + 10000, 0, 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..350236e 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -523,6 +523,11 @@ # are logged regardless of their duration; 1.0 logs all # statements from all transactions, 0.0 never logs +#log_startup_progress_interval = 10s # Sets the time interval between each + # progress update of the startup process. + # 0 disables the feature, > 0 indicates + # the interval in milliseconds. + # - What to Log - #debug_print_parse = off diff --git a/src/include/postmaster/startup.h b/src/include/postmaster/startup.h index bf6adf1..c57acf2 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 (has_startup_progress_timeout_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 has_startup_progress_timeout_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