From ee604cafe279be7ef3df04ebab475fc6f23de76d Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Tue, 2 Aug 2022 07:13:08 +0000 Subject: [PATCH v1] Generalize ereport_startup_progress infrastructure The ereport_startup_progress infrastructure added by commit 9ce346e will be super-useful for reporting progress of any long-running server operations, not just the startup process operations. For instance, postmaster can use it for reporting progress of temp file and temp relation file removals, checkpointer can use it for reporting progress of snapshot or mapping file processing or even WAL file processing and so on. And I'm sure there can be many places in the code where we have while or for loops which can, at times, take a long time to finish and having a log message there would definitely help. This patch attempts to generalize the ereport_startup_progress infrastructure. --- doc/src/sgml/config.sgml | 19 +++-- src/backend/access/transam/xlog.c | 4 +- src/backend/access/transam/xlogrecovery.c | 6 +- src/backend/postmaster/startup.c | 73 ------------------ src/backend/storage/file/fd.c | 18 ++--- src/backend/storage/file/reinit.c | 10 +-- src/backend/utils/error/elog.c | 74 +++++++++++++++++++ src/backend/utils/misc/guc.c | 6 +- src/backend/utils/misc/postgresql.conf.sample | 4 +- src/include/postmaster/startup.h | 17 ----- src/include/utils/elog.h | 21 ++++++ src/include/utils/timeout.h | 2 +- 12 files changed, 129 insertions(+), 125 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e2d728e0c4..8c3701e6b7 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -6724,21 +6724,20 @@ local0.* /var/log/postgresql - - log_startup_progress_interval (integer) + + log_progress_report_interval (integer) - log_startup_progress_interval configuration parameter + log_progress_report_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. The default is 10 seconds. A setting of 0 - disables the feature. If this value is specified without units, - it is taken as milliseconds. This setting is applied separately to - each operation. + Sets the amount of time after which the server 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. + The default is 10 seconds. A setting of 0 disables + the feature. If this value is specified without units, it is taken as + milliseconds. This setting is applied separately to each operation. This parameter can only be set in the postgresql.conf file or on the server command line. diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 15ab8d90d4..f97716256d 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -4981,8 +4981,8 @@ StartupXLOG(void) /* Set up timeout handler needed to report startup progress. */ if (!IsBootstrapProcessingMode()) - RegisterTimeout(STARTUP_PROGRESS_TIMEOUT, - startup_progress_timeout_handler); + RegisterTimeout(PROGRESS_REPORT_TIMEOUT, + progress_report_timeout_handler); /*---------- * If we previously crashed, perform a couple of actions: diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index 27e02fbfcd..17490209bd 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1643,7 +1643,7 @@ PerformWalRecovery(void) /* Prepare to report progress of the redo phase. */ if (!StandbyMode) - begin_startup_progress_phase(); + begin_progress_report_phase(); /* * main redo apply loop @@ -1651,8 +1651,8 @@ PerformWalRecovery(void) do { if (!StandbyMode) - ereport_startup_progress("redo in progress, elapsed time: %ld.%02d s, current LSN: %X/%X", - LSN_FORMAT_ARGS(xlogreader->ReadRecPtr)); + ereport_progress("redo in progress, elapsed time: %ld.%02d s, current LSN: %X/%X", + LSN_FORMAT_ARGS(xlogreader->ReadRecPtr)); #ifdef WAL_DEBUG if (XLOG_DEBUG || diff --git a/src/backend/postmaster/startup.c b/src/backend/postmaster/startup.c index f99186eab7..f52c15d019 100644 --- a/src/backend/postmaster/startup.c +++ b/src/backend/postmaster/startup.c @@ -61,22 +61,6 @@ static volatile sig_atomic_t promote_signaled = false; */ static volatile sig_atomic_t in_restore_command = false; -/* - * Time at which the most recent startup operation started. - */ -static TimestampTz startup_progress_phase_start_time; - -/* - * 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; - -/* - * Time between progress updates for long-running startup operations. - */ -int log_startup_progress_interval = 10000; /* 10 sec */ - /* Signal handlers */ static void StartupProcTriggerHandler(SIGNAL_ARGS); static void StartupProcSigHupHandler(SIGNAL_ARGS); @@ -304,60 +288,3 @@ ResetPromoteSignaled(void) { promote_signaled = false; } - -/* - * Set a flag indicating that it's time to log a progress report. - */ -void -startup_progress_timeout_handler(void) -{ - startup_progress_timer_expired = true; -} - -/* - * Set the start timestamp of the current operation and enable the timeout. - */ -void -begin_startup_progress_phase(void) -{ - TimestampTz fin_time; - - /* Feature is disabled. */ - if (log_startup_progress_interval == 0) - return; - - disable_timeout(STARTUP_PROGRESS_TIMEOUT, false); - startup_progress_timer_expired = false; - startup_progress_phase_start_time = GetCurrentTimestamp(); - fin_time = TimestampTzPlusMilliseconds(startup_progress_phase_start_time, - log_startup_progress_interval); - enable_timeout_every(STARTUP_PROGRESS_TIMEOUT, fin_time, - log_startup_progress_interval); -} - -/* - * Report whether startup progress timeout has occurred. Reset the timer flag - * if it did, set the elapsed time to the out parameters and return true, - * otherwise 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; - startup_progress_timer_expired = false; - - return true; -} diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c index f904f60c08..2b8977a356 100644 --- a/src/backend/storage/file/fd.c +++ b/src/backend/storage/file/fd.c @@ -3321,8 +3321,8 @@ do_syncfs(const char *path) { int fd; - ereport_startup_progress("syncing data directory (syncfs), elapsed time: %ld.%02d s, current path: %s", - path); + ereport_progress("syncing data directory (syncfs), elapsed time: %ld.%02d s, current path: %s", + path); fd = OpenTransientFile(path, O_RDONLY); if (fd < 0) @@ -3409,7 +3409,7 @@ SyncDataDirectory(void) */ /* Prepare to report progress syncing the data directory via syncfs. */ - begin_startup_progress_phase(); + begin_progress_report_phase(); /* Sync the top level pgdata directory. */ do_syncfs("."); @@ -3435,7 +3435,7 @@ SyncDataDirectory(void) #ifdef PG_FLUSH_DATA_WORKS /* Prepare to report progress of the pre-fsync phase. */ - begin_startup_progress_phase(); + begin_progress_report_phase(); /* * If possible, hint to the kernel that we're soon going to fsync the data @@ -3449,7 +3449,7 @@ SyncDataDirectory(void) #endif /* Prepare to report progress syncing the data directory via fsync. */ - begin_startup_progress_phase(); + begin_progress_report_phase(); /* * Now we do the fsync()s in the same order. @@ -3553,8 +3553,8 @@ 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); + ereport_progress("syncing data directory (pre-fsync), elapsed time: %ld.%02d s, current path: %s", + fname); fd = OpenTransientFile(fname, O_RDONLY | PG_BINARY); @@ -3585,8 +3585,8 @@ 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); + ereport_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 diff --git a/src/backend/storage/file/reinit.c b/src/backend/storage/file/reinit.c index 647c458b52..7d48a3de12 100644 --- a/src/backend/storage/file/reinit.c +++ b/src/backend/storage/file/reinit.c @@ -67,7 +67,7 @@ ResetUnloggedRelations(int op) oldctx = MemoryContextSwitchTo(tmpctx); /* Prepare to report progress resetting unlogged relations. */ - begin_startup_progress_phase(); + begin_progress_report_phase(); /* * First process unlogged files in pg_default ($PGDATA/base) @@ -142,11 +142,11 @@ ResetUnloggedRelationsInTablespaceDir(const char *tsdirname, int op) 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); + ereport_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); + ereport_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/error/elog.c b/src/backend/utils/error/elog.c index 95f32de4e2..6ef4812157 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -82,6 +82,7 @@ #include "utils/guc.h" #include "utils/memutils.h" #include "utils/ps_status.h" +#include "utils/timeout.h" /* In this module, access gettext() via err_gettext() */ @@ -170,6 +171,21 @@ static char formatted_log_time[FORMATTED_TS_LEN]; } \ } while (0) +/* + * Time at which the most recent server operation started. + */ +static TimestampTz progress_report_phase_start_time; + +/* + * Indicates whether the progress interval mentioned by the user is elapsed or + * not. TRUE if timeout occurred, FALSE otherwise. + */ +static volatile sig_atomic_t progress_report_timer_expired = false; + +/* + * Time between progress updates for long-running server operations. + */ +int log_progress_report_interval = 10000; /* 10 sec */ static const char *err_gettext(const char *str) pg_attribute_format_arg(1); static pg_noinline void set_backtrace(ErrorData *edata, int num_skip); @@ -3436,3 +3452,61 @@ trace_recovery(int trace_level) return trace_level; } + +/* + * Set a flag indicating that it's time to log a progress report. + */ +void +progress_report_timeout_handler(void) +{ + progress_report_timer_expired = true; +} + +/* + * Set the start timestamp of the current operation and enable the timeout. + */ +void +begin_progress_report_phase(void) +{ + TimestampTz fin_time; + + /* Feature is disabled. */ + if (log_progress_report_interval == 0) + return; + + disable_timeout(PROGRESS_REPORT_TIMEOUT, false); + progress_report_timer_expired = false; + progress_report_phase_start_time = GetCurrentTimestamp(); + fin_time = TimestampTzPlusMilliseconds(progress_report_phase_start_time, + log_progress_report_interval); + enable_timeout_every(PROGRESS_REPORT_TIMEOUT, fin_time, + log_progress_report_interval); +} + +/* + * Report whether progress report timeout has occurred. Reset the timer flag if + * it did, set the elapsed time to the out parameters and return true, + * otherwise return false. + */ +bool +has_progress_report_timeout_expired(long *secs, int *usecs) +{ + long seconds; + int useconds; + TimestampTz now; + + /* No timeout has occurred. */ + if (!progress_report_timer_expired) + return false; + + /* Calculate the elapsed time. */ + now = GetCurrentTimestamp(); + TimestampDifference(progress_report_phase_start_time, + now, &seconds, &useconds); + + *secs = seconds; + *usecs = useconds; + progress_report_timer_expired = false; + + return true; +} diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index af4a1c3068..f543f0d98b 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -3651,13 +3651,13 @@ static struct config_int ConfigureNamesInt[] = }, { - {"log_startup_progress_interval", PGC_SIGHUP, LOGGING_WHEN, + {"log_progress_report_interval", PGC_SIGHUP, LOGGING_WHEN, gettext_noop("Time between progress updates for " - "long-running startup operations."), + "long-running server operations."), gettext_noop("0 turns this feature off."), GUC_UNIT_MS, }, - &log_startup_progress_interval, + &log_progress_report_interval, 10000, 0, INT_MAX, NULL, NULL, NULL }, diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index b4bc06e5f5..a3346e15e1 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -535,8 +535,8 @@ # are logged regardless of their duration; 1.0 logs all # statements from all transactions, 0.0 never logs -#log_startup_progress_interval = 10s # Time between progress updates for - # long-running startup operations. +#log_progress_report_interval = 10s # Time between progress updates for + # long-running server operations. # 0 disables the feature, > 0 indicates # the interval in milliseconds. diff --git a/src/include/postmaster/startup.h b/src/include/postmaster/startup.h index d66ec1fcb1..068d0c82c6 100644 --- a/src/include/postmaster/startup.h +++ b/src/include/postmaster/startup.h @@ -12,19 +12,6 @@ #ifndef _STARTUP_H #define _STARTUP_H -/* - * Log the startup progress message if a 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 PGDLLIMPORT int log_startup_progress_interval; - extern void HandleStartupProcInterrupts(void); extern void StartupProcessMain(void) pg_attribute_noreturn(); extern void PreRestoreCommand(void); @@ -32,8 +19,4 @@ 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/elog.h b/src/include/utils/elog.h index 68ead8e873..66951b0f74 100644 --- a/src/include/utils/elog.h +++ b/src/include/utils/elog.h @@ -471,4 +471,25 @@ extern void set_syslog_parameters(const char *ident, int facility); */ extern void write_stderr(const char *fmt,...) pg_attribute_printf(1, 2); +/* + * Log the progress report message if a timer has expired. + * + * For a process to use this function, it must initialize timeouts, register + * for the timeout PROGRESS_REPORT_TIMEOUT and call begin_progress_report_phase + * function. + */ +#define ereport_progress(msg, ...) \ + do { \ + long secs; \ + int usecs; \ + if (has_progress_report_timeout_expired(&secs, &usecs)) \ + ereport(LOG, errmsg(msg, secs, (usecs / 10000), __VA_ARGS__ )); \ + } while(0) + +extern PGDLLIMPORT int log_progress_report_interval; + +extern void begin_progress_report_phase(void); +extern void progress_report_timeout_handler(void); +extern bool has_progress_report_timeout_expired(long *secs, int *usecs); + #endif /* ELOG_H */ diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h index c068986d09..df107fdc3f 100644 --- a/src/include/utils/timeout.h +++ b/src/include/utils/timeout.h @@ -34,7 +34,7 @@ typedef enum TimeoutId IDLE_SESSION_TIMEOUT, IDLE_STATS_UPDATE_TIMEOUT, CLIENT_CONNECTION_CHECK_TIMEOUT, - STARTUP_PROGRESS_TIMEOUT, + PROGRESS_REPORT_TIMEOUT, /* First user-definable timeout reason */ USER_TIMEOUT, /* Maximum number of timeout reasons */ -- 2.34.1