Generalize ereport_startup_progress infrastructure
Hi,
ereport_startup_progress infrastructure added by commit 9ce346e [1]commit 9ce346eabf350a130bba46be3f8c50ba28506969 Author: Robert Haas <rhaas@postgresql.org> Date: Mon Oct 25 11:51:57 2021 -0400
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 [2]/messages/by-id/CALj2ACWeUFhhnDJKm6R5YxCsF4K7aB2pmRMvqP0BVTxdyce3EA@mail.gmail.com, 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.
Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.
Thoughts?
Thanks Robert for an offlist chat.
[1]: commit 9ce346eabf350a130bba46be3f8c50ba28506969 Author: Robert Haas <rhaas@postgresql.org> Date: Mon Oct 25 11:51:57 2021 -0400
commit 9ce346eabf350a130bba46be3f8c50ba28506969
Author: Robert Haas <rhaas@postgresql.org>
Date: Mon Oct 25 11:51:57 2021 -0400
Report progress of startup operations that take a long time.
[2]: /messages/by-id/CALj2ACWeUFhhnDJKm6R5YxCsF4K7aB2pmRMvqP0BVTxdyce3EA@mail.gmail.com
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/
Attachments:
v1-0001-Generalize-ereport_startup_progress-infrastructur.patchapplication/octet-stream; name=v1-0001-Generalize-ereport_startup_progress-infrastructur.patchDownload
From ee604cafe279be7ef3df04ebab475fc6f23de76d Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
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
</listitem>
</varlistentry>
- <varlistentry id="guc-log-startup-progress-interval" xreflabel="log_startup_progress_interval">
- <term><varname>log_startup_progress_interval</varname> (<type>integer</type>)
+ <varlistentry id="guc-log-progress-report-interval" xreflabel="log_progress_report_interval">
+ <term><varname>log_progress_report_interval</varname> (<type>integer</type>)
<indexterm>
- <primary><varname>log_startup_progress_interval</varname> configuration parameter</primary>
+ <primary><varname>log_progress_report_interval</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- 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 <literal>0</literal>
- 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 <literal>0</literal> 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 <filename>postgresql.conf</filename>
file or on the server command line.
</para>
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
On Tue, Aug 2, 2022 at 3:25 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
ereport_startup_progress infrastructure added by commit 9ce346e [1]
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 [2], 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.Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.
I'm not averse to reusing this infrastructure in other places, but I
doubt we'd want all of those places to be controlled by a single GUC,
especially because that GUC is also the on/off switch for the feature.
--
Robert Haas
EDB: http://www.enterprisedb.com
Hi,
On 8/2/22 8:40 PM, Robert Haas wrote:
CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
On Tue, Aug 2, 2022 at 3:25 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:ereport_startup_progress infrastructure added by commit 9ce346e [1]
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 [2], 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.Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.I'm not averse to reusing this infrastructure in other places, but I
doubt we'd want all of those places to be controlled by a single GUC,
especially because that GUC is also the on/off switch for the feature.
+1 on the idea to generalize this infrastructure in other places.
I also doubt about having one single GUC to control all the places: What
about adding in the patch the calls to the new API where you think it
could be useful too? (and in the same time make use of dedicated GUC(s)
where it makes sense?)
Regards,
--
Bertrand Drouvot
Amazon Web Services: https://aws.amazon.com
On Wed, Aug 3, 2022 at 12:11 AM Robert Haas <robertmhaas@gmail.com> wrote:
On Tue, Aug 2, 2022 at 3:25 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:ereport_startup_progress infrastructure added by commit 9ce346e [1]
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 [2], 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.Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.I'm not averse to reusing this infrastructure in other places, but I
doubt we'd want all of those places to be controlled by a single GUC,
especially because that GUC is also the on/off switch for the feature.
Thanks Robert! How about we tweak the function a bit -
begin_progress_report_phase(int timeout), so that each process can use
their own timeout interval? In this case, do we want to retain
log_startup_progress_interval as-is specific to the startup process?
If yes, other processes might come up with their own GUCs (if they
don't want to use hard-coded timeouts) similar to
log_startup_progress_interval, which isn't the right way IMO.
I think the notion of ereport_progress feature being disabled when the
timeout is 0, makes sense to me at least.
On the flip side, what if we just have a single GUC
log_progress_report_interval (as proposed in the v1 patch)? Do we ever
want different processes to emit progress report messages at different
frequencies? Well, I can think of the startup process during standby
recovery needing to emit recovery progress report messages at a much
lower frequency than the startup process during the crash recovery.
Again, controlling the frequencies with different GUCs isn't the way
forward. But we can do something like: process 1 emits messages with a
frequency of 2*log_progress_report_interval, process 2 with a
frequency 4*log_progress_report_interval and so on without needing
additional GUCs.
Thoughts?
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/rds/postgresql/
On Thu, Aug 4, 2022 at 9:57 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
On Wed, Aug 3, 2022 at 12:11 AM Robert Haas <robertmhaas@gmail.com> wrote:
On Tue, Aug 2, 2022 at 3:25 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:ereport_startup_progress infrastructure added by commit 9ce346e [1]
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 [2], 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.Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.I'm not averse to reusing this infrastructure in other places, but I
doubt we'd want all of those places to be controlled by a single GUC,
especially because that GUC is also the on/off switch for the feature.Thanks Robert! How about we tweak the function a bit -
begin_progress_report_phase(int timeout), so that each process can use
their own timeout interval? In this case, do we want to retain
log_startup_progress_interval as-is specific to the startup process?
If yes, other processes might come up with their own GUCs (if they
don't want to use hard-coded timeouts) similar to
log_startup_progress_interval, which isn't the right way IMO.I think the notion of ereport_progress feature being disabled when the
timeout is 0, makes sense to me at least.On the flip side, what if we just have a single GUC
log_progress_report_interval (as proposed in the v1 patch)? Do we ever
want different processes to emit progress report messages at different
frequencies? Well, I can think of the startup process during standby
recovery needing to emit recovery progress report messages at a much
lower frequency than the startup process during the crash recovery.
Again, controlling the frequencies with different GUCs isn't the way
forward. But we can do something like: process 1 emits messages with a
frequency of 2*log_progress_report_interval, process 2 with a
frequency 4*log_progress_report_interval and so on without needing
additional GUCs.Thoughts?
Here's v2 patch, passing progress report interval as an input to
begin_progress_report_phase() so that the processes can use their own
intervals(hard-coded or GUC) if they wish to not use the generic GUC
log_progress_report_interval.
Thoughts?
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/rds/postgresql/
Attachments:
v2-0001-Generalize-ereport_startup_progress-infrastructur.patchapplication/octet-stream; name=v2-0001-Generalize-ereport_startup_progress-infrastructur.patchDownload
From 9bf336ef7d959f5c10320b06d6748d0c63174e3b Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Mon, 8 Aug 2022 04:23:55 +0000
Subject: [PATCH v2] 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 | 22 ++++++
src/include/utils/timeout.h | 2 +-
12 files changed, 130 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
</listitem>
</varlistentry>
- <varlistentry id="guc-log-startup-progress-interval" xreflabel="log_startup_progress_interval">
- <term><varname>log_startup_progress_interval</varname> (<type>integer</type>)
+ <varlistentry id="guc-log-progress-report-interval" xreflabel="log_progress_report_interval">
+ <term><varname>log_progress_report_interval</varname> (<type>integer</type>)
<indexterm>
- <primary><varname>log_startup_progress_interval</varname> configuration parameter</primary>
+ <primary><varname>log_progress_report_interval</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
- 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 <literal>0</literal>
- 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 <literal>0</literal> 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 <filename>postgresql.conf</filename>
file or on the server command line.
</para>
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..15309b6ce4 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_progress_report_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..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 efb34d4dcb..0790df1c3c 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_progress_report_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_progress_report_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_progress_report_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..05d6265f81 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_progress_report_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..f5a2577d66 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(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/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 5639817690..e1e0d3e703 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -471,4 +471,26 @@ 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. Use the common GUC log_progress_report_interval if it fits the
+ * need, otherwise use a different 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 PGDLLIMPORT int log_progress_report_interval;
+
+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
On Mon, Aug 8, 2022 at 12:29 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
Here's v2 patch, passing progress report interval as an input to
begin_progress_report_phase() so that the processes can use their own
intervals(hard-coded or GUC) if they wish to not use the generic GUC
log_progress_report_interval.
I don't think we should rename the GUC to be more generic. I like it
the way that it is.
I also think you should extend this patch series with 1 or 2
additional patches showing where else you think we should be using
this infrastructure.
If no such places exist, this is pointless.
--
Robert Haas
EDB: http://www.enterprisedb.com
On Tue, Aug 9, 2022 at 6:05 PM Robert Haas <robertmhaas@gmail.com> wrote:
On Mon, Aug 8, 2022 at 12:29 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:Here's v2 patch, passing progress report interval as an input to
begin_progress_report_phase() so that the processes can use their own
intervals(hard-coded or GUC) if they wish to not use the generic GUC
log_progress_report_interval.I don't think we should rename the GUC to be more generic. I like it
the way that it is.
Done.
I also think you should extend this patch series with 1 or 2
additional patches showing where else you think we should be using
this infrastructure.If no such places exist, this is pointless.
I'm attaching 0002 for reporting removal of temp files and temp
relation files by postmaster.
If this looks okay, I can code 0003 for reporting processing of
snapshot, mapping and old WAL files by checkpointer.
Thoughts?
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/rds/postgresql/
Attachments:
v3-0001-Generalize-ereport_startup_progress-infrastructur.patchapplication/octet-stream; name=v3-0001-Generalize-ereport_startup_progress-infrastructur.patchDownload
From b97e490a5f30c504f62d4c77dbb7a34d4bb6cc2e Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
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
v3-0002-Progress-report-removal-of-temp-files-and-temp-re.patchapplication/octet-stream; name=v3-0002-Progress-report-removal-of-temp-files-and-temp-re.patchDownload
From 0bdf2771a648c8ff480da8b79c877915ee6e922f Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Tue, 9 Aug 2022 14:59:22 +0000
Subject: [PATCH v3] Progress report removal of temp files and temp relation
files
At times, there can be many temp files (under pgsql_tmp) and temp
relation files (under removal which after crash may take longer
during which users have no clue about what's going on in the
server before it comes up online. This patch uses
ereport_startup_progress to report the progress of the file
removal.
---
doc/src/sgml/config.sgml | 22 +++++++++++++++++++
src/backend/postmaster/postmaster.c | 14 +++++++++++-
src/backend/storage/file/fd.c | 14 ++++++++++++
src/backend/utils/misc/guc.c | 12 ++++++++++
src/backend/utils/misc/postgresql.conf.sample | 5 +++++
src/backend/utils/misc/timeout.c | 11 ++++++++--
src/include/postmaster/postmaster.h | 1 +
7 files changed, 76 insertions(+), 3 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2522f4c8c5..e10b5d7c34 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6761,6 +6761,28 @@ local0.* /var/log/postgresql
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-postmaster-progress-interval" xreflabel="log_postmaster_progress_interval">
+ <term><varname>log_postmaster_progress_interval</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_postmaster_progress_interval</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Sets the amount of time after which the postmaster 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, similar to <xref linkend="guc-log-startup-progress-interval"/>
+ parameter. The default is 10 seconds. A setting of <literal>0</literal>
+ 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 <filename>postgresql.conf</filename>
+ file or on the server command line.
+ </para>
+ </listitem>
+ </varlistentry>
+
</variablelist>
<para>
diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c
index 81cb585891..32b70420a4 100644
--- a/src/backend/postmaster/postmaster.c
+++ b/src/backend/postmaster/postmaster.c
@@ -247,6 +247,11 @@ char *bonjour_name;
bool restart_after_crash = true;
bool remove_temp_files_after_crash = true;
+/*
+ * Time between progress updates for long-running postmaster operations.
+ */
+int log_postmaster_progress_interval = 10000; /* 10 sec */
+
/* PIDs of special child processes; 0 when not running */
static pid_t StartupPID = 0,
BgWriterPID = 0,
@@ -653,7 +658,6 @@ PostmasterMain(int argc, char *argv[])
pqsignal_pm(SIGINT, pmdie); /* send SIGTERM and shut down */
pqsignal_pm(SIGQUIT, pmdie); /* send SIGQUIT and die */
pqsignal_pm(SIGTERM, pmdie); /* wait for children and shut down */
- pqsignal_pm(SIGALRM, SIG_IGN); /* ignored */
pqsignal_pm(SIGPIPE, SIG_IGN); /* ignored */
pqsignal_pm(SIGUSR1, sigusr1_handler); /* message from child process */
pqsignal_pm(SIGUSR2, dummy_handler); /* unused, reserve for children */
@@ -688,6 +692,11 @@ PostmasterMain(int argc, char *argv[])
pqsignal_pm(SIGXFSZ, SIG_IGN); /* ignored */
#endif
+ InitializeTimeouts(); /* establishes SIGALRM handler */
+
+ RegisterTimeout(PROGRESS_REPORT_TIMEOUT,
+ progress_report_timeout_handler);
+
/*
* Options setup
*/
@@ -1119,6 +1128,9 @@ PostmasterMain(int argc, char *argv[])
/* Write out nondefault GUC settings for child processes to use */
write_nondefault_variables(PGC_POSTMASTER);
+ /* Prepare to report progress of the temporary files removal phase */
+ begin_progress_report_phase(log_postmaster_progress_interval);
+
/*
* Clean out the temp directory used to transmit parameters to child
* processes (see internal_forkexec, below). We must do this before
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c
index a227f38775..74c6f264e3 100644
--- a/src/backend/storage/file/fd.c
+++ b/src/backend/storage/file/fd.c
@@ -97,11 +97,13 @@
#include "pgstat.h"
#include "port/pg_iovec.h"
#include "portability/mem.h"
+#include "postmaster/postmaster.h"
#include "postmaster/startup.h"
#include "storage/fd.h"
#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)
@@ -3081,6 +3083,12 @@ RemovePgTempFiles(void)
DIR *spc_dir;
struct dirent *spc_de;
+ /*
+ * Prepare to report progress of the temporary and temporary relation files
+ * removal phase.
+ */
+ begin_progress_report_phase(log_postmaster_progress_interval);
+
/*
* First process temp files in pg_default ($PGDATA/base)
*/
@@ -3154,6 +3162,9 @@ RemovePgTempFilesInDir(const char *tmpdirname, bool missing_ok, bool unlink_all)
snprintf(rm_path, sizeof(rm_path), "%s/%s",
tmpdirname, temp_de->d_name);
+ ereport_progress("removing temporary files under pgsql_tmp directory, elapsed time: %ld.%02d s, current file: %s",
+ rm_path);
+
if (unlink_all ||
strncmp(temp_de->d_name,
PG_TEMP_FILE_PREFIX,
@@ -3244,6 +3255,9 @@ RemovePgTempRelationFilesInDbspace(const char *dbspacedirname)
snprintf(rm_path, sizeof(rm_path), "%s/%s",
dbspacedirname, de->d_name);
+ ereport_progress("removing temporary relation files under pg_tblspc directory, elapsed time: %ld.%02d s, current file: %s",
+ rm_path);
+
if (unlink(rm_path) < 0)
ereport(LOG,
(errcode_for_file_access(),
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 5db5df6285..917717e9e9 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -3664,6 +3664,18 @@ static struct config_int ConfigureNamesInt[] =
NULL, NULL, NULL
},
+ {
+ {"log_postmaster_progress_interval", PGC_SIGHUP, LOGGING_WHEN,
+ gettext_noop("Time between progress updates for "
+ "long-running postmaster operations."),
+ gettext_noop("0 turns this feature off."),
+ GUC_UNIT_MS,
+ },
+ &log_postmaster_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 90bec0502c..21d882ee3b 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -540,6 +540,11 @@
# 0 disables the feature, > 0 indicates
# the interval in milliseconds.
+#log_postmaster_progress_interval = 10s # Time between progress updates for
+ # long-running postmaster operations.
+ # 0 disables the feature, > 0 indicates
+ # the interval in milliseconds.
+
# - What to Log -
#debug_print_parse = off
diff --git a/src/backend/utils/misc/timeout.c b/src/backend/utils/misc/timeout.c
index 6f5e08bc30..c4c567dc61 100644
--- a/src/backend/utils/misc/timeout.c
+++ b/src/backend/utils/misc/timeout.c
@@ -16,6 +16,7 @@
#include <sys/time.h>
+#include "libpq/pqsignal.h"
#include "miscadmin.h"
#include "storage/proc.h"
#include "utils/timeout.h"
@@ -375,8 +376,11 @@ handle_sig_alarm(SIGNAL_ARGS)
/*
* SIGALRM is always cause for waking anything waiting on the process
* latch.
+ *
+ * Postmaster has no latch associated with it.
*/
- SetLatch(MyLatch);
+ if (MyLatch)
+ SetLatch(MyLatch);
/*
* Always reset signal_pending, even if !alarm_enabled, since indeed no
@@ -494,7 +498,10 @@ InitializeTimeouts(void)
all_timeouts_initialized = true;
/* Now establish the signal handler */
- pqsignal(SIGALRM, handle_sig_alarm);
+ if (MyProcPid == PostmasterPid)
+ pqsignal_pm(SIGALRM, handle_sig_alarm);
+ else
+ pqsignal(SIGALRM, handle_sig_alarm);
}
/*
diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h
index 90e333ccd2..540e9e9895 100644
--- a/src/include/postmaster/postmaster.h
+++ b/src/include/postmaster/postmaster.h
@@ -30,6 +30,7 @@ extern PGDLLIMPORT bool enable_bonjour;
extern PGDLLIMPORT char *bonjour_name;
extern PGDLLIMPORT bool restart_after_crash;
extern PGDLLIMPORT bool remove_temp_files_after_crash;
+extern PGDLLIMPORT int log_postmaster_progress_interval;
#ifdef WIN32
extern PGDLLIMPORT HANDLE PostmasterHandle;
--
2.34.1
Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.I'm not averse to reusing this infrastructure in other places, but I
doubt we'd want all of those places to be controlled by a single GUC,
especially because that GUC is also the on/off switch for the feature.Thanks Robert! How about we tweak the function a bit -
begin_progress_report_phase(int timeout), so that each process can use
their own timeout interval? In this case, do we want to retain
log_startup_progress_interval as-is specific to the startup process?
If yes, other processes might come up with their own GUCs (if they
don't want to use hard-coded timeouts) similar to
log_startup_progress_interval, which isn't the right way IMO.I think the notion of ereport_progress feature being disabled when the
timeout is 0, makes sense to me at least.On the flip side, what if we just have a single GUC
log_progress_report_interval (as proposed in the v1 patch)? Do we ever
want different processes to emit progress report messages at different
frequencies? Well, I can think of the startup process during standby
recovery needing to emit recovery progress report messages at a much
lower frequency than the startup process during the crash recovery.
Again, controlling the frequencies with different GUCs isn't the way
forward. But we can do something like: process 1 emits messages with a
frequency of 2*log_progress_report_interval, process 2 with a
frequency 4*log_progress_report_interval and so on without needing
additional GUCs.Thoughts?
+1 for the idea to generalize the infrastructure.
Given two options, option-1 is to use a single GUC across all kind of
log running operations and option-2 is to use multiple GUCs (one for
each kind of long running operations), I go with option-1 because if a
user is interested to see a log message after every 10s for startup
operations (or any other long running operations) then it is likely
that he is interested to see other long running operations after every
10s only. It does not make sense to use different intervals for each
kind of long running operation here. It also increases the number of
GUCs which makes things complex. So it is a good idea to use a single
GUC here. But I am worried about the on/off switch as Robert
mentioned. How about using a new GUC to indicate features on/off. Say
"log_long_running_operations" which contains a comma separated string
which indicates the features to be enabled. For example,
"log_long_running_operations = startup, postmaster" will enable
logging for startup and postmaster operations and disables logging of
other long running operations. With this the number of GUCs will be
limited to 2 and it is simple and easy for the user.
Thanks & Regards,
Nitin Jadhav
On Thu, Aug 4, 2022 at 9:58 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
Show quoted text
On Wed, Aug 3, 2022 at 12:11 AM Robert Haas <robertmhaas@gmail.com> wrote:
On Tue, Aug 2, 2022 at 3:25 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:ereport_startup_progress infrastructure added by commit 9ce346e [1]
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 [2], 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.Here's an attempt to generalize the ereport_startup_progress
infrastructure. The attached v1 patch places the code in elog.c/.h,
renames associated functions and variables, something like
ereport_startup_progress to ereport_progress,
log_startup_progress_interval to log_progress_report_interval and so
on.I'm not averse to reusing this infrastructure in other places, but I
doubt we'd want all of those places to be controlled by a single GUC,
especially because that GUC is also the on/off switch for the feature.Thanks Robert! How about we tweak the function a bit -
begin_progress_report_phase(int timeout), so that each process can use
their own timeout interval? In this case, do we want to retain
log_startup_progress_interval as-is specific to the startup process?
If yes, other processes might come up with their own GUCs (if they
don't want to use hard-coded timeouts) similar to
log_startup_progress_interval, which isn't the right way IMO.I think the notion of ereport_progress feature being disabled when the
timeout is 0, makes sense to me at least.On the flip side, what if we just have a single GUC
log_progress_report_interval (as proposed in the v1 patch)? Do we ever
want different processes to emit progress report messages at different
frequencies? Well, I can think of the startup process during standby
recovery needing to emit recovery progress report messages at a much
lower frequency than the startup process during the crash recovery.
Again, controlling the frequencies with different GUCs isn't the way
forward. But we can do something like: process 1 emits messages with a
frequency of 2*log_progress_report_interval, process 2 with a
frequency 4*log_progress_report_interval and so on without needing
additional GUCs.Thoughts?
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/rds/postgresql/
On Tue, Aug 9, 2022 at 11:54 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
I'm attaching 0002 for reporting removal of temp files and temp
relation files by postmaster.If this looks okay, I can code 0003 for reporting processing of
snapshot, mapping and old WAL files by checkpointer.
I think that someone is going to complain about the changes to
timeout.c. Some trouble has been taken to allow things like
SetLatch(MyLatch) to be unconditional. Aside from that, I am unsure
how generally safe it is to use the timeout infrastructure in the
postmaster.
From a user-interface point of view, log_postmaster_progress_interval
seems a bit awkward. It's really quite narrow, basically just checking
for one thing. I'm not sure I like adding a GUC for something that
specific, although I also don't have another idea at the moment
either. Hmm.
Maybe the checkpointer is a better candidate, but somehow I feel that
we can't consider this sort of thing separate from the existing
progress reporting that checkpointer already does. Perhaps we need to
think of changing or improving that in some way rather than adding
something wholly new alongside the existing system.
--
Robert Haas
EDB: http://www.enterprisedb.com
On Wed, Aug 10, 2022 at 11:00:20AM -0400, Robert Haas wrote:
Maybe the checkpointer is a better candidate, but somehow I feel that
we can't consider this sort of thing separate from the existing
progress reporting that checkpointer already does. Perhaps we need to
think of changing or improving that in some way rather than adding
something wholly new alongside the existing system.
I agree that the checkpointer has a good chance of being a better
candidate. Are you thinking of integrating this into log_checkpoints
somehow? Perhaps this parameter could optionally accept an interval for
logging the progress of ongoing checkpoints.
--
Nathan Bossart
Amazon Web Services: https://aws.amazon.com
On Wed, Aug 10, 2022 at 6:21 PM Nitin Jadhav
<nitinjadhavpostgres@gmail.com> wrote:
Given two options, option-1 is to use a single GUC across all kind of
log running operations and option-2 is to use multiple GUCs (one for
each kind of long running operations), I go with option-1 because if a
user is interested to see a log message after every 10s for startup
operations (or any other long running operations) then it is likely
that he is interested to see other long running operations after every
10s only. It does not make sense to use different intervals for each
kind of long running operation here. It also increases the number of
GUCs which makes things complex. So it is a good idea to use a single
GUC here.
+1.
But I am worried about the on/off switch as Robert
mentioned.
Are you worried that users might want to switch off the progress
report messages at process level, for instance, they want to log the
startup process' long running operations progress but not, say,
checkpointer or postmaster? IMO, a long running operation, if it is
happening in any of the processes, is a concern for the users and
having progress report log messages for them would help users debug
any issues or improve observability of the server as a whole. With
single GUC, the server log might contain progress reports of all the
long running (wherever we use this ereport_progress()) operations in
the entire server's lifecycle, which isn't bad IMO.
I'd still vote for a single GUC log_progress_report_interval without
worrying much about process-level enable/disable capability. However,
let's hear what other hackers think about this.
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/rds/postgresql/
On Wed, Aug 17, 2022 at 2:45 AM Nathan Bossart <nathandbossart@gmail.com> wrote:
On Wed, Aug 10, 2022 at 11:00:20AM -0400, Robert Haas wrote:
Maybe the checkpointer is a better candidate, but somehow I feel that
we can't consider this sort of thing separate from the existing
progress reporting that checkpointer already does. Perhaps we need to
think of changing or improving that in some way rather than adding
something wholly new alongside the existing system.I agree that the checkpointer has a good chance of being a better
candidate. Are you thinking of integrating this into log_checkpoints
somehow? Perhaps this parameter could optionally accept an interval for
logging the progress of ongoing checkpoints.
Certainly the checkpointer is an immediate candidate. For instance, I
can think of using ereport_progress() in CheckPointSnapBuild() for
snapshot files processing, CheckPointLogicalRewriteHeap() for mapping
files processing, BufferSync() for checkpointing dirty buffers (?),
ProcessSyncRequests() for processing fsync() requests,
RemoveOldXlogFiles(), RemoveNonParentXlogFiles()(?). I personally have
seen cases where some of these checkpoint operations take a lot of
time in production environments and a better observability would help
a lot.
However, I'm not sure if turning log_checkpoints to an integer type to
use for checkpoint progress reporting is a good idea here.
As I explained upthread [1]/messages/by-id/CALj2ACUJA73nCK_Li7v4_OOkRqwQBX14Fx2ALb7GDRwUTNGK-Q@mail.gmail.com, I'd vote for a single GUC at the entire
server level. If the users/customers request per-process or
per-operation progress report GUCs, we can then consider it.
Thoughts?
[1]: /messages/by-id/CALj2ACUJA73nCK_Li7v4_OOkRqwQBX14Fx2ALb7GDRwUTNGK-Q@mail.gmail.com
--
Bharath Rupireddy
RDS Open Source Databases: https://aws.amazon.com/rds/postgresql/
On Wed, Aug 17, 2022 at 4:30 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
As I explained upthread [1], I'd vote for a single GUC at the entire
server level. If the users/customers request per-process or
per-operation progress report GUCs, we can then consider it.
Well, I don't agree that either of the proposed new uses of this
infrastructure are the right way to solve the problems in question, so
worrying about how to name the GUCs when we have a bunch of uses of
this infrastructure seems to me to be premature. The proposed use in
the postmaster doesn't look very safe, so you either need to give up
on that or figure out a way to make it safe. The proposed use in the
checkpointer looks like it needs more design work, because it's not
clear whether or how it should interact with log_checkpoints. While I
agree that changing log_checkpoints into an integer value doesn't
necessarily make sense, having some kind of new checkpoint logging
that is completely unrelated to existing checkpoint logging doesn't
necessarily make sense to me either.
I do have some sympathy with the idea that if people care about
operations that unexpectedly run for a long time, they probably care
about all of them, and probably don't care about changing the timeout
or even the enable switch for each one individually. Honestly, it's
not very clear to me who would want to ever turn off the startup
progress stuff, or why they'd want to change the interval. I added a
GUC for it out of an abundance of caution, but I don't know why you'd
really want a different setting. Maybe there's some reason, but it's
not clear to me. At the same time, I don't think the overall picture
here is too clear yet. I'm reluctant to commit to a specific UI for a
feature whose scope we don't seem to know.
--
Robert Haas
EDB: http://www.enterprisedb.com
On Wed, Aug 17, 2022 at 8:44 PM Robert Haas <robertmhaas@gmail.com> wrote:
Well, I don't agree that either of the proposed new uses of this
infrastructure are the right way to solve the problems in question, so
worrying about how to name the GUCs when we have a bunch of uses of
this infrastructure seems to me to be premature.
Agreed.
The proposed use in
the postmaster doesn't look very safe, so you either need to give up
on that or figure out a way to make it safe.
Is registering a SIGALRM handler in postmaster not a good idea? Is
setting the MyLatch conditionally [1]/* * SIGALRM is always cause for waking anything waiting on the process * latch. + * + * Postmaster has no latch associated with it. */ - SetLatch(MyLatch); + if (MyLatch) + SetLatch(MyLatch); a concern?
I agree that the handle_sig_alarm() code for postmaster may not look
good as it holds interrupts and does a bunch of other things. But is
it a bigger issue?
The proposed use in the
checkpointer looks like it needs more design work, because it's not
clear whether or how it should interact with log_checkpoints. While I
agree that changing log_checkpoints into an integer value doesn't
necessarily make sense, having some kind of new checkpoint logging
that is completely unrelated to existing checkpoint logging doesn't
necessarily make sense to me either.
Hm. Yes, we cannot forget about log_checkpoints while considering
adding more logs and controls with other GUCs. We could say that one
needs to enable both log_checkpoints and the progress report GUC, but
that's not great from usability perspective.
I do have some sympathy with the idea that if people care about
operations that unexpectedly run for a long time, they probably care
about all of them, and probably don't care about changing the timeout
or even the enable switch for each one individually.
I've seen the cases myself and asked by many about the server being
unresponsive in the cases where it processes files, for instance, temp
files in postmaster after a restart or snapshot or mapping or
BufferSync() during checkpoint where this sort of progress reporting
would've helped.
Thinking of another approach for reporting file processing alone - a
GUC log_file_processing_traffic = {none, medium, high} or {0, 1, 2,
..... limit} that users can set to emit a file processing log after a
certain number of files. It doesn't require a timeout mechanism, so it
can be used by any process. But, it is specific to just files.
Similar to above but a bit generic, not specific to just file
processing, a GUC log_processing_traffic = {none, medium, high} or {0,
1, 2, ..... limit}.
Thoughts?
[1]
/*
* SIGALRM is always cause for waking anything waiting on the process
* latch.
+ *
+ * Postmaster has no latch associated with it.
*/
- SetLatch(MyLatch);
+ if (MyLatch)
+ SetLatch(MyLatch);--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com