From: Justin Pryzby <pryzby@telsasoft.com>
To: Robert Haas <robertmhaas@gmail.com>
Cc: Nitin Jadhav <nitinjadhavpostgres@gmail.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Cc: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Andres Freund <andres@anarazel.de>
Cc: Stephen Frost <sfrost@snowman.net>
Cc: Magnus Hagander <magnus@hagander.net>
Cc: Thomas Munro <thomas.munro@gmail.com>
Cc: pgsql-hackers@postgresql.org
Subject: Re: when the startup process doesn't (logging startup delays)
Date: Mon, 26 Jul 2021 10:30:23 -0500
Message-ID: <20210726153023.GC23997@telsasoft.com> (raw)
In-Reply-To: <CA+TgmoY-0AUppRhiOGg1Bev+CwE_ZTajCDAY8B-wSLuw0KGC0w@mail.gmail.com>
References: <20210610100125.GE16435@telsasoft.com>
<CAMm1aWbj3G8YJohr+FUOt1R+vz+e5sGiGCoK5kSRCgmDj5k+0Q@mail.gmail.com>
<20210617125254.GB31772@telsasoft.com>
<CAMm1aWadG_xgncYxFt-GAqRXWL2WE-5bu3qdJtW6CYEwhw7QbQ@mail.gmail.com>
<CALj2ACUNaAQjLYnyQvG988d=Qzw5yQhaRLYN6ihaxZShJ6AeHg@mail.gmail.com>
<CAMm1aWZScAOM4CA60sS90y3qPNtZ75Wo+6mRUry06bVjfRqePg@mail.gmail.com>
<20210721131326.GA19620@telsasoft.com>
<CAMm1aWb2OzbvOBxB-M+UUEXt0h2nmtNybo5x30b4vyCOLZB_dA@mail.gmail.com>
<20210725175654.GA23997@telsasoft.com>
<CA+TgmoY-0AUppRhiOGg1Bev+CwE_ZTajCDAY8B-wSLuw0KGC0w@mail.gmail.com>
On Mon, Jul 26, 2021 at 10:13:09AM -0400, Robert Haas wrote:
> I don't think walkdir() has any business calling LogStartupProgress()
> at all. It's supposed to be a generic function, not one that is only
> available to be called from the startup process, or has different
> behavior there. From my point of view, the right thing is to put the
> logging calls into the particular callbacks that SyncDataDirectory()
> uses.
You're right - this is better.
On Wed, Jul 21, 2021 at 04:47:32PM +0530, Bharath Rupireddy wrote:
> > > 1) I still don't see the need for two functions LogStartupProgress and
> > > LogStartupProgressComplete. Most of the code is duplicate. I think we
> > > can just do it with a single function something like [1]:
> >
> > I agree that one function can do this more succinctly. I think it's best to
> > use a separate enum value for START operations and END operations.
>
> Maybe I'm missing something here, but I don't understand the purpose
> of this. You can always combine two functions into one, but it's only
> worth doing if you end up with less code, which doesn't seem to be the
> case here.
4 files changed, 39 insertions(+), 71 deletions(-)
> ... but I'm not exactly sure how to get there from here. Having only
> LogStartupProgress() but having it do a giant if-statement to figure
> out whether we're mid-phase or end-of-phase does not seem like the
> right approach.
I used a bool arg and negation to handle within a single switch. Maybe it's
cleaner to use a separate enum value for each DONE, and set a local done flag.
startup[29675] LOG: database system was interrupted; last known up at 2021-07-26 10:23:04 CDT
startup[29675] LOG: syncing data directory (fsync), elapsed time: 1.38 s, current path: ./pg_ident.conf
startup[29675] LOG: data directory sync (fsync) complete after 1.72 s
startup[29675] LOG: database system was not properly shut down; automatic recovery in progress
startup[29675] LOG: resetting unlogged relations (cleanup) complete after 0.00 s
startup[29675] LOG: redo starts at 0/17BE500
startup[29675] LOG: redo in progress, elapsed time: 1.00 s, current LSN: 0/35D7CB8
startup[29675] LOG: redo in progress, elapsed time: 2.00 s, current LSN: 0/54A6918
startup[29675] LOG: redo in progress, elapsed time: 3.00 s, current LSN: 0/7370570
startup[29675] LOG: redo in progress, elapsed time: 4.00 s, current LSN: 0/924D8A0
startup[29675] LOG: redo done at 0/9FFFFB8 system usage: CPU: user: 4.28 s, system: 0.15 s, elapsed: 4.44 s
startup[29675] LOG: resetting unlogged relations (init) complete after 0.03 s
startup[29675] LOG: checkpoint starting: end-of-recovery immediate
startup[29675] LOG: checkpoint complete: wrote 9872 buffers (60.3%); 0 WAL file(s) added, 0 removed, 8 recycled; write=0.136 s, sync=0.801 s, total=1.260 s; sync files=21, longest=0.774 s, average=B
Attachments:download all (2 files, .tar.gz)0001-Shows-the-progress-of-the-operations-performed-durin.patch (text/x-diff, 14.6K) download
From 9443005040be52225498d58678b5faa1668bd2ad Mon Sep 17 00:00:00 2001
From: Nitin <nitin.jadhav@enterprisedb.com>
Date: Fri, 23 Jul 2021 15:46:56 +0530
Subject: [PATCH 1/2] 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 | 178 ++++++++++++++++++
src/backend/postmaster/startup.c | 1 +
src/backend/storage/file/fd.c | 13 ++
src/backend/storage/file/reinit.c | 18 ++
src/backend/utils/misc/guc.c | 13 +-
src/backend/utils/misc/postgresql.conf.sample | 6 +
src/include/access/xlog.h | 18 ++
src/include/utils/timeout.h | 1 +
8 files changed, 247 insertions(+), 1 deletion(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.cindex 3479402272..4f052050f3 100644--- a/src/backend/access/transam/xlog.c+++ b/src/backend/access/transam/xlog.c@@ -79,6 +79,7 @@
#include "utils/relmapper.h"
#include "utils/pg_rusage.h"
#include "utils/snapmgr.h"
+#include "utils/timeout.h"
#include "utils/timestamp.h"
extern uint32 bootstrap_data_checksum_version;
@@ -397,6 +398,23 @@ static bool doRequestWalReceiverReply;
*/
static XLogRecPtr RedoStartLSN = InvalidXLogRecPtr;
+/*+ * Start timestamp of the operation that occur during startup process.+ */+static TimestampTz startupProcessOpStartTime;++/*+ * Indicates whether the startup progress interval mentioned by the user is+ * elapsed or not. TRUE if timeout occurred, FALSE otherwise.+ */+static bool logStartupProgressTimeout;++/*+ * The interval between each progress update of the operations that occur+ * during startup process.+ */+int log_startup_progress_interval;+
/*----------
* Shared-memory data structures for XLOG control
*
@@ -7351,6 +7369,8 @@ StartupXLOG(void)
(errmsg("redo starts at %X/%X",
LSN_FORMAT_ARGS(ReadRecPtr))));
+ InitStartupProgress();+
/*
* main redo apply loop
*/
@@ -7358,6 +7378,8 @@ StartupXLOG(void)
{
bool switchedTLI = false;
+ LogStartupProgress(STARTUP_PROCESS_OP_REDO, NULL);+
#ifdef WAL_DEBUG
if (XLOG_DEBUG ||
(rmid == RM_XACT_ID && trace_recovery_messages <= DEBUG2) ||
@@ -13021,3 +13043,159 @@ XLogRequestWalReceiverReply(void)
{
doRequestWalReceiverReply = true;
}
++/*+ * Schedule a wakeup call for logging the progress of startup process.+ */+void+LogStartupProgressTimeoutHandler(void)+{+ logStartupProgressTimeout = true;+}++/*+ * Sets the start timestamp of the current operation and also enables the+ * timeout for logging the progress of startup process.+ */+void+InitStartupProgress(void)+{+ /*+ * If not called from startup process then just return without+ * initialization.+ */+ if (!AmStartupProcess())+ return;++ startupProcessOpStartTime = GetCurrentTimestamp();+ enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT,+ (log_startup_progress_interval * 1000));+}++/*+ * Logs the progress of the operations performed during startup process.+ */+void+LogStartupProgress(StartupProcessOp operation, const char *path)+{+ long secs;+ int usecs;+ int elapsed_ms;+ int interval_in_ms;++ /* If not called from startup process then this feature is of no use. */+ if (!AmStartupProcess())+ return;++ /* If the feature is disabled, then no need to proceed further. */+ if (log_startup_progress_interval < 0)+ return;++ /* If the timeout has not occurred, then no need to log the details. */+ if (!logStartupProgressTimeout)+ return;++ /* Timeout has occurred. */+ TimestampDifference(startupProcessOpStartTime,+ GetCurrentTimestamp(),+ &secs, &usecs);++ /*+ * Enable the timer for the next log message based on the time that current+ * log message timer was supposed to fire.+ */+ elapsed_ms = (secs * 1000) + (usecs / 1000);+ interval_in_ms = log_startup_progress_interval * 1000;+ enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT,+ (interval_in_ms - (elapsed_ms % interval_in_ms)));++ switch(operation)+ {+ case STARTUP_PROCESS_OP_SYNCFS:+ ereport(LOG,+ (errmsg("syncing data directory (syncfs), elapsed time: %ld.%02d s, current path: %s",+ secs, (usecs / 10000), path)));+ break;+ case STARTUP_PROCESS_OP_FSYNC:+ ereport(LOG,+ (errmsg("syncing data directory (fsync), elapsed time: %ld.%02d s, current path: %s",+ secs, (usecs / 10000), path)));+ break;+ case STARTUP_PROCESS_OP_REDO:+ ereport(LOG,+ (errmsg("redo in progress, elapsed time: %ld.%02d s, current LSN: %X/%X",+ secs, (usecs / 10000), LSN_FORMAT_ARGS(ReadRecPtr))));+ break;+ case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT:+ ereport(LOG,+ (errmsg("resetting unlogged relations (init), elapsed time: %ld.%02d s, current path: %s",+ secs, (usecs / 10000), path)));+ break;+ case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP:+ ereport(LOG,+ (errmsg("resetting unlogged relations (cleanup), elapsed time: %ld.%02d s, current path: %s",+ secs, (usecs / 10000), path)));+ break;+ default:+ ereport(ERROR,+ (errmsg("unrecognized operation (%d) in startup progress update",+ operation)));+ break;+ }++ logStartupProgressTimeout = false;+}++/*+ * Logs the completion of the operation performed during startup process and+ * disables the timeout used for logging the progress.+ */+void+LogStartupProgressComplete(StartupProcessOp operation)+{+ long secs;+ int usecs;++ /* If not called from startup process then this feature is of no use. */+ if (!AmStartupProcess())+ return;++ /* If the feature is disabled, then no need to proceed further. */+ if (log_startup_progress_interval < 0)+ return;++ TimestampDifference(startupProcessOpStartTime,+ GetCurrentTimestamp(),+ &secs, &usecs);++ switch(operation)+ {+ case STARTUP_PROCESS_OP_SYNCFS:+ ereport(LOG,+ (errmsg("data directory sync (syncfs) complete after %ld.%02d s",+ secs, (usecs / 10000))));+ break;+ case STARTUP_PROCESS_OP_FSYNC:+ ereport(LOG,+ (errmsg("data directory sync (fsync) complete after %ld.%02d s",+ secs, (usecs / 10000))));+ break;+ case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT:+ ereport(LOG,+ (errmsg("resetting unlogged relations (init) complete after %ld.%02d s",+ secs, (usecs / 10000))));+ break;+ case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP:+ ereport(LOG,+ (errmsg("resetting unlogged relations (cleanup) complete after %ld.%02d s",+ secs, (usecs / 10000))));+ break;+ default:+ ereport(ERROR,+ (errmsg("unrecognized operation (%d) in startup progress update",+ operation)));+ break;+ }++ disable_timeout(LOG_STARTUP_PROGRESS_TIMEOUT, false);+}diff --git a/src/backend/postmaster/startup.c b/src/backend/postmaster/startup.cindex 69077bd207..08c271cad6 100644--- a/src/backend/postmaster/startup.c+++ b/src/backend/postmaster/startup.c@@ -232,6 +232,7 @@ StartupProcessMain(void)
RegisterTimeout(STANDBY_DEADLOCK_TIMEOUT, StandbyDeadLockHandler);
RegisterTimeout(STANDBY_TIMEOUT, StandbyTimeoutHandler);
RegisterTimeout(STANDBY_LOCK_TIMEOUT, StandbyLockTimeoutHandler);
+ RegisterTimeout(LOG_STARTUP_PROGRESS_TIMEOUT, LogStartupProgressTimeoutHandler);
/*
* Unblock signals (they were blocked when the postmaster forked us)
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.cindex 5d5e8ae94e..49ecbbd3b9 100644--- a/src/backend/storage/file/fd.c+++ b/src/backend/storage/file/fd.c@@ -100,6 +100,7 @@
#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)
@@ -3334,6 +3335,8 @@ do_syncfs(const char *path)
{
int fd;
+ LogStartupProgress(STARTUP_PROCESS_OP_SYNCFS, path);+
fd = OpenTransientFile(path, O_RDONLY);
if (fd < 0)
{
@@ -3410,6 +3413,8 @@ SyncDataDirectory(void)
DIR *dir;
struct dirent *de;
+ InitStartupProgress();+
/*
* 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
@@ -3436,6 +3441,8 @@ SyncDataDirectory(void)
/* If pg_wal is a symlink, process that too. */
if (xlog_is_symlink)
do_syncfs("pg_wal");
++ LogStartupProgressComplete(STARTUP_PROCESS_OP_SYNCFS);
return;
}
#endif /* !HAVE_SYNCFS */
@@ -3452,6 +3459,8 @@ SyncDataDirectory(void)
walkdir("pg_tblspc", pre_sync_fname, true, DEBUG1);
#endif
+ InitStartupProgress();+
/*
* Now we do the fsync()s in the same order.
*
@@ -3465,6 +3474,8 @@ SyncDataDirectory(void)
if (xlog_is_symlink)
walkdir("pg_wal", datadir_fsync_fname, false, LOG);
walkdir("pg_tblspc", datadir_fsync_fname, true, LOG);
++ LogStartupProgressComplete(STARTUP_PROCESS_OP_FSYNC);
}
/*
@@ -3505,6 +3516,8 @@ walkdir(const char *path,
snprintf(subpath, sizeof(subpath), "%s/%s", path, de->d_name);
+ LogStartupProgress(STARTUP_PROCESS_OP_FSYNC, path);+
switch (get_dirent_type(subpath, de, process_symlinks, elevel))
{
case PGFILETYPE_REG:
diff --git a/src/backend/storage/file/reinit.c b/src/backend/storage/file/reinit.cindex 40c758d789..ba18996d98 100644--- a/src/backend/storage/file/reinit.c+++ b/src/backend/storage/file/reinit.c@@ -16,12 +16,14 @@
#include <unistd.h>
+#include "access/xlog.h"
#include "common/relpath.h"
#include "storage/copydir.h"
#include "storage/fd.h"
#include "storage/reinit.h"
#include "utils/hsearch.h"
#include "utils/memutils.h"
+#include "utils/timeout.h"
static void ResetUnloggedRelationsInTablespaceDir(const char *tsdirname,
int op);
@@ -65,6 +67,8 @@ ResetUnloggedRelations(int op)
ALLOCSET_DEFAULT_SIZES);
oldctx = MemoryContextSwitchTo(tmpctx);
+ InitStartupProgress();+
/*
* First process unlogged files in pg_default ($PGDATA/base)
*/
@@ -75,6 +79,7 @@ ResetUnloggedRelations(int op)
*/
spc_dir = AllocateDir("pg_tblspc");
+
while ((spc_de = ReadDir(spc_dir, "pg_tblspc")) != NULL)
{
if (strcmp(spc_de->d_name, ".") == 0 ||
@@ -86,6 +91,11 @@ ResetUnloggedRelations(int op)
ResetUnloggedRelationsInTablespaceDir(temp_path, op);
}
+ if (op & UNLOGGED_RELATION_INIT)+ LogStartupProgressComplete(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT);+ else if (op & UNLOGGED_RELATION_CLEANUP)+ LogStartupProgressComplete(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP);+
FreeDir(spc_dir);
/*
@@ -136,6 +146,14 @@ ResetUnloggedRelationsInTablespaceDir(const char *tsdirname, int op)
snprintf(dbspace_path, sizeof(dbspace_path), "%s/%s",
tsdirname, de->d_name);
++ if (op & UNLOGGED_RELATION_INIT)+ LogStartupProgress(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT,+ dbspace_path);+ else if (op & UNLOGGED_RELATION_CLEANUP)+ LogStartupProgress(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP,+ dbspace_path);+
ResetUnloggedRelationsInDbspaceDir(dbspace_path, op);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.cindex a2e0f8de7e..d0ea7de8ff 100644--- a/src/backend/utils/misc/guc.c+++ b/src/backend/utils/misc/guc.c@@ -679,7 +679,6 @@ static char *recovery_target_lsn_string;
/* should be static, but commands/variable.c needs to get at this */
char *role_string;
-
/*
* Displayable names for context types (enum GucContext)
*
@@ -3546,6 +3545,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.sampleindex b242a7fc8b..901e4ba461 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/access/xlog.h b/src/include/access/xlog.hindex ccfcf43d62..f17d91bf9c 100644--- a/src/include/access/xlog.h+++ b/src/include/access/xlog.h@@ -132,6 +132,7 @@ extern char *PrimaryConnInfo;
extern char *PrimarySlotName;
extern bool wal_receiver_create_temp_slot;
extern bool track_wal_io_timing;
+extern int log_startup_progress_interval;
/* indirectly set via GUC system */
extern TransactionId recoveryTargetXid;
@@ -295,6 +296,18 @@ typedef enum WALAvailability
WALAVAIL_REMOVED /* WAL segment has been removed */
} WALAvailability;
+/*+ * Codes of the operations performed during startup process+ */+typedef enum StartupProcessOp+{+ STARTUP_PROCESS_OP_SYNCFS,+ STARTUP_PROCESS_OP_FSYNC,+ STARTUP_PROCESS_OP_REDO,+ STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT,+ STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP+} StartupProcessOp;+
struct XLogRecData;
extern XLogRecPtr XLogInsertRecord(struct XLogRecData *rdata,
@@ -399,6 +412,11 @@ extern void do_pg_abort_backup(int code, Datum arg);
extern void register_persistent_abort_backup_handler(void);
extern SessionBackupState get_backup_status(void);
+extern void InitStartupProgress(void);+extern void LogStartupProgress(StartupProcessOp operation, const char *path);+extern void LogStartupProgressComplete(StartupProcessOp operation);+extern void LogStartupProgressTimeoutHandler(void);+
/* File path names (all relative to $PGDATA) */
#define RECOVERY_SIGNAL_FILE "recovery.signal"
#define STANDBY_SIGNAL_FILE "standby.signal"
diff --git a/src/include/utils/timeout.h b/src/include/utils/timeout.hindex 93e6a691b3..ef892dd647 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,
+ LOG_STARTUP_PROGRESS_TIMEOUT,
/* First user-definable timeout reason */
USER_TIMEOUT,
/* Maximum number of timeout reasons */
--
2.17.0
0002-justins-changes.patch (text/x-diff, 9.4K) download
From 0119274e7a05da4e31b1f7cfeccd14b90363829d Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Mon, 26 Jul 2021 10:10:21 -0500
Subject: [PATCH 2/2] justins changes
---
src/backend/access/transam/xlog.c | 83 ++++++++++---------------------
src/backend/storage/file/fd.c | 12 ++---
src/backend/storage/file/reinit.c | 9 ++--
src/backend/utils/misc/guc.c | 1 +
src/include/access/xlog.h | 7 ++-
5 files changed, 40 insertions(+), 72 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.cindex 4f052050f3..6b6619a143 100644--- a/src/backend/access/transam/xlog.c+++ b/src/backend/access/transam/xlog.c@@ -7378,7 +7378,7 @@ StartupXLOG(void)
{
bool switchedTLI = false;
- LogStartupProgress(STARTUP_PROCESS_OP_REDO, NULL);+ LogStartupProgress(STARTUP_PROCESS_OP_REDO, NULL, false);
#ifdef WAL_DEBUG
if (XLOG_DEBUG ||
@@ -13073,15 +13073,18 @@ InitStartupProgress(void)
}
/*
- * Logs the progress of the operations performed during startup process.+ * Logs the status of operations performed during startup process.
*/
void
-LogStartupProgress(StartupProcessOp operation, const char *path)+LogStartupProgress(StartupProcessOp operation, const char *path, bool done)
{
long secs;
int usecs;
int elapsed_ms;
int interval_in_ms;
+ int swval = done ? -operation : operation;++ Assert(operation != 0);
/* If not called from startup process then this feature is of no use. */
if (!AmStartupProcess())
@@ -13092,7 +13095,7 @@ LogStartupProgress(StartupProcessOp operation, const char *path)
return;
/* If the timeout has not occurred, then no need to log the details. */
- if (!logStartupProgressTimeout)+ if (!logStartupProgressTimeout && !done)
return;
/* Timeout has occurred. */
@@ -13100,16 +13103,7 @@ LogStartupProgress(StartupProcessOp operation, const char *path)
GetCurrentTimestamp(),
&secs, &usecs);
- /*- * Enable the timer for the next log message based on the time that current- * log message timer was supposed to fire.- */- elapsed_ms = (secs * 1000) + (usecs / 1000);- interval_in_ms = log_startup_progress_interval * 1000;- enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT,- (interval_in_ms - (elapsed_ms % interval_in_ms)));-- switch(operation)+ switch (swval)
{
case STARTUP_PROCESS_OP_SYNCFS:
ereport(LOG,
@@ -13136,66 +13130,41 @@ LogStartupProgress(StartupProcessOp operation, const char *path)
(errmsg("resetting unlogged relations (cleanup), elapsed time: %ld.%02d s, current path: %s",
secs, (usecs / 10000), path)));
break;
- default:- ereport(ERROR,- (errmsg("unrecognized operation (%d) in startup progress update",- operation)));- break;- }-- logStartupProgressTimeout = false;-}--/*- * Logs the completion of the operation performed during startup process and- * disables the timeout used for logging the progress.- */-void-LogStartupProgressComplete(StartupProcessOp operation)-{- long secs;- int usecs;-- /* If not called from startup process then this feature is of no use. */- if (!AmStartupProcess())- return;- /* If the feature is disabled, then no need to proceed further. */- if (log_startup_progress_interval < 0)- return;-- TimestampDifference(startupProcessOpStartTime,- GetCurrentTimestamp(),- &secs, &usecs);-- switch(operation)- {- case STARTUP_PROCESS_OP_SYNCFS:+ case -STARTUP_PROCESS_OP_SYNCFS:
ereport(LOG,
(errmsg("data directory sync (syncfs) complete after %ld.%02d s",
secs, (usecs / 10000))));
break;
- case STARTUP_PROCESS_OP_FSYNC:+ case -STARTUP_PROCESS_OP_FSYNC:
ereport(LOG,
(errmsg("data directory sync (fsync) complete after %ld.%02d s",
secs, (usecs / 10000))));
break;
- case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT:+ case -STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT:
ereport(LOG,
(errmsg("resetting unlogged relations (init) complete after %ld.%02d s",
secs, (usecs / 10000))));
break;
- case STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP:+ case -STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP:
ereport(LOG,
(errmsg("resetting unlogged relations (cleanup) complete after %ld.%02d s",
secs, (usecs / 10000))));
break;
- default:- ereport(ERROR,- (errmsg("unrecognized operation (%d) in startup progress update",- operation)));- break;
}
- disable_timeout(LOG_STARTUP_PROGRESS_TIMEOUT, false);+ if (!done)+ {+ /*+ * Enable the timer for the next log message based on the time that+ * the current log message timer was supposed to fire.+ */+ logStartupProgressTimeout = false;+ elapsed_ms = (secs * 1000) + (usecs / 1000);+ interval_in_ms = log_startup_progress_interval * 1000;+ enable_timeout_after(LOG_STARTUP_PROGRESS_TIMEOUT,+ (interval_in_ms - (elapsed_ms % interval_in_ms)));+ }+ else+ disable_timeout(LOG_STARTUP_PROGRESS_TIMEOUT, false);
}
diff --git a/src/backend/storage/file/fd.c b/src/backend/storage/file/fd.cindex 49ecbbd3b9..65e7de200e 100644--- a/src/backend/storage/file/fd.c+++ b/src/backend/storage/file/fd.c@@ -3335,7 +3335,7 @@ do_syncfs(const char *path)
{
int fd;
- LogStartupProgress(STARTUP_PROCESS_OP_SYNCFS, path);+ LogStartupProgress(STARTUP_PROCESS_OP_SYNCFS, path, false);
fd = OpenTransientFile(path, O_RDONLY);
if (fd < 0)
@@ -3442,7 +3442,7 @@ SyncDataDirectory(void)
if (xlog_is_symlink)
do_syncfs("pg_wal");
- LogStartupProgressComplete(STARTUP_PROCESS_OP_SYNCFS);+ LogStartupProgress(STARTUP_PROCESS_OP_SYNCFS, NULL, true);
return;
}
#endif /* !HAVE_SYNCFS */
@@ -3475,7 +3475,7 @@ SyncDataDirectory(void)
walkdir("pg_wal", datadir_fsync_fname, false, LOG);
walkdir("pg_tblspc", datadir_fsync_fname, true, LOG);
- LogStartupProgressComplete(STARTUP_PROCESS_OP_FSYNC);+ LogStartupProgress(STARTUP_PROCESS_OP_FSYNC, NULL, true);
}
/*
@@ -3516,8 +3516,6 @@ walkdir(const char *path,
snprintf(subpath, sizeof(subpath), "%s/%s", path, de->d_name);
- LogStartupProgress(STARTUP_PROCESS_OP_FSYNC, path);-
switch (get_dirent_type(subpath, de, process_symlinks, elevel))
{
case PGFILETYPE_REG:
@@ -3596,8 +3594,10 @@ pre_sync_fname(const char *fname, bool isdir, int elevel)
static void
datadir_fsync_fname(const char *fname, bool isdir, int elevel)
{
+ LogStartupProgress(STARTUP_PROCESS_OP_FSYNC, fname, false);+
/*
- * We want to silently ignoring errors about unreadable files. Pass that+ * We want to silently ignore errors about unreadable files. Pass that
* desire on to fsync_fname_ext().
*/
fsync_fname_ext(fname, isdir, true, elevel);
diff --git a/src/backend/storage/file/reinit.c b/src/backend/storage/file/reinit.cindex ba18996d98..21a414d434 100644--- a/src/backend/storage/file/reinit.c+++ b/src/backend/storage/file/reinit.c@@ -79,7 +79,6 @@ ResetUnloggedRelations(int op)
*/
spc_dir = AllocateDir("pg_tblspc");
-
while ((spc_de = ReadDir(spc_dir, "pg_tblspc")) != NULL)
{
if (strcmp(spc_de->d_name, ".") == 0 ||
@@ -92,9 +91,9 @@ ResetUnloggedRelations(int op)
}
if (op & UNLOGGED_RELATION_INIT)
- LogStartupProgressComplete(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT);+ LogStartupProgress(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT, NULL, true);
else if (op & UNLOGGED_RELATION_CLEANUP)
- LogStartupProgressComplete(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP);+ LogStartupProgress(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP, NULL, true);
FreeDir(spc_dir);
@@ -149,10 +148,10 @@ ResetUnloggedRelationsInTablespaceDir(const char *tsdirname, int op)
if (op & UNLOGGED_RELATION_INIT)
LogStartupProgress(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT,
- dbspace_path);+ dbspace_path, false);
else if (op & UNLOGGED_RELATION_CLEANUP)
LogStartupProgress(STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP,
- dbspace_path);+ dbspace_path, false);
ResetUnloggedRelationsInDbspaceDir(dbspace_path, op);
}
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.cindex d0ea7de8ff..82bbc880d8 100644--- a/src/backend/utils/misc/guc.c+++ b/src/backend/utils/misc/guc.c@@ -679,6 +679,7 @@ static char *recovery_target_lsn_string;
/* should be static, but commands/variable.c needs to get at this */
char *role_string;
+
/*
* Displayable names for context types (enum GucContext)
*
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.hindex f17d91bf9c..22ede3baa9 100644--- a/src/include/access/xlog.h+++ b/src/include/access/xlog.h@@ -301,11 +301,11 @@ typedef enum WALAvailability
*/
typedef enum StartupProcessOp
{
- STARTUP_PROCESS_OP_SYNCFS,+ STARTUP_PROCESS_OP_SYNCFS = 1,
STARTUP_PROCESS_OP_FSYNC,
STARTUP_PROCESS_OP_REDO,
STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_INIT,
- STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP+ STARTUP_PROCESS_OP_RESET_UNLOGGED_REL_CLEANUP,
} StartupProcessOp;
struct XLogRecData;
@@ -413,8 +413,7 @@ extern void register_persistent_abort_backup_handler(void);
extern SessionBackupState get_backup_status(void);
extern void InitStartupProgress(void);
-extern void LogStartupProgress(StartupProcessOp operation, const char *path);-extern void LogStartupProgressComplete(StartupProcessOp operation);+extern void LogStartupProgress(StartupProcessOp operation, const char *path, bool done);
extern void LogStartupProgressTimeoutHandler(void);
/* File path names (all relative to $PGDATA) */
--
2.17.0
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: pryzby@telsasoft.com, robertmhaas@gmail.com, nitinjadhavpostgres@gmail.com, bharath.rupireddyforpostgres@gmail.com, tgl@sss.pgh.pa.us, andres@anarazel.de, sfrost@snowman.net, magnus@hagander.net, thomas.munro@gmail.com
Subject: Re: when the startup process doesn't (logging startup delays)
In-Reply-To: <20210726153023.GC23997@telsasoft.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox