Modified the reset_startup_progress_timeout() to take the second
parameter which indicates whether it is called for initialization or
for resetting. Without this parameter there is a problem if we call
init_startup_progress() more than one time if there is no call to
ereport_startup_progress() in between as the code related to disabling
the timer has been removed.
reset_startup_progress_timeout(TimeStampTz now, bool is_init)
{
if (is_init)
next_timeout = now + interval;
else
{
next_timeout = scheduled_startup_progress_timeout + interval;
if (next_timeout < now)
{
// Either the timeout was processed so late that we missed an
entire cycle,
// or the system clock was set backwards.
next_timeout = now + interval;
}
enable_timeout_at(next_timeout);
scheduled_startup_progress_timeout = next_timeout;
}
}
I have incorporated this in the attached patch. Please correct me if I am wrong.
> This makes sense, but I think I'd like to have all the functions in
> this patch use names_like_this() rather than NamesLikeThis().
I have changed all the function names accordingly. But I would like to
know why it should be names_like_this() as there are many functions
with the format NamesLikeThis(). I would like to understand when to
use what, just to incorporate in the future patches.
> Hmm, yeah, that seems good, but given this change, maybe the variables
> need a little renaming. Like change last_startup_progress_timeout to
> scheduled_startup_progress_timeout, perhaps.
Right. Changed the variable name.
> I guess this one needs to return a Boolean, actually.
Yes.
> reset_startup_progress_timeout(TimeStampTz now)
> {
> next_timeout = last_startup_progress_timeout + interval;
> if (next_timeout < now)
> {
> // Either the timeout was processed so late that we missed an entire
> cycle,
> // or the system clock was set backwards.
> next_timeout = now + interval;
> }
> enable_timeout_at(next_timeout);
> last_startup_progress_timeout = next_timeout;
> }
As per the above logic, I would like to discuss 2 cases.
Case-1:
First scheduled timeout is after 1 sec. But the time out occurred
after 1.5 sec. So the log msg prints after 1.5 sec. Next timer is
scheduled after 2 sec (scheduled_startup_progress_timeout + interval).
The condition (next_timeout < now) gets evaluated to false and
everything goes smooth.
Case-2:
First scheduled timeout is after 1 sec. But the timeout occurred after
2.5 sec. So the log msg prints after 2.5 sec. Now next time is
scheduled after 2 sec (scheduled_startup_progress_timeout + interval).
So the condition (next_timeout < now) will fail and the next_timeout
will get reset to 3.5 sec (2.5 + 1) and it continues. Is this
behaviour ok or should we set the next_timeout to 3 sec. Please share
your thoughts on this.
Thanks & Regards,
Nitin Jadhav
On Thu, Aug 5, 2021 at 7:49 PM Robert Haas <robertmh...@gmail.com> wrote:
>
> On Thu, Aug 5, 2021 at 7:41 AM Nitin Jadhav
> <nitinjadhavpostg...@gmail.com> wrote:
> > This seems a little confusing. As we are setting
> > last_startup_progress_timeout = now and then calling
> > reset_startup_progress_timeout() which will calculate the next_time
> > based on the value of last_startup_progress_timeout initially and
> > checks whether next_timeout is less than now. It doesn't make sense to
> > me. I feel we should calculate the next_timeout based on the time that
> > it is supposed to fire next time. So we should set
> > last_startup_progress_timeout = next_timeout after enabling the timer.
> > Also I feel with the 2 functions mentioned above, we also need
> > InitStartupProgress() which sets the initial value to
> > startupProcessOpStartTime which is used to calculate the time
> > difference and display in the logs. I could see those functions like
> > below.
> >
> > InitStartupProgress(void)
> > {
> > startupProcessOpStartTime = GetCurrentTimestamp();
> > ResetStartupProgressTimeout(startupProcessOpStartTime);
> > }
>
> This makes sense, but I think I'd like to have all the functions in
> this patch use names_like_this() rather than NamesLikeThis().
>
> > reset_startup_progress_timeout(TimeStampTz now)
> > {
> > next_timeout = last_startup_progress_timeout + interval;
> > if (next_timeout < now)
> > {
> > // Either the timeout was processed so late that we missed an entire
> > cycle,
> > // or the system clock was set backwards.
> > next_timeout = now + interval;
> > }
> > enable_timeout_at(next_timeout);
> > last_startup_progress_timeout = next_timeout;
> > }
>
> Hmm, yeah, that seems good, but given this change, maybe the variables
> need a little renaming. Like change last_startup_progress_timeout to
> scheduled_startup_progress_timeout, perhaps.
>
> > startup_progress_timeout_has_expired()
> > {
> > if (!startup_progress_timer_expired)
> > return;
> > now = GetCurrentTimestamp();
> > // compute timestamp difference based on startupProcessOpStartTime
> > reset_startup_progress_timeout(now);
> > }
>
> I guess this one needs to return a Boolean, actually.
>
> --
> Robert Haas
> EDB: http://www.enterprisedb.com
From 9c2507fa2daaf12f50f366259fcc4b883acd608b Mon Sep 17 00:00:00 2001
From: Nitin <nitin.jadhav@enterprisedb.com>
Date: Mon, 9 Aug 2021 17:50:10 +0530
Subject: [PATCH] Shows the progress of the operations performed during startup
process. The interval between each progress update is configurable and it
should be mentioned in seconds
---
src/backend/access/transam/xlog.c | 5 ++
src/backend/postmaster/startup.c | 97 +++++++++++++++++++++++++++
src/backend/storage/file/fd.c | 11 +++
src/backend/storage/file/reinit.c | 10 +++
src/backend/utils/init/postinit.c | 2 +
src/backend/utils/misc/guc.c | 17 +++++
src/backend/utils/misc/postgresql.conf.sample | 6 ++
src/include/postmaster/startup.h | 18 +++++
src/include/utils/guc.h | 2 +
src/include/utils/timeout.h | 1 +
10 files changed, 169 insertions(+)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 8b39a2f..988302e 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -7354,6 +7354,8 @@ StartupXLOG(void)
(errmsg("redo starts at %X/%X",
LSN_FORMAT_ARGS(ReadRecPtr))));
+ init_startup_progress();
+
/*
* main redo apply loop
*/
@@ -7361,6 +7363,9 @@ StartupXLOG(void)
{
bool switchedTLI = false;
+ ereport_startup_progress("redo in progress, elapsed time: %ld.%02d s, current LSN: %X/%X",
+ LSN_FORMAT_ARGS(ReadRecPtr));
+
#ifdef WAL_DEBUG
if (XLOG_DEBUG ||
(rmid == RM_XACT_ID && trace_recovery_messages <= DEBUG2) ||
diff --git a/src/backend/postmaster/startup.c b/src/backend/postmaster/startup.c
index 0f4f00d..b812be5 100644
--- a/src/backend/postmaster/startup.c
+++ b/src/backend/postmaster/startup.c
@@ -59,6 +59,22 @@ static volatile sig_atomic_t promote_signaled = false;
*/
static volatile sig_atomic_t in_restore_command = false;
+/*
+ * Start timestamp of the operation that occur during startup process.
+ */
+static TimestampTz startup_process_op_start_time;
+
+/*
+ * Indicates the timestamp at which the timer was supposed to expire.
+ */
+static TimestampTz scheduled_startup_progress_timeout;
+
+/*
+ * Indicates whether the startup progress interval mentioned by the user is
+ * elapsed or not. TRUE if timeout occurred, FALSE otherwise.
+ */
+static bool startup_progress_timer_expired;
+
/* Signal handlers */
static void StartupProcTriggerHandler(SIGNAL_ARGS);
static void StartupProcSigHupHandler(SIGNAL_ARGS);
@@ -233,6 +249,7 @@ StartupProcessMain(void)
RegisterTimeout(STANDBY_DEADLOCK_TIMEOUT, StandbyDeadLockHandler);
RegisterTimeout(STANDBY_TIMEOUT, StandbyTimeoutHandler);
RegisterTimeout(STANDBY_LOCK_TIMEOUT, StandbyLockTimeoutHandler);
+ RegisterTimeout(STARTUP_PROGRESS_TIMEOUT, startup_progress_timeout_handler);
/*
* Unblock signals (they were blocked when the postmaster forked us)
@@ -282,3 +299,83 @@ ResetPromoteSignaled(void)
{
promote_signaled = false;
}
+
+/*
+ * Schedule a wakeup call for logging the progress of startup process.
+ */
+void
+startup_progress_timeout_handler(void)
+{
+ startup_progress_timer_expired = true;
+}
+
+/*
+ * Sets the start timestamp of the current operation and also enables the
+ * timeout for logging the progress of startup process.
+ */
+void
+init_startup_progress(void)
+{
+ startup_process_op_start_time = GetCurrentTimestamp();
+ reset_startup_progress_timeout(startup_process_op_start_time, true);
+}
+
+/*
+ * Decides whether to log the startup progress or not based on whether the
+ * timer is expired or not. It returns FALSE if the timer is not expired,
+ * Otherwise it calculates the elapsed time and sets the respective out
+ * parameters secs and usecs. Enables the timer for the next log message and
+ * returns TRUE.
+ */
+bool
+startup_progress_timeout_has_expired(long *secs, int *usecs)
+{
+ long seconds;
+ int useconds;
+ TimestampTz now;
+
+ /* If the timeout has not occurred, then no need to log the details. */
+ if (!startup_progress_timer_expired)
+ return false;
+
+ /* Calculate the elapsed time. */
+ now = GetCurrentTimestamp();
+ TimestampDifference(startup_process_op_start_time, now, &seconds, &useconds);
+
+ *secs = seconds;
+ *usecs = useconds;
+
+ reset_startup_progress_timeout(now, false);
+ return true;
+}
+
+/*
+ * Calculates the timestamp at which the next timer should expire and enables
+ * the timer accordingly.
+ */
+void
+reset_startup_progress_timeout(TimestampTz now, bool is_init)
+{
+ TimestampTz next_timeout;
+ int interval_in_ms = log_startup_progress_interval * 1000;
+
+ if (is_init)
+ next_timeout = TimestampTzPlusMilliseconds(now, interval_in_ms);
+ else
+ {
+ next_timeout = TimestampTzPlusMilliseconds(scheduled_startup_progress_timeout,
+ interval_in_ms);
+ if (next_timeout < now)
+ {
+ /*
+ * Either the timeout was processed so late that we missed an
+ * entire cycle or system clock was set backwards.
+ */
+ next_timeout = TimestampTzPlusMilliseconds(now, interval_in_ms);
+ }
+ }
+
+ enable_timeout_at(STARTUP_PROGRESS_TIMEOUT, next_timeout);
+ scheduled_startup_progress_timeout = next_timeout;
+ startup_progress_timer_expired = false;
+}
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.c
index 5d5e8ae..9128d22 100644
--- a/src/backend/storage/file/fd.c
+++ b/src/backend/storage/file/fd.c
@@ -96,6 +96,7 @@
#include "pgstat.h"
#include "port/pg_iovec.h"
#include "portability/mem.h"
+#include "postmaster/startup.h"
#include "storage/fd.h"
#include "storage/ipc.h"
#include "utils/guc.h"
@@ -3334,6 +3335,9 @@ do_syncfs(const char *path)
{
int fd;
+ ereport_startup_progress("syncing data directory (syncfs), elapsed time: %ld.%02d s, current path: %s",
+ path);
+
fd = OpenTransientFile(path, O_RDONLY);
if (fd < 0)
{
@@ -3410,6 +3414,8 @@ SyncDataDirectory(void)
DIR *dir;
struct dirent *de;
+ init_startup_progress();
+
/*
* On Linux, we don't have to open every single file one by one. We
* can use syncfs() to sync whole filesystems. We only expect
@@ -3452,6 +3458,8 @@ SyncDataDirectory(void)
walkdir("pg_tblspc", pre_sync_fname, true, DEBUG1);
#endif
+ init_startup_progress();
+
/*
* Now we do the fsync()s in the same order.
*
@@ -3583,6 +3591,9 @@ pre_sync_fname(const char *fname, bool isdir, int elevel)
static void
datadir_fsync_fname(const char *fname, bool isdir, int elevel)
{
+ ereport_startup_progress("syncing data directory (fsync), elapsed time: %ld.%02d s, current path: %s",
+ fname);
+
/*
* We want to silently ignoring errors about unreadable files. Pass that
* desire on to fsync_fname_ext().
diff --git a/src/backend/storage/file/reinit.c b/src/backend/storage/file/reinit.c
index 40c758d..41bae8a 100644
--- a/src/backend/storage/file/reinit.c
+++ b/src/backend/storage/file/reinit.c
@@ -17,6 +17,7 @@
#include <unistd.h>
#include "common/relpath.h"
+#include "postmaster/startup.h"
#include "storage/copydir.h"
#include "storage/fd.h"
#include "storage/reinit.h"
@@ -64,6 +65,7 @@ ResetUnloggedRelations(int op)
"ResetUnloggedRelations",
ALLOCSET_DEFAULT_SIZES);
oldctx = MemoryContextSwitchTo(tmpctx);
+ init_startup_progress();
/*
* First process unlogged files in pg_default ($PGDATA/base)
@@ -136,6 +138,14 @@ ResetUnloggedRelationsInTablespaceDir(const char *tsdirname, int op)
snprintf(dbspace_path, sizeof(dbspace_path), "%s/%s",
tsdirname, de->d_name);
+
+ if (op & UNLOGGED_RELATION_INIT)
+ ereport_startup_progress("resetting unlogged relations (init), elapsed time: %ld.%02d s, current path: %s",
+ dbspace_path);
+ else if (op & UNLOGGED_RELATION_CLEANUP)
+ ereport_startup_progress("resetting unlogged relations (cleanup), elapsed time: %ld.%02d s, current path: %s",
+ dbspace_path);
+
ResetUnloggedRelationsInDbspaceDir(dbspace_path, op);
}
diff --git a/src/backend/utils/init/postinit.c b/src/backend/utils/init/postinit.c
index 51d1bbe..1676bc1 100644
--- a/src/backend/utils/init/postinit.c
+++ b/src/backend/utils/init/postinit.c
@@ -40,6 +40,7 @@
#include "pgstat.h"
#include "postmaster/autovacuum.h"
#include "postmaster/postmaster.h"
+#include "postmaster/startup.h"
#include "replication/walsender.h"
#include "storage/bufmgr.h"
#include "storage/fd.h"
@@ -622,6 +623,7 @@ InitPostgres(const char *in_dbname, Oid dboid, const char *username,
IdleInTransactionSessionTimeoutHandler);
RegisterTimeout(IDLE_SESSION_TIMEOUT, IdleSessionTimeoutHandler);
RegisterTimeout(CLIENT_CONNECTION_CHECK_TIMEOUT, ClientCheckTimeoutHandler);
+ RegisterTimeout(STARTUP_PROGRESS_TIMEOUT, startup_progress_timeout_handler);
}
/*
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index a2e0f8d..31894aa 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -679,6 +679,11 @@ static char *recovery_target_lsn_string;
/* should be static, but commands/variable.c needs to get at this */
char *role_string;
+/*
+ * The interval between each progress update of the operations that occur
+ * during startup process.
+ */
+int log_startup_progress_interval;
/*
* Displayable names for context types (enum GucContext)
@@ -3546,6 +3551,18 @@ static struct config_int ConfigureNamesInt[] =
check_client_connection_check_interval, NULL, NULL
},
+ {
+ {"log_startup_progress_interval", PGC_SIGHUP, LOGGING_WHEN,
+ gettext_noop("Sets the time interval between each progress update "
+ "of the startup process."),
+ gettext_noop("0 logs all messages. -1 turns this feature off."),
+ GUC_UNIT_S,
+ },
+ &log_startup_progress_interval,
+ -1, -1, INT_MAX,
+ NULL, NULL, NULL
+ },
+
/* End-of-list marker */
{
{NULL, 0, 0, NULL, NULL}, NULL, 0, 0, 0, NULL, NULL, NULL
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index b242a7f..901e4ba 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -523,6 +523,12 @@
# are logged regardless of their duration; 1.0 logs all
# statements from all transactions, 0.0 never logs
+log_startup_progress_interval = 10 # Sets the time interval between each
+ # progress update of the startup process.
+ # -1 disables the feature, 0 logs all
+ # messages, > 0 indicates the interval in
+ # seconds.
+
# - What to Log -
#debug_print_parse = off
diff --git a/src/include/postmaster/startup.h b/src/include/postmaster/startup.h
index bf6adf1..3596be8 100644
--- a/src/include/postmaster/startup.h
+++ b/src/include/postmaster/startup.h
@@ -12,6 +12,19 @@
#ifndef _STARTUP_H
#define _STARTUP_H
+#include "datatype/timestamp.h"
+
+/*
+ * Logs the startup progress message if the timer has expired.
+ */
+#define ereport_startup_progress(msg, ...) \
+ do { \
+ long secs; \
+ int usecs; \
+ if (startup_progress_timeout_has_expired(&secs, &usecs)) \
+ ereport(LOG, errmsg(msg, secs, (usecs / 10000), ##__VA_ARGS__ )); \
+ } while(0)
+
extern void HandleStartupProcInterrupts(void);
extern void StartupProcessMain(void) pg_attribute_noreturn();
extern void PreRestoreCommand(void);
@@ -19,4 +32,9 @@ extern void PostRestoreCommand(void);
extern bool IsPromoteSignaled(void);
extern void ResetPromoteSignaled(void);
+extern void init_startup_progress(void);
+extern void startup_progress_timeout_handler(void);
+bool startup_progress_timeout_has_expired(long *secs, int *usecs);
+void reset_startup_progress_timeout(TimestampTz cur_time, bool is_init);
+
#endif /* _STARTUP_H */
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index a7c3a49..7c12632 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -282,6 +282,8 @@ extern int tcp_user_timeout;
extern bool trace_sort;
#endif
+extern int log_startup_progress_interval;
+
/*
* Functions exported by guc.c
*/
diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.h
index 93e6a69..29ea7f6 100644
--- a/src/include/utils/timeout.h
+++ b/src/include/utils/timeout.h
@@ -33,6 +33,7 @@ typedef enum TimeoutId
IDLE_IN_TRANSACTION_SESSION_TIMEOUT,
IDLE_SESSION_TIMEOUT,
CLIENT_CONNECTION_CHECK_TIMEOUT,
+ STARTUP_PROGRESS_TIMEOUT,
/* First user-definable timeout reason */
USER_TIMEOUT,
/* Maximum number of timeout reasons */
--
1.8.3.1
