From b97e490a5f30c504f62d4c77dbb7a34d4bb6cc2e Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Tue, 9 Aug 2022 14:33:24 +0000 Subject: [PATCH v3] 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. --- src/backend/access/transam/xlog.c | 4 +- src/backend/access/transam/xlogrecovery.c | 6 +- src/backend/postmaster/startup.c | 68 ---------------------- src/backend/storage/file/fd.c | 18 +++--- src/backend/storage/file/reinit.c | 10 ++-- src/backend/utils/error/elog.c | 69 +++++++++++++++++++++++ src/include/postmaster/startup.h | 15 ----- src/include/utils/elog.h | 19 +++++++ src/include/utils/timeout.h | 2 +- 9 files changed, 108 insertions(+), 103 deletions(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 34f0150d1e..6e0299543f 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -4979,8 +4979,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 21088e78f6..7accd7b8cd 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(log_startup_progress_interval); /* * 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..5cb5c53e48 100644 --- a/src/backend/postmaster/startup.c +++ b/src/backend/postmaster/startup.c @@ -61,17 +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. */ @@ -304,60 +293,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 efb34d4dcb..a227f38775 100644 --- a/src/backend/storage/file/fd.c +++ b/src/backend/storage/file/fd.c @@ -3309,8 +3309,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) @@ -3392,7 +3392,7 @@ SyncDataDirectory(void) */ /* Prepare to report progress syncing the data directory via syncfs. */ - begin_startup_progress_phase(); + begin_progress_report_phase(log_startup_progress_interval); /* Sync the top level pgdata directory. */ do_syncfs("."); @@ -3418,7 +3418,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(log_startup_progress_interval); /* * If possible, hint to the kernel that we're soon going to fsync the data @@ -3432,7 +3432,7 @@ SyncDataDirectory(void) #endif /* Prepare to report progress syncing the data directory via fsync. */ - begin_startup_progress_phase(); + begin_progress_report_phase(log_startup_progress_interval); /* * Now we do the fsync()s in the same order. @@ -3536,8 +3536,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); @@ -3568,8 +3568,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..ef05f7246b 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(log_startup_progress_interval); /* * 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..c94ca31307 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,16 @@ 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; 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 +3447,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(int progress_report_interval) +{ + TimestampTz fin_time; + + /* Feature is disabled. */ + if (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, + progress_report_interval); + enable_timeout_every(PROGRESS_REPORT_TIMEOUT, fin_time, + 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/include/postmaster/startup.h b/src/include/postmaster/startup.h index d66ec1fcb1..96f90a6290 100644 --- a/src/include/postmaster/startup.h +++ b/src/include/postmaster/startup.h @@ -12,17 +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); @@ -32,8 +21,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 5639817690..55995bc2d8 100644 --- a/src/include/utils/elog.h +++ b/src/include/utils/elog.h @@ -471,4 +471,23 @@ 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 with a time for progress report interval. + */ +#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 void begin_progress_report_phase(int progress_report_interval); +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