public inbox for [email protected]help / color / mirror / Atom feed
[PATCH v52 3/7] Make archiver process an auxiliary process 5+ messages / 3 participants [nested] [flat]
* [PATCH v52 3/7] Make archiver process an auxiliary process @ 2020-03-13 07:59 Kyotaro Horiguchi <[email protected]> 0 siblings, 0 replies; 5+ messages in thread From: Kyotaro Horiguchi @ 2020-03-13 07:59 UTC (permalink / raw) This is a preliminary patch for shared-memory based stats collector. Archiver process must be a auxiliary process since it uses shared memory after stats data was moved into shared-memory. Make the process an auxiliary process in order to make it work. --- src/backend/access/transam/xlogarchive.c | 6 +- src/backend/bootstrap/bootstrap.c | 22 ++- src/backend/postmaster/pgarch.c | 224 ++++++++--------------- src/backend/postmaster/postmaster.c | 83 ++++----- src/backend/storage/ipc/ipci.c | 2 + src/include/miscadmin.h | 2 + src/include/postmaster/pgarch.h | 13 +- src/include/storage/pmsignal.h | 1 - src/include/storage/proc.h | 8 +- 9 files changed, 139 insertions(+), 222 deletions(-) diff --git a/src/backend/access/transam/xlogarchive.c b/src/backend/access/transam/xlogarchive.c index 1c5a4f8b5a..2558bcfb08 100644 --- a/src/backend/access/transam/xlogarchive.c +++ b/src/backend/access/transam/xlogarchive.c @@ -25,11 +25,13 @@ #include "common/archive.h" #include "miscadmin.h" #include "postmaster/startup.h" +#include "postmaster/pgarch.h" #include "replication/walsender.h" #include "storage/fd.h" #include "storage/ipc.h" #include "storage/lwlock.h" -#include "storage/pmsignal.h" +#include "storage/latch.h" +#include "storage/proc.h" /* * Attempt to retrieve the specified file from off-line archival storage. @@ -491,7 +493,7 @@ XLogArchiveNotify(const char *xlog) /* Notify archiver that it's got something to do */ if (IsUnderPostmaster) - SendPostmasterSignal(PMSIGNAL_WAKEN_ARCHIVER); + PgArchWakeup(); } /* diff --git a/src/backend/bootstrap/bootstrap.c b/src/backend/bootstrap/bootstrap.c index 6f615e6622..41da0c5059 100644 --- a/src/backend/bootstrap/bootstrap.c +++ b/src/backend/bootstrap/bootstrap.c @@ -317,6 +317,9 @@ AuxiliaryProcessMain(int argc, char *argv[]) case StartupProcess: MyBackendType = B_STARTUP; break; + case ArchiverProcess: + MyBackendType = B_ARCHIVER; + break; case BgWriterProcess: MyBackendType = B_BG_WRITER; break; @@ -437,30 +440,29 @@ AuxiliaryProcessMain(int argc, char *argv[]) proc_exit(1); /* should never return */ case StartupProcess: - /* don't set signals, startup process has its own agenda */ StartupProcessMain(); - proc_exit(1); /* should never return */ + proc_exit(1); + + case ArchiverProcess: + PgArchiverMain(); + proc_exit(1); case BgWriterProcess: - /* don't set signals, bgwriter has its own agenda */ BackgroundWriterMain(); - proc_exit(1); /* should never return */ + proc_exit(1); case CheckpointerProcess: - /* don't set signals, checkpointer has its own agenda */ CheckpointerMain(); - proc_exit(1); /* should never return */ + proc_exit(1); case WalWriterProcess: - /* don't set signals, walwriter has its own agenda */ InitXLOGAccess(); WalWriterMain(); - proc_exit(1); /* should never return */ + proc_exit(1); case WalReceiverProcess: - /* don't set signals, walreceiver has its own agenda */ WalReceiverMain(); - proc_exit(1); /* should never return */ + proc_exit(1); default: elog(PANIC, "unrecognized process type: %d", (int) MyAuxProcType); diff --git a/src/backend/postmaster/pgarch.c b/src/backend/postmaster/pgarch.c index edec311f12..c399e6c267 100644 --- a/src/backend/postmaster/pgarch.c +++ b/src/backend/postmaster/pgarch.c @@ -38,16 +38,14 @@ #include "libpq/pqsignal.h" #include "miscadmin.h" #include "pgstat.h" -#include "postmaster/fork_process.h" #include "postmaster/interrupt.h" #include "postmaster/pgarch.h" -#include "postmaster/postmaster.h" -#include "storage/dsm.h" #include "storage/fd.h" #include "storage/ipc.h" #include "storage/latch.h" -#include "storage/pg_shmem.h" #include "storage/pmsignal.h" +#include "storage/procsignal.h" +#include "storage/spin.h" #include "utils/guc.h" #include "utils/ps_status.h" @@ -73,153 +71,68 @@ */ #define NUM_ORPHAN_CLEANUP_RETRIES 3 +/* Shared memory area for archiver process */ +typedef struct PgArchData +{ + Latch *latch; /* latch to wake the archiver up */ + slock_t mutex; /* locks this struct */ +} PgArchData; + /* ---------- * Local data * ---------- */ -static time_t last_pgarch_start_time; static time_t last_sigterm_time = 0; +PgArchData *PgArch = NULL; /* * Flags set by interrupt handlers for later service in the main loop. */ -static volatile sig_atomic_t wakened = false; static volatile sig_atomic_t ready_to_stop = false; /* ---------- * Local function forward declarations * ---------- */ -#ifdef EXEC_BACKEND -static pid_t pgarch_forkexec(void); -#endif - -NON_EXEC_STATIC void PgArchiverMain(int argc, char *argv[]) pg_attribute_noreturn(); -static void pgarch_waken(SIGNAL_ARGS); static void pgarch_waken_stop(SIGNAL_ARGS); static void pgarch_MainLoop(void); static void pgarch_ArchiverCopyLoop(void); static bool pgarch_archiveXlog(char *xlog); static bool pgarch_readyXlog(char *xlog); static void pgarch_archiveDone(char *xlog); +static void pgarch_die(int code, Datum arg); +/* Report shared memory space needed by PgArchShmemInit */ +Size +PgArchShmemSize(void) +{ + Size size = 0; -/* ------------------------------------------------------------ - * Public functions called from postmaster follow - * ------------------------------------------------------------ - */ + size = add_size(size, sizeof(PgArchData)); -/* - * pgarch_start - * - * Called from postmaster at startup or after an existing archiver - * died. Attempt to fire up a fresh archiver process. - * - * Returns PID of child process, or 0 if fail. - * - * Note: if fail, we will be called again from the postmaster main loop. - */ -int -pgarch_start(void) -{ - time_t curtime; - pid_t pgArchPid; + return size; +} - /* - * Do nothing if no archiver needed - */ - if (!XLogArchivingActive()) - return 0; +/* Allocate and initialize archiver-related shared memory */ +void +PgArchShmemInit(void) +{ + bool found; - /* - * Do nothing if too soon since last archiver start. This is a safety - * valve to protect against continuous respawn attempts if the archiver is - * dying immediately at launch. Note that since we will be re-called from - * the postmaster main loop, we will get another chance later. - */ - curtime = time(NULL); - if ((unsigned int) (curtime - last_pgarch_start_time) < - (unsigned int) PGARCH_RESTART_INTERVAL) - return 0; - last_pgarch_start_time = curtime; + PgArch = (PgArchData *) + ShmemInitStruct("Archiver ", PgArchShmemSize(), &found); -#ifdef EXEC_BACKEND - switch ((pgArchPid = pgarch_forkexec())) -#else - switch ((pgArchPid = fork_process())) -#endif + if (!found) { - case -1: - ereport(LOG, - (errmsg("could not fork archiver: %m"))); - return 0; - -#ifndef EXEC_BACKEND - case 0: - /* in postmaster child ... */ - InitPostmasterChild(); - - /* Close the postmaster's sockets */ - ClosePostmasterPorts(false); - - /* Drop our connection to postmaster's shared memory, as well */ - dsm_detach_all(); - PGSharedMemoryDetach(); - - PgArchiverMain(0, NULL); - break; -#endif - - default: - return (int) pgArchPid; + SpinLockInit(&PgArch->mutex); + PgArch->latch = NULL; } - - /* shouldn't get here */ - return 0; -} - -/* ------------------------------------------------------------ - * Local functions called by archiver follow - * ------------------------------------------------------------ - */ - - -#ifdef EXEC_BACKEND - -/* - * pgarch_forkexec() - - * - * Format up the arglist for, then fork and exec, archive process - */ -static pid_t -pgarch_forkexec(void) -{ - char *av[10]; - int ac = 0; - - av[ac++] = "postgres"; - - av[ac++] = "--forkarch"; - - av[ac++] = NULL; /* filled in by postmaster_forkexec */ - - av[ac] = NULL; - Assert(ac < lengthof(av)); - - return postmaster_forkexec(ac, av); } -#endif /* EXEC_BACKEND */ - -/* - * PgArchiverMain - * - * The argc/argv parameters are valid only in EXEC_BACKEND case. However, - * since we don't use 'em, it hardly matters... - */ -NON_EXEC_STATIC void -PgArchiverMain(int argc, char *argv[]) +/* Main entry point for archiver process */ +void +PgArchiverMain(void) { /* * Ignore all signals usually bound to some action in the postmaster, @@ -231,33 +144,48 @@ PgArchiverMain(int argc, char *argv[]) /* SIGQUIT handler was already set up by InitPostmasterChild */ pqsignal(SIGALRM, SIG_IGN); pqsignal(SIGPIPE, SIG_IGN); - pqsignal(SIGUSR1, pgarch_waken); + pqsignal(SIGUSR1, procsignal_sigusr1_handler); pqsignal(SIGUSR2, pgarch_waken_stop); + /* Reset some signals that are accepted by postmaster but not here */ pqsignal(SIGCHLD, SIG_DFL); + + /* Unblock signals (they were blocked when the postmaster forked us) */ PG_SETMASK(&UnBlockSig); - MyBackendType = B_ARCHIVER; - init_ps_display(NULL); + /* Arrange to clean up at archiver exit */ + on_shmem_exit(pgarch_die, 0); + + /* + * Advertise our latch that backends can use to wake us up while we're + * sleeping. + */ + SpinLockAcquire(&PgArch->mutex); + PgArch->latch = MyLatch; + SpinLockRelease(&PgArch->mutex); pgarch_MainLoop(); - exit(0); + proc_exit(0); } -/* SIGUSR1 signal handler for archiver process */ -static void -pgarch_waken(SIGNAL_ARGS) +/* + * Wake up the archiver + */ +void +PgArchWakeup(void) { - int save_errno = errno; + Latch *latch; - /* set flag that there is work to be done */ - wakened = true; - SetLatch(MyLatch); + SpinLockAcquire(&PgArch->mutex); + latch = PgArch->latch; + SpinLockRelease(&PgArch->mutex); - errno = save_errno; + if (latch) + SetLatch(latch); } + /* SIGUSR2 signal handler for archiver process */ static void pgarch_waken_stop(SIGNAL_ARGS) @@ -282,14 +210,6 @@ pgarch_MainLoop(void) pg_time_t last_copy_time = 0; bool time_to_stop; - /* - * We run the copy loop immediately upon entry, in case there are - * unarchived files left over from a previous database run (or maybe the - * archiver died unexpectedly). After that we wait for a signal or - * timeout before doing more. - */ - wakened = true; - /* * There shouldn't be anything for the archiver to do except to wait for a * signal ... however, the archiver exists to protect our data, so she @@ -328,12 +248,8 @@ pgarch_MainLoop(void) } /* Do what we're here for */ - if (wakened || time_to_stop) - { - wakened = false; - pgarch_ArchiverCopyLoop(); - last_copy_time = time(NULL); - } + pgarch_ArchiverCopyLoop(); + last_copy_time = time(NULL); /* * Sleep until a signal is received, or until a poll is forced by @@ -354,13 +270,9 @@ pgarch_MainLoop(void) WL_LATCH_SET | WL_TIMEOUT | WL_POSTMASTER_DEATH, timeout * 1000L, WAIT_EVENT_ARCHIVER_MAIN); - if (rc & WL_TIMEOUT) - wakened = true; if (rc & WL_POSTMASTER_DEATH) time_to_stop = true; } - else - wakened = true; } /* @@ -744,3 +656,17 @@ pgarch_archiveDone(char *xlog) StatusFilePath(rlogdone, xlog, ".done"); (void) durable_rename(rlogready, rlogdone, WARNING); } + + +/* + * pgarch_die + * + * exit-time cleanup handler + */ +static void +pgarch_die(int code, Datum arg) +{ + SpinLockAcquire(&PgArch->mutex); + PgArch->latch = NULL; + SpinLockRelease(&PgArch->mutex); +} diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index edab95a19e..34c8551288 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -548,6 +548,7 @@ static void ShmemBackendArrayRemove(Backend *bn); #endif /* EXEC_BACKEND */ #define StartupDataBase() StartChildProcess(StartupProcess) +#define StartArchiver() StartChildProcess(ArchiverProcess) #define StartBackgroundWriter() StartChildProcess(BgWriterProcess) #define StartCheckpointer() StartChildProcess(CheckpointerProcess) #define StartWalWriter() StartChildProcess(WalWriterProcess) @@ -1792,7 +1793,7 @@ ServerLoop(void) /* If we have lost the archiver, try to start a new one. */ if (PgArchPID == 0 && PgArchStartupAllowed()) - PgArchPID = pgarch_start(); + PgArchPID = StartArchiver(); /* If we need to signal the autovacuum launcher, do so now */ if (avlauncher_needs_signal) @@ -3007,7 +3008,7 @@ reaper(SIGNAL_ARGS) if (!IsBinaryUpgrade && AutoVacuumingActive() && AutoVacPID == 0) AutoVacPID = StartAutoVacLauncher(); if (PgArchStartupAllowed() && PgArchPID == 0) - PgArchPID = pgarch_start(); + PgArchPID = StartArchiver(); if (PgStatPID == 0) PgStatPID = pgstat_start(); @@ -3141,24 +3142,6 @@ reaper(SIGNAL_ARGS) continue; } - /* - * Was it the archiver? If so, just try to start a new one; no need - * to force reset of the rest of the system. (If fail, we'll try - * again in future cycles of the main loop.). Unless we were waiting - * for it to shut down; don't restart it in that case, and - * PostmasterStateMachine() will advance to the next shutdown step. - */ - if (pid == PgArchPID) - { - PgArchPID = 0; - if (!EXIT_STATUS_0(exitstatus)) - LogChildExit(LOG, _("archiver process"), - pid, exitstatus); - if (PgArchStartupAllowed()) - PgArchPID = pgarch_start(); - continue; - } - /* * Was it the statistics collector? If so, just try to start a new * one; no need to force reset of the rest of the system. (If fail, @@ -3175,6 +3158,26 @@ reaper(SIGNAL_ARGS) continue; } + /* + * Was it the archiver? If exit status is zero (normal) or one (FATAL + * exit), we assume everything is all right just like normal backends + * and just try to restart a new one so that we immediately retry + * archiving remaining files. (If fail, we'll try again in future + * cycles of the postmaster's main loop.) Unless we were waiting for it + * to shut down; don't restart it in that case, and + * PostmasterStateMachine() will advance to the next shutdown step. + */ + if (pid == PgArchPID) + { + PgArchPID = 0; + if (!EXIT_STATUS_0(exitstatus) && !EXIT_STATUS_1(exitstatus)) + HandleChildCrash(pid, exitstatus, + _("archiver process")); + if (PgArchStartupAllowed()) + PgArchPID = StartArchiver(); + continue; + } + /* Was it the system logger? If so, try to start a new one */ if (pid == SysLoggerPID) { @@ -3403,7 +3406,7 @@ CleanupBackend(int pid, /* * HandleChildCrash -- cleanup after failed backend, bgwriter, checkpointer, - * walwriter, autovacuum, or background worker. + * walwriter, autovacuum, archiver or background worker. * * The objectives here are to clean up our local state about the child * process, and to signal all other remaining children to quickdie. @@ -3609,19 +3612,16 @@ HandleChildCrash(int pid, int exitstatus, const char *procname) signal_child(AutoVacPID, (SendStop ? SIGSTOP : SIGQUIT)); } - /* - * Force a power-cycle of the pgarch process too. (This isn't absolutely - * necessary, but it seems like a good idea for robustness, and it - * simplifies the state-machine logic in the case where a shutdown request - * arrives during crash processing.) - */ - if (PgArchPID != 0 && take_action) + /* Take care of the archiver too */ + if (pid == PgArchPID) + PgArchPID = 0; + else if (PgArchPID != 0 && take_action) { ereport(DEBUG2, (errmsg_internal("sending %s to process %d", - "SIGQUIT", + (SendStop ? "SIGSTOP" : "SIGQUIT"), (int) PgArchPID))); - signal_child(PgArchPID, SIGQUIT); + signal_child(PgArchPID, (SendStop ? SIGSTOP : SIGQUIT)); } /* @@ -3912,6 +3912,7 @@ PostmasterStateMachine(void) Assert(CheckpointerPID == 0); Assert(WalWriterPID == 0); Assert(AutoVacPID == 0); + Assert(PgArchPID == 0); /* syslogger is not considered here */ pmState = PM_NO_CHILDREN; } @@ -5037,12 +5038,6 @@ SubPostmasterMain(int argc, char *argv[]) StartBackgroundWorker(); } - if (strcmp(argv[1], "--forkarch") == 0) - { - /* Do not want to attach to shared memory */ - - PgArchiverMain(argc, argv); /* does not return */ - } if (strcmp(argv[1], "--forkcol") == 0) { /* Do not want to attach to shared memory */ @@ -5140,7 +5135,7 @@ sigusr1_handler(SIGNAL_ARGS) */ Assert(PgArchPID == 0); if (XLogArchivingAlways()) - PgArchPID = pgarch_start(); + PgArchPID = StartArchiver(); /* * If we aren't planning to enter hot standby mode later, treat @@ -5194,16 +5189,6 @@ sigusr1_handler(SIGNAL_ARGS) if (StartWorkerNeeded || HaveCrashedWorker) maybe_start_bgworkers(); - if (CheckPostmasterSignal(PMSIGNAL_WAKEN_ARCHIVER) && - PgArchPID != 0) - { - /* - * Send SIGUSR1 to archiver process, to wake it up and begin archiving - * next WAL file. - */ - signal_child(PgArchPID, SIGUSR1); - } - /* Tell syslogger to rotate logfile if requested */ if (SysLoggerPID != 0) { @@ -5445,6 +5430,10 @@ StartChildProcess(AuxProcType type) ereport(LOG, (errmsg("could not fork startup process: %m"))); break; + case ArchiverProcess: + ereport(LOG, + (errmsg("could not fork archiver process: %m"))); + break; case BgWriterProcess: ereport(LOG, (errmsg("could not fork background writer process: %m"))); diff --git a/src/backend/storage/ipc/ipci.c b/src/backend/storage/ipc/ipci.c index f9bbe97b50..3e4ec53a97 100644 --- a/src/backend/storage/ipc/ipci.c +++ b/src/backend/storage/ipc/ipci.c @@ -144,6 +144,7 @@ CreateSharedMemoryAndSemaphores(void) size = add_size(size, ReplicationOriginShmemSize()); size = add_size(size, WalSndShmemSize()); size = add_size(size, WalRcvShmemSize()); + size = add_size(size, PgArchShmemSize()); size = add_size(size, ApplyLauncherShmemSize()); size = add_size(size, SnapMgrShmemSize()); size = add_size(size, BTreeShmemSize()); @@ -258,6 +259,7 @@ CreateSharedMemoryAndSemaphores(void) ReplicationOriginShmemInit(); WalSndShmemInit(); WalRcvShmemInit(); + PgArchShmemInit(); ApplyLauncherShmemInit(); /* diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index 1bdc97e308..adb9f819bb 100644 --- a/src/include/miscadmin.h +++ b/src/include/miscadmin.h @@ -419,6 +419,7 @@ typedef enum BootstrapProcess, StartupProcess, BgWriterProcess, + ArchiverProcess, CheckpointerProcess, WalWriterProcess, WalReceiverProcess, @@ -431,6 +432,7 @@ extern AuxProcType MyAuxProcType; #define AmBootstrapProcess() (MyAuxProcType == BootstrapProcess) #define AmStartupProcess() (MyAuxProcType == StartupProcess) #define AmBackgroundWriterProcess() (MyAuxProcType == BgWriterProcess) +#define AmArchiverProcess() (MyAuxProcType == ArchiverProcess) #define AmCheckpointerProcess() (MyAuxProcType == CheckpointerProcess) #define AmWalWriterProcess() (MyAuxProcType == WalWriterProcess) #define AmWalReceiverProcess() (MyAuxProcType == WalReceiverProcess) diff --git a/src/include/postmaster/pgarch.h b/src/include/postmaster/pgarch.h index d102a21ab7..d053bf1564 100644 --- a/src/include/postmaster/pgarch.h +++ b/src/include/postmaster/pgarch.h @@ -26,14 +26,9 @@ #define MAX_XFN_CHARS 40 #define VALID_XFN_CHARS "0123456789ABCDEF.history.backup.partial" -/* ---------- - * Functions called from postmaster - * ---------- - */ -extern int pgarch_start(void); - -#ifdef EXEC_BACKEND -extern void PgArchiverMain(int argc, char *argv[]) pg_attribute_noreturn(); -#endif +extern Size PgArchShmemSize(void); +extern void PgArchShmemInit(void); +extern void PgArchiverMain(void) pg_attribute_noreturn(); +extern void PgArchWakeup(void); #endif /* _PGARCH_H */ diff --git a/src/include/storage/pmsignal.h b/src/include/storage/pmsignal.h index dbbed18f61..8ed4d87ae6 100644 --- a/src/include/storage/pmsignal.h +++ b/src/include/storage/pmsignal.h @@ -34,7 +34,6 @@ typedef enum { PMSIGNAL_RECOVERY_STARTED, /* recovery has started */ PMSIGNAL_BEGIN_HOT_STANDBY, /* begin Hot Standby */ - PMSIGNAL_WAKEN_ARCHIVER, /* send a NOTIFY signal to xlog archiver */ PMSIGNAL_ROTATE_LOGFILE, /* send SIGUSR1 to syslogger to rotate logfile */ PMSIGNAL_START_AUTOVAC_LAUNCHER, /* start an autovacuum launcher */ PMSIGNAL_START_AUTOVAC_WORKER, /* start an autovacuum worker */ diff --git a/src/include/storage/proc.h b/src/include/storage/proc.h index a777cb64a1..2fd1ff09a7 100644 --- a/src/include/storage/proc.h +++ b/src/include/storage/proc.h @@ -370,11 +370,11 @@ extern PGPROC *PreparedXactProcs; * We set aside some extra PGPROC structures for auxiliary processes, * ie things that aren't full-fledged backends but need shmem access. * - * Background writer, checkpointer and WAL writer run during normal operation. - * Startup process and WAL receiver also consume 2 slots, but WAL writer is - * launched only after startup has exited, so we only need 4 slots. + * Background writer, checkpointer, WAL writer and archiver run during normal + * operation. Startup process and WAL receiver also consume 2 slots, but WAL + * writer is launched only after startup has exited, so we only need 5 slots. */ -#define NUM_AUXILIARY_PROCS 4 +#define NUM_AUXILIARY_PROCS 5 /* configurable options */ extern PGDLLIMPORT int DeadlockTimeout; -- 2.27.0 ----Next_Part(Wed_Mar_10_17_51_37_2021_192)-- Content-Type: Text/X-Patch; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="v52-0004-Shared-memory-based-stats-collector.patch" ^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Make mesage at end-of-recovery less scary. @ 2022-02-15 14:47 Ashutosh Sharma <[email protected]> 0 siblings, 1 reply; 5+ messages in thread From: Ashutosh Sharma @ 2022-02-15 14:47 UTC (permalink / raw) To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; Michael Paquier <[email protected]>; Bossart, Nathan <[email protected]>; David Steele <[email protected]>; Peter Eisentraut <[email protected]>; Andres Freund <[email protected]>; PostgreSQL Hackers <[email protected]>; [email protected]; Robert Haas <[email protected]> On Tue, Feb 15, 2022 at 7:52 AM Kyotaro Horiguchi <[email protected]> wrote: > > At Mon, 14 Feb 2022 20:14:11 +0530, Ashutosh Sharma <[email protected]> wrote in > > No, I haven't tried to compare archive recovery to PITR or vice versa, > > instead I was trying to compare crash recovery with PITR. The message > > you're emitting says just before entering into the archive recovery is > > - "reached end-of-WAL on ... in pg_wal *during crash recovery*, > > entering archive recovery". This message is static and can be emitted > > not only during crash recovery, but also during PITR. I think we can > > No. It is emitted *only* after crash recovery before starting archive > recovery. Another message this patch adds can be emitted after PITR > or archive recovery. > > > not only during crash recovery, but also during PITR. I think we can > > remove the "during crash recovery" part from this message, so "reached > > the end of WAL at %X/%X on timeline %u in %s, entering archive > > What makes you think it can be emitted after other than crash recovery? > (Please look at the code comment just above.) > Yep that's right. We won't be coming here in case of pitr. > > recovery". Also I don't think we need format specifier %s here, it can > > be hard-coded with pg_wal as in this case we can only enter archive > > recovery after reading wal from pg_wal, so current WAL source has to > > be pg_wal, isn't it? > > You're right that it can't be other than pg_wal. It was changed just > in accordance woth another message this patch adds and it would be a > matter of taste. I replaced to "pg_wal" in this version. > OK. I have verified the changes. > > Thanks for the changes. Please note that I am not able to apply the > > latest patch on HEAD. Could you please rebase it on HEAD and share the > > new version. Thank you. > > A change on TAP script hit this. The v13 attached is: > OK. The v13 patch looks good. I have marked it as ready to commit. Thank you for working on all my review comments. -- With Regards, Ashutosh Sharma. ^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Make mesage at end-of-recovery less scary. @ 2022-02-17 07:50 Kyotaro Horiguchi <[email protected]> parent: Ashutosh Sharma <[email protected]> 0 siblings, 1 reply; 5+ messages in thread From: Kyotaro Horiguchi @ 2022-02-17 07:50 UTC (permalink / raw) To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected] At Tue, 15 Feb 2022 20:17:20 +0530, Ashutosh Sharma <[email protected]> wrote in > OK. The v13 patch looks good. I have marked it as ready to commit. > Thank you for working on all my review comments. Thaks! But the recent xlog.c refactoring crashes into this patch. And I found a silly bug while rebasing. xlog.c:12463 / xlogrecovery.c:3168 if (!WaitForWALToBecomeAvailable(targetPagePtr + reqLen, .. { + Assert(!StandbyMode); ... + xlogreader->EndOfWAL = true; Yeah, I forgot about promotion there.. So what I should have done is setting EndOfWAL according to StandbyMode. + Assert(!StandbyMode || CheckForStandbyTrigger()); ... + /* promotion exit is not end-of-WAL */ + xlogreader->EndOfWAL = !StandbyMode; The rebased v14 is attached. regards. -- Kyotaro Horiguchi NTT Open Source Software Center Attachments: [text/x-patch] v14-0001-Make-End-Of-Recovery-error-less-scary.patch (16.2K, ../../[email protected]/2-v14-0001-Make-End-Of-Recovery-error-less-scary.patch) download | inline diff: From 5613ee80a4d2a9786f5ce8421dcbb560b63a13c1 Mon Sep 17 00:00:00 2001 From: Kyotaro Horiguchi <[email protected]> Date: Fri, 28 Feb 2020 15:52:58 +0900 Subject: [PATCH v14] Make End-Of-Recovery error less scary When recovery in any type ends, we see a bit scary error message like "invalid record length" that suggests something serious is happening. Actually if recovery meets a record with length = 0, that usually means it finished applying all available WAL records. Make this message less scary as "reached end of WAL". Instead, raise the error level for other kind of WAL failure to WARNING. --- src/backend/access/transam/xlogreader.c | 78 ++++++++++++++++ src/backend/access/transam/xlogrecovery.c | 92 ++++++++++++++----- src/backend/replication/walreceiver.c | 7 +- src/bin/pg_waldump/pg_waldump.c | 13 ++- src/include/access/xlogreader.h | 1 + src/test/recovery/t/011_crash_recovery.pl | 106 ++++++++++++++++++++++ 6 files changed, 268 insertions(+), 29 deletions(-) diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c index 35029cf97d..22982c4de7 100644 --- a/src/backend/access/transam/xlogreader.c +++ b/src/backend/access/transam/xlogreader.c @@ -121,6 +121,7 @@ XLogReaderAllocate(int wal_segment_size, const char *waldir, pfree(state); return NULL; } + state->EndOfWAL = false; state->errormsg_buf[0] = '\0'; /* @@ -292,6 +293,7 @@ XLogReadRecord(XLogReaderState *state, char **errormsg) /* reset error state */ *errormsg = NULL; state->errormsg_buf[0] = '\0'; + state->EndOfWAL = false; ResetDecoder(state); state->abortedRecPtr = InvalidXLogRecPtr; @@ -588,6 +590,15 @@ err: */ state->abortedRecPtr = RecPtr; state->missingContrecPtr = targetPagePtr; + + /* + * If the message is not set yet, that means we failed to load the + * page for the record. Otherwise do not hide the existing message. + */ + if (state->errormsg_buf[0] == '\0') + report_invalid_record(state, + "missing contrecord at %X/%X", + LSN_FORMAT_ARGS(RecPtr)); } /* @@ -730,6 +741,40 @@ ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr, XLogRecPtr PrevRecPtr, XLogRecord *record, bool randAccess) { + if (record->xl_tot_len == 0) + { + /* + * We are almost sure reaching the end of WAL, make sure that the + * whole page after the record is filled with zeroes. + */ + char *p; + char *pe; + + /* scan from the beginning of the record to the end of block */ + p = (char *) record; + pe = p + XLOG_BLCKSZ - (RecPtr & (XLOG_BLCKSZ - 1)); + + while (*p == 0 && p < pe) + p++; + + if (p == pe) + { + /* + * The page after the record is completely zeroed. That suggests + * we don't have a record after this point. We don't bother + * checking the pages after since they are not zeroed in the case + * of recycled segments. + */ + report_invalid_record(state, "empty record at %X/%X", + LSN_FORMAT_ARGS(RecPtr)); + + /* notify end-of-wal to callers */ + state->EndOfWAL = true; + return false; + } + + /* The same condition will be caught as invalid record length */ + } if (record->xl_tot_len < SizeOfXLogRecord) { report_invalid_record(state, @@ -836,6 +881,31 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr, XLogSegNoOffsetToRecPtr(segno, offset, state->segcxt.ws_segsize, recaddr); + StaticAssertStmt(XLOG_PAGE_MAGIC != 0, "XLOG_PAGE_MAGIC is zero"); + + if (hdr->xlp_magic == 0) + { + /* Regard an empty page as End-Of-WAL */ + int i; + + for (i = 0; i < XLOG_BLCKSZ && phdr[i] == 0; i++); + if (i == XLOG_BLCKSZ) + { + char fname[MAXFNAMELEN]; + + XLogFileName(fname, state->seg.ws_tli, segno, + state->segcxt.ws_segsize); + + report_invalid_record(state, + "empty page in log segment %s, offset %u", + fname, + offset); + state->EndOfWAL = true; + return false; + } + + /* The same condition will be caught as invalid magic number */ + } if (hdr->xlp_magic != XLOG_PAGE_MAGIC) { char fname[MAXFNAMELEN]; @@ -921,6 +991,14 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr, LSN_FORMAT_ARGS(hdr->xlp_pageaddr), fname, offset); + + /* + * If the page address is less than expected we assume it is an unused + * page in a recycled segment. + */ + if (hdr->xlp_pageaddr < recaddr) + state->EndOfWAL = true; + return false; } diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index f9f212680b..750056acaf 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1592,7 +1592,7 @@ PerformWalRecovery(void) /* just have to read next record after CheckPoint */ Assert(xlogreader->ReadRecPtr == CheckPointLoc); replayTLI = CheckPointTLI; - record = ReadRecord(xlogreader, LOG, false, replayTLI); + record = ReadRecord(xlogreader, WARNING, false, replayTLI); } if (record != NULL) @@ -1706,7 +1706,7 @@ PerformWalRecovery(void) } /* Else, try to fetch the next WAL record */ - record = ReadRecord(xlogreader, LOG, false, replayTLI); + record = ReadRecord(xlogreader, WARNING, false, replayTLI); } while (record != NULL); /* @@ -1765,13 +1765,20 @@ PerformWalRecovery(void) InRedo = false; } - else + else if (xlogreader->EndOfWAL) { /* there are no WAL records following the checkpoint */ ereport(LOG, (errmsg("redo is not required"))); } + else + { + /* broken record found */ + ereport(WARNING, + (errmsg("redo is skipped"), + errhint("This suggests WAL file corruption. You might need to check the database."))); + } /* * This check is intentionally after the above log messages that indicate @@ -2939,6 +2946,7 @@ ReadRecord(XLogReaderState *xlogreader, int emode, for (;;) { char *errormsg; + XLogRecPtr ErrRecPtr = InvalidXLogRecPtr; record = XLogReadRecord(xlogreader, &errormsg); if (record == NULL) @@ -2954,6 +2962,18 @@ ReadRecord(XLogReaderState *xlogreader, int emode, { abortedRecPtr = xlogreader->abortedRecPtr; missingContrecPtr = xlogreader->missingContrecPtr; + ErrRecPtr = abortedRecPtr; + } + else + { + /* + * EndRecPtr is the LSN we tried to read but failed. In the + * case of decoding error, it is at the end of the failed + * record but we don't have a means for now to know EndRecPtr + * is pointing to which of the beginning or ending of the + * failed record. + */ + ErrRecPtr = xlogreader->EndRecPtr; } if (readFile >= 0) @@ -2963,13 +2983,16 @@ ReadRecord(XLogReaderState *xlogreader, int emode, } /* - * We only end up here without a message when XLogPageRead() - * failed - in that case we already logged something. In - * StandbyMode that only happens if we have been triggered, so we - * shouldn't loop anymore in that case. + * We only end up here without a message when XLogPageRead() failed + * in that case we already logged something, or just met end-of-WAL + * conditions. In StandbyMode that only happens if we have been + * triggered, so we shouldn't loop anymore in that case. When + * EndOfWAL is true, we don't emit that error if any immediately + * and instead will show it as a part of a decent end-of-wal + * message later. */ - if (errormsg) - ereport(emode_for_corrupt_record(emode, xlogreader->EndRecPtr), + if (!xlogreader->EndOfWAL && errormsg) + ereport(emode_for_corrupt_record(emode, ErrRecPtr), (errmsg_internal("%s", errormsg) /* already translated */ )); } @@ -3000,11 +3023,14 @@ ReadRecord(XLogReaderState *xlogreader, int emode, /* Great, got a record */ return record; } - else + + Assert(ErrRecPtr != InvalidXLogRecPtr); + + /* No valid record available from this source */ + lastSourceFailed = true; + + if (!fetching_ckpt) { - /* No valid record available from this source */ - lastSourceFailed = true; - /* * If archive recovery was requested, but we were still doing * crash recovery, switch to archive recovery and retry using the @@ -3017,11 +3043,16 @@ ReadRecord(XLogReaderState *xlogreader, int emode, * we'd have no idea how far we'd have to replay to reach * consistency. So err on the safe side and give up. */ - if (!InArchiveRecovery && ArchiveRecoveryRequested && - !fetching_ckpt) + if (!InArchiveRecovery && ArchiveRecoveryRequested) { + /* + * We don't report this as LOG, since we don't stop recovery + * here + */ ereport(DEBUG1, - (errmsg_internal("reached end of WAL in pg_wal, entering archive recovery"))); + (errmsg_internal("reached end of WAL at %X/%X on timeline %u in pg_wal during crash recovery, entering archive recovery", + LSN_FORMAT_ARGS(ErrRecPtr), + replayTLI))); InArchiveRecovery = true; if (StandbyModeRequested) StandbyMode = true; @@ -3042,12 +3073,24 @@ ReadRecord(XLogReaderState *xlogreader, int emode, continue; } - /* In standby mode, loop back to retry. Otherwise, give up. */ - if (StandbyMode && !CheckForStandbyTrigger()) - continue; - else - return NULL; + /* + * recovery ended. + * + * Emit a decent message if we met end-of-WAL. Otherwise we should + * have already emitted an error message. + */ + if (xlogreader->EndOfWAL) + ereport(LOG, + (errmsg("reached end of WAL at %X/%X on timeline %u", + LSN_FORMAT_ARGS(ErrRecPtr), replayTLI), + (errormsg ? errdetail_internal("%s", errormsg) : 0))); } + + /* In standby mode, loop back to retry. Otherwise, give up. */ + if (StandbyMode && !CheckForStandbyTrigger()) + continue; + else + return NULL; } } @@ -3129,12 +3172,16 @@ retry: private->replayTLI, xlogreader->EndRecPtr)) { + Assert(!StandbyMode || CheckForStandbyTrigger()); + if (readFile >= 0) close(readFile); readFile = -1; readLen = 0; readSource = XLOG_FROM_ANY; + /* promotion exit is not end-of-WAL */ + xlogreader->EndOfWAL = !StandbyMode; return -1; } } @@ -3767,7 +3814,8 @@ emode_for_corrupt_record(int emode, XLogRecPtr RecPtr) { static XLogRecPtr lastComplaint = 0; - if (readSource == XLOG_FROM_PG_WAL && emode == LOG) + /* use currentSource as readSource is reset at failure */ + if (currentSource == XLOG_FROM_PG_WAL && emode <= WARNING) { if (RecPtr == lastComplaint) emode = DEBUG1; diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c index ceaff097b9..4f117ea4da 100644 --- a/src/backend/replication/walreceiver.c +++ b/src/backend/replication/walreceiver.c @@ -472,10 +472,9 @@ WalReceiverMain(void) else if (len < 0) { ereport(LOG, - (errmsg("replication terminated by primary server"), - errdetail("End of WAL reached on timeline %u at %X/%X.", - startpointTLI, - LSN_FORMAT_ARGS(LogstreamResult.Write)))); + (errmsg("replication terminated by primary server at %X/%X on timeline %u.", + LSN_FORMAT_ARGS(LogstreamResult.Write), + startpointTLI))); endofwal = true; break; } diff --git a/src/bin/pg_waldump/pg_waldump.c b/src/bin/pg_waldump/pg_waldump.c index a6251e1a96..3745e76488 100644 --- a/src/bin/pg_waldump/pg_waldump.c +++ b/src/bin/pg_waldump/pg_waldump.c @@ -1176,9 +1176,16 @@ main(int argc, char **argv) exit(0); if (errormsg) - fatal_error("error in WAL record at %X/%X: %s", - LSN_FORMAT_ARGS(xlogreader_state->ReadRecPtr), - errormsg); + { + if (xlogreader_state->EndOfWAL) + pg_log_info("end of WAL at %X/%X: %s", + LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr), + errormsg); + else + fatal_error("error in WAL record at %X/%X: %s", + LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr), + errormsg); + } XLogReaderFree(xlogreader_state); diff --git a/src/include/access/xlogreader.h b/src/include/access/xlogreader.h index 477f0efe26..7b314ef10e 100644 --- a/src/include/access/xlogreader.h +++ b/src/include/access/xlogreader.h @@ -174,6 +174,7 @@ struct XLogReaderState */ XLogRecPtr ReadRecPtr; /* start of last record read */ XLogRecPtr EndRecPtr; /* end+1 of last record read */ + bool EndOfWAL; /* was the last attempt EOW? */ /* * Set at the end of recovery: the start point of a partial record at the diff --git a/src/test/recovery/t/011_crash_recovery.pl b/src/test/recovery/t/011_crash_recovery.pl index 14154d1ce0..01033334d6 100644 --- a/src/test/recovery/t/011_crash_recovery.pl +++ b/src/test/recovery/t/011_crash_recovery.pl @@ -10,7 +10,9 @@ use PostgreSQL::Test::Cluster; use PostgreSQL::Test::Utils; use Test::More; use Config; +use IPC::Run; +my $reached_eow_pat = "reached end of WAL at "; my $node = PostgreSQL::Test::Cluster->new('primary'); $node->init(allows_streaming => 1); $node->start; @@ -48,7 +50,15 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]), # Crash and restart the postmaster $node->stop('immediate'); +my $logstart = get_log_size($node); $node->start; +my $max_attempts = 360; +while ($max_attempts-- >= 0) +{ + last if (find_in_log($node, $reached_eow_pat, $logstart)); + sleep 0.5; +} +ok ($max_attempts >= 0, "end-of-wal is logged"); # Make sure we really got a new xid cmp_ok($node->safe_psql('postgres', 'SELECT pg_current_xact_id()'), @@ -61,4 +71,100 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]), $stdin .= "\\q\n"; $tx->finish; # wait for psql to quit gracefully +my $segsize = $node->safe_psql('postgres', + qq[SELECT setting FROM pg_settings WHERE name = 'wal_segment_size';]); + +# make sure no records afterwards go to the next segment +$node->safe_psql('postgres', qq[ + SELECT pg_switch_wal(); + CHECKPOINT; + CREATE TABLE t(); +]); +$node->stop('immediate'); + +# identify REDO WAL file +my $cmd = "pg_controldata -D " . $node->data_dir(); +$cmd = ['pg_controldata', '-D', $node->data_dir()]; +$stdout = ''; +$stderr = ''; +IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr; +ok($stdout =~ /^Latest checkpoint's REDO WAL file:[ \t] *(.+)$/m, + "checkpoint file is identified"); +my $chkptfile = $1; + +# identify the last record +my $walfile = $node->data_dir() . "/pg_wal/$chkptfile"; +$cmd = ['pg_waldump', $walfile]; +$stdout = ''; +$stderr = ''; +my $lastrec; +IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr; +foreach my $l (split(/\r?\n/, $stdout)) +{ + $lastrec = $l; +} +ok(defined $lastrec, "last WAL record is extracted"); +ok($stderr =~ /end of WAL at ([0-9A-F\/]+): .* at \g1/, + "pg_waldump emits the correct ending message"); + +# read the last record LSN excluding leading zeroes +ok ($lastrec =~ /, lsn: 0\/0*([1-9A-F][0-9A-F]+),/, + "LSN of the last record identified"); +my $lastlsn = $1; + +# corrupt the last record +my $offset = hex($lastlsn) % $segsize; +open(my $segf, '+<', $walfile) or die "failed to open $walfile\n"; +seek($segf, $offset, 0); # halfway break the last record +print $segf "\0\0\0\0"; +close($segf); + +# pg_waldump complains about the corrupted record +$stdout = ''; +$stderr = ''; +IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr; +ok($stderr =~ /fatal: error in WAL record at 0\/$lastlsn: .* at 0\/$lastlsn/, + "pg_waldump emits the correct error message"); + +# also server complains +$logstart = get_log_size($node); +$node->start; +$max_attempts = 360; +while ($max_attempts-- >= 0) +{ + last if (find_in_log($node, "WARNING: invalid record length at 0/$lastlsn: wanted [0-9]+, got 0", + $logstart)); + sleep 0.5; +} +ok($max_attempts >= 0, "header error is logged at $lastlsn"); + +# no end-of-wal message should be seen this time +ok(!find_in_log($node, $reached_eow_pat, $logstart), + "false log message is not emitted"); + +$node->stop('immediate'); + done_testing(); + +#### helper routines +# return the size of logfile of $node in bytes +sub get_log_size +{ + my ($node) = @_; + + return (stat $node->logfile)[7]; +} + +# find $pat in logfile of $node after $off-th byte +sub find_in_log +{ + my ($node, $pat, $off) = @_; + + $off = 0 unless defined $off; + my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile); + return 0 if (length($log) <= $off); + + $log = substr($log, $off); + + return $log =~ m/$pat/; +} -- 2.27.0 ^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Make mesage at end-of-recovery less scary. @ 2022-02-19 04:01 Ashutosh Sharma <[email protected]> parent: Kyotaro Horiguchi <[email protected]> 0 siblings, 1 reply; 5+ messages in thread From: Ashutosh Sharma @ 2022-02-19 04:01 UTC (permalink / raw) To: Kyotaro Horiguchi <[email protected]>; +Cc: [email protected]; Michael Paquier <[email protected]>; Bossart, Nathan <[email protected]>; David Steele <[email protected]>; Peter Eisentraut <[email protected]>; Andres Freund <[email protected]>; PostgreSQL Hackers <[email protected]>; [email protected]; Robert Haas <[email protected]> On Thu, Feb 17, 2022 at 1:20 PM Kyotaro Horiguchi <[email protected]> wrote: > > At Tue, 15 Feb 2022 20:17:20 +0530, Ashutosh Sharma <[email protected]> wrote in > > OK. The v13 patch looks good. I have marked it as ready to commit. > > Thank you for working on all my review comments. > > Thaks! But the recent xlog.c refactoring crashes into this patch. > And I found a silly bug while rebasing. > > xlog.c:12463 / xlogrecovery.c:3168 > if (!WaitForWALToBecomeAvailable(targetPagePtr + reqLen, > .. > { > + Assert(!StandbyMode); > ... > + xlogreader->EndOfWAL = true; > > Yeah, I forgot about promotion there.. Yes, we exit WaitForWALToBecomeAvailable() even in standby mode provided the user has requested for the promotion. So checking for the !StandbyMode condition alone was not enough. So what I should have done is > setting EndOfWAL according to StandbyMode. > > + Assert(!StandbyMode || CheckForStandbyTrigger()); > ... > + /* promotion exit is not end-of-WAL */ > + xlogreader->EndOfWAL = !StandbyMode; > The changes looks good. thanks.! -- With Regards, Ashutosh Sharma. ^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: Make mesage at end-of-recovery less scary. @ 2022-03-02 02:17 Kyotaro Horiguchi <[email protected]> parent: Ashutosh Sharma <[email protected]> 0 siblings, 0 replies; 5+ messages in thread From: Kyotaro Horiguchi @ 2022-03-02 02:17 UTC (permalink / raw) To: [email protected]; +Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected] At Sat, 19 Feb 2022 09:31:33 +0530, Ashutosh Sharma <[email protected]> wrote in > The changes looks good. thanks.! Thanks! Some recent core change changed WAL insertion speed during the TAP test and revealed one forgotton case of EndOfWAL. When a record header flows into the next page, XLogReadRecord does separate check from ValidXLogRecordHeader by itself. > * If the whole record header is on this page, validate it immediately. > * Otherwise do just a basic sanity check on xl_tot_len, and validate the > * rest of the header after reading it from the next page. The xl_tot_len > * check is necessary here to ensure that we enter the "Need to reassemble > * record" code path below; otherwise we might fail to apply > * ValidXLogRecordHeader at all. > */ > if (targetRecOff <= XLOG_BLCKSZ - SizeOfXLogRecord) > { ... > } > else > { > /* XXX: more validation should be done here */ > if (total_len < SizeOfXLogRecord) > { I could simplly copy-in a part of ValidXLogRecordHeader there but that results in rather large duplicate code. I could have ValidXLogRecordHeader handle the partial header case but it seems to me complex. So in this version I split the xl_tot_len part of ValidXLogRecordHeader into ValidXLogRecordLength. regards. -- Kyotaro Horiguchi NTT Open Source Software Center Attachments: [text/x-patch] v15-0001-Make-End-Of-Recovery-error-less-scary.patch (18.8K, ../../[email protected]/2-v15-0001-Make-End-Of-Recovery-error-less-scary.patch) download | inline diff: From 01cce076d2b3ad536398cc2b716ef64ed9b2c409 Mon Sep 17 00:00:00 2001 From: Kyotaro Horiguchi <[email protected]> Date: Fri, 28 Feb 2020 15:52:58 +0900 Subject: [PATCH v15] Make End-Of-Recovery error less scary When recovery in any type ends, we see a bit scary error message like "invalid record length" that suggests something serious is happening. Actually if recovery meets a record with length = 0, that usually means it finished applying all available WAL records. Make this message less scary as "reached end of WAL". Instead, raise the error level for other kind of WAL failure to WARNING. --- src/backend/access/transam/xlogreader.c | 125 ++++++++++++++++++---- src/backend/access/transam/xlogrecovery.c | 92 ++++++++++++---- src/backend/replication/walreceiver.c | 7 +- src/bin/pg_waldump/pg_waldump.c | 13 ++- src/include/access/xlogreader.h | 1 + src/test/recovery/t/011_crash_recovery.pl | 106 ++++++++++++++++++ 6 files changed, 297 insertions(+), 47 deletions(-) diff --git a/src/backend/access/transam/xlogreader.c b/src/backend/access/transam/xlogreader.c index 35029cf97d..ba1c1ece87 100644 --- a/src/backend/access/transam/xlogreader.c +++ b/src/backend/access/transam/xlogreader.c @@ -42,6 +42,8 @@ static bool allocate_recordbuf(XLogReaderState *state, uint32 reclength); static int ReadPageInternal(XLogReaderState *state, XLogRecPtr pageptr, int reqLen); static void XLogReaderInvalReadState(XLogReaderState *state); +static bool ValidXLogRecordLength(XLogReaderState *state, XLogRecPtr RecPtr, + XLogRecord *record); static bool ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr, XLogRecPtr PrevRecPtr, XLogRecord *record, bool randAccess); static bool ValidXLogRecord(XLogReaderState *state, XLogRecord *record, @@ -121,6 +123,7 @@ XLogReaderAllocate(int wal_segment_size, const char *waldir, pfree(state); return NULL; } + state->EndOfWAL = false; state->errormsg_buf[0] = '\0'; /* @@ -292,6 +295,7 @@ XLogReadRecord(XLogReaderState *state, char **errormsg) /* reset error state */ *errormsg = NULL; state->errormsg_buf[0] = '\0'; + state->EndOfWAL = false; ResetDecoder(state); state->abortedRecPtr = InvalidXLogRecPtr; @@ -380,12 +384,11 @@ restart: * whole header. */ record = (XLogRecord *) (state->readBuf + RecPtr % XLOG_BLCKSZ); - total_len = record->xl_tot_len; /* * If the whole record header is on this page, validate it immediately. - * Otherwise do just a basic sanity check on xl_tot_len, and validate the - * rest of the header after reading it from the next page. The xl_tot_len + * Otherwise do just a basic sanity check on record length, and validate + * the rest of the header after reading it from the next page. The length * check is necessary here to ensure that we enter the "Need to reassemble * record" code path below; otherwise we might fail to apply * ValidXLogRecordHeader at all. @@ -399,18 +402,13 @@ restart: } else { - /* XXX: more validation should be done here */ - if (total_len < SizeOfXLogRecord) - { - report_invalid_record(state, - "invalid record length at %X/%X: wanted %u, got %u", - LSN_FORMAT_ARGS(RecPtr), - (uint32) SizeOfXLogRecord, total_len); + if (!ValidXLogRecordLength(state, RecPtr, record)) goto err; - } + gotheader = false; } + total_len = record->xl_tot_len; len = XLOG_BLCKSZ - RecPtr % XLOG_BLCKSZ; if (total_len > len) { @@ -588,6 +586,15 @@ err: */ state->abortedRecPtr = RecPtr; state->missingContrecPtr = targetPagePtr; + + /* + * If the message is not set yet, that means we failed to load the + * page for the record. Otherwise do not hide the existing message. + */ + if (state->errormsg_buf[0] == '\0') + report_invalid_record(state, + "missing contrecord at %X/%X", + LSN_FORMAT_ARGS(RecPtr)); } /* @@ -719,6 +726,60 @@ XLogReaderInvalReadState(XLogReaderState *state) state->readLen = 0; } +/* + * Validate record length of an XLOG record header. + * + * This is substantially a part of ValidXLogRecordHeader. But XLogReadRecord + * needs this separate from the function in case of a partial record header. + */ +static bool +ValidXLogRecordLength(XLogReaderState *state, XLogRecPtr RecPtr, + XLogRecord *record) +{ + if (record->xl_tot_len == 0) + { + char *p; + char *pe; + + /* + * We are almost sure reaching the end of WAL, make sure that the + * whole page after the record is filled with zeroes. + */ + p = (char *) record; + pe = p + XLOG_BLCKSZ - (RecPtr & (XLOG_BLCKSZ - 1)); + + while (*p == 0 && p < pe) + p++; + + if (p == pe) + { + /* + * The page after the record is completely zeroed. That suggests + * we don't have a record after this point. We don't bother + * checking the pages after since they are not zeroed in the case + * of recycled segments. + */ + report_invalid_record(state, "empty record at %X/%X", + LSN_FORMAT_ARGS(RecPtr)); + + /* notify end-of-wal to callers */ + state->EndOfWAL = true; + return false; + } + } + + if (record->xl_tot_len < SizeOfXLogRecord) + { + report_invalid_record(state, + "invalid record length at %X/%X: wanted %u, got %u", + LSN_FORMAT_ARGS(RecPtr), + (uint32) SizeOfXLogRecord, record->xl_tot_len); + return false; + } + + return true; +} + /* * Validate an XLOG record header. * @@ -730,14 +791,9 @@ ValidXLogRecordHeader(XLogReaderState *state, XLogRecPtr RecPtr, XLogRecPtr PrevRecPtr, XLogRecord *record, bool randAccess) { - if (record->xl_tot_len < SizeOfXLogRecord) - { - report_invalid_record(state, - "invalid record length at %X/%X: wanted %u, got %u", - LSN_FORMAT_ARGS(RecPtr), - (uint32) SizeOfXLogRecord, record->xl_tot_len); + if (!ValidXLogRecordLength(state, RecPtr, record)) return false; - } + if (record->xl_rmid > RM_MAX_ID) { report_invalid_record(state, @@ -836,6 +892,31 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr, XLogSegNoOffsetToRecPtr(segno, offset, state->segcxt.ws_segsize, recaddr); + StaticAssertStmt(XLOG_PAGE_MAGIC != 0, "XLOG_PAGE_MAGIC is zero"); + + if (hdr->xlp_magic == 0) + { + /* Regard an empty page as End-Of-WAL */ + int i; + + for (i = 0; i < XLOG_BLCKSZ && phdr[i] == 0; i++); + if (i == XLOG_BLCKSZ) + { + char fname[MAXFNAMELEN]; + + XLogFileName(fname, state->seg.ws_tli, segno, + state->segcxt.ws_segsize); + + report_invalid_record(state, + "empty page in log segment %s, offset %u", + fname, + offset); + state->EndOfWAL = true; + return false; + } + + /* The same condition will be caught as invalid magic number */ + } if (hdr->xlp_magic != XLOG_PAGE_MAGIC) { char fname[MAXFNAMELEN]; @@ -921,6 +1002,14 @@ XLogReaderValidatePageHeader(XLogReaderState *state, XLogRecPtr recptr, LSN_FORMAT_ARGS(hdr->xlp_pageaddr), fname, offset); + + /* + * If the page address is less than expected we assume it is an unused + * page in a recycled segment. + */ + if (hdr->xlp_pageaddr < recaddr) + state->EndOfWAL = true; + return false; } diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index f9f212680b..750056acaf 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1592,7 +1592,7 @@ PerformWalRecovery(void) /* just have to read next record after CheckPoint */ Assert(xlogreader->ReadRecPtr == CheckPointLoc); replayTLI = CheckPointTLI; - record = ReadRecord(xlogreader, LOG, false, replayTLI); + record = ReadRecord(xlogreader, WARNING, false, replayTLI); } if (record != NULL) @@ -1706,7 +1706,7 @@ PerformWalRecovery(void) } /* Else, try to fetch the next WAL record */ - record = ReadRecord(xlogreader, LOG, false, replayTLI); + record = ReadRecord(xlogreader, WARNING, false, replayTLI); } while (record != NULL); /* @@ -1765,13 +1765,20 @@ PerformWalRecovery(void) InRedo = false; } - else + else if (xlogreader->EndOfWAL) { /* there are no WAL records following the checkpoint */ ereport(LOG, (errmsg("redo is not required"))); } + else + { + /* broken record found */ + ereport(WARNING, + (errmsg("redo is skipped"), + errhint("This suggests WAL file corruption. You might need to check the database."))); + } /* * This check is intentionally after the above log messages that indicate @@ -2939,6 +2946,7 @@ ReadRecord(XLogReaderState *xlogreader, int emode, for (;;) { char *errormsg; + XLogRecPtr ErrRecPtr = InvalidXLogRecPtr; record = XLogReadRecord(xlogreader, &errormsg); if (record == NULL) @@ -2954,6 +2962,18 @@ ReadRecord(XLogReaderState *xlogreader, int emode, { abortedRecPtr = xlogreader->abortedRecPtr; missingContrecPtr = xlogreader->missingContrecPtr; + ErrRecPtr = abortedRecPtr; + } + else + { + /* + * EndRecPtr is the LSN we tried to read but failed. In the + * case of decoding error, it is at the end of the failed + * record but we don't have a means for now to know EndRecPtr + * is pointing to which of the beginning or ending of the + * failed record. + */ + ErrRecPtr = xlogreader->EndRecPtr; } if (readFile >= 0) @@ -2963,13 +2983,16 @@ ReadRecord(XLogReaderState *xlogreader, int emode, } /* - * We only end up here without a message when XLogPageRead() - * failed - in that case we already logged something. In - * StandbyMode that only happens if we have been triggered, so we - * shouldn't loop anymore in that case. + * We only end up here without a message when XLogPageRead() failed + * in that case we already logged something, or just met end-of-WAL + * conditions. In StandbyMode that only happens if we have been + * triggered, so we shouldn't loop anymore in that case. When + * EndOfWAL is true, we don't emit that error if any immediately + * and instead will show it as a part of a decent end-of-wal + * message later. */ - if (errormsg) - ereport(emode_for_corrupt_record(emode, xlogreader->EndRecPtr), + if (!xlogreader->EndOfWAL && errormsg) + ereport(emode_for_corrupt_record(emode, ErrRecPtr), (errmsg_internal("%s", errormsg) /* already translated */ )); } @@ -3000,11 +3023,14 @@ ReadRecord(XLogReaderState *xlogreader, int emode, /* Great, got a record */ return record; } - else + + Assert(ErrRecPtr != InvalidXLogRecPtr); + + /* No valid record available from this source */ + lastSourceFailed = true; + + if (!fetching_ckpt) { - /* No valid record available from this source */ - lastSourceFailed = true; - /* * If archive recovery was requested, but we were still doing * crash recovery, switch to archive recovery and retry using the @@ -3017,11 +3043,16 @@ ReadRecord(XLogReaderState *xlogreader, int emode, * we'd have no idea how far we'd have to replay to reach * consistency. So err on the safe side and give up. */ - if (!InArchiveRecovery && ArchiveRecoveryRequested && - !fetching_ckpt) + if (!InArchiveRecovery && ArchiveRecoveryRequested) { + /* + * We don't report this as LOG, since we don't stop recovery + * here + */ ereport(DEBUG1, - (errmsg_internal("reached end of WAL in pg_wal, entering archive recovery"))); + (errmsg_internal("reached end of WAL at %X/%X on timeline %u in pg_wal during crash recovery, entering archive recovery", + LSN_FORMAT_ARGS(ErrRecPtr), + replayTLI))); InArchiveRecovery = true; if (StandbyModeRequested) StandbyMode = true; @@ -3042,12 +3073,24 @@ ReadRecord(XLogReaderState *xlogreader, int emode, continue; } - /* In standby mode, loop back to retry. Otherwise, give up. */ - if (StandbyMode && !CheckForStandbyTrigger()) - continue; - else - return NULL; + /* + * recovery ended. + * + * Emit a decent message if we met end-of-WAL. Otherwise we should + * have already emitted an error message. + */ + if (xlogreader->EndOfWAL) + ereport(LOG, + (errmsg("reached end of WAL at %X/%X on timeline %u", + LSN_FORMAT_ARGS(ErrRecPtr), replayTLI), + (errormsg ? errdetail_internal("%s", errormsg) : 0))); } + + /* In standby mode, loop back to retry. Otherwise, give up. */ + if (StandbyMode && !CheckForStandbyTrigger()) + continue; + else + return NULL; } } @@ -3129,12 +3172,16 @@ retry: private->replayTLI, xlogreader->EndRecPtr)) { + Assert(!StandbyMode || CheckForStandbyTrigger()); + if (readFile >= 0) close(readFile); readFile = -1; readLen = 0; readSource = XLOG_FROM_ANY; + /* promotion exit is not end-of-WAL */ + xlogreader->EndOfWAL = !StandbyMode; return -1; } } @@ -3767,7 +3814,8 @@ emode_for_corrupt_record(int emode, XLogRecPtr RecPtr) { static XLogRecPtr lastComplaint = 0; - if (readSource == XLOG_FROM_PG_WAL && emode == LOG) + /* use currentSource as readSource is reset at failure */ + if (currentSource == XLOG_FROM_PG_WAL && emode <= WARNING) { if (RecPtr == lastComplaint) emode = DEBUG1; diff --git a/src/backend/replication/walreceiver.c b/src/backend/replication/walreceiver.c index ceaff097b9..4f117ea4da 100644 --- a/src/backend/replication/walreceiver.c +++ b/src/backend/replication/walreceiver.c @@ -472,10 +472,9 @@ WalReceiverMain(void) else if (len < 0) { ereport(LOG, - (errmsg("replication terminated by primary server"), - errdetail("End of WAL reached on timeline %u at %X/%X.", - startpointTLI, - LSN_FORMAT_ARGS(LogstreamResult.Write)))); + (errmsg("replication terminated by primary server at %X/%X on timeline %u.", + LSN_FORMAT_ARGS(LogstreamResult.Write), + startpointTLI))); endofwal = true; break; } diff --git a/src/bin/pg_waldump/pg_waldump.c b/src/bin/pg_waldump/pg_waldump.c index 2340dc247b..215abe95dc 100644 --- a/src/bin/pg_waldump/pg_waldump.c +++ b/src/bin/pg_waldump/pg_waldump.c @@ -1173,9 +1173,16 @@ main(int argc, char **argv) exit(0); if (errormsg) - fatal_error("error in WAL record at %X/%X: %s", - LSN_FORMAT_ARGS(xlogreader_state->ReadRecPtr), - errormsg); + { + if (xlogreader_state->EndOfWAL) + pg_log_info("end of WAL at %X/%X: %s", + LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr), + errormsg); + else + fatal_error("error in WAL record at %X/%X: %s", + LSN_FORMAT_ARGS(xlogreader_state->EndRecPtr), + errormsg); + } XLogReaderFree(xlogreader_state); diff --git a/src/include/access/xlogreader.h b/src/include/access/xlogreader.h index 477f0efe26..7b314ef10e 100644 --- a/src/include/access/xlogreader.h +++ b/src/include/access/xlogreader.h @@ -174,6 +174,7 @@ struct XLogReaderState */ XLogRecPtr ReadRecPtr; /* start of last record read */ XLogRecPtr EndRecPtr; /* end+1 of last record read */ + bool EndOfWAL; /* was the last attempt EOW? */ /* * Set at the end of recovery: the start point of a partial record at the diff --git a/src/test/recovery/t/011_crash_recovery.pl b/src/test/recovery/t/011_crash_recovery.pl index 14154d1ce0..01033334d6 100644 --- a/src/test/recovery/t/011_crash_recovery.pl +++ b/src/test/recovery/t/011_crash_recovery.pl @@ -10,7 +10,9 @@ use PostgreSQL::Test::Cluster; use PostgreSQL::Test::Utils; use Test::More; use Config; +use IPC::Run; +my $reached_eow_pat = "reached end of WAL at "; my $node = PostgreSQL::Test::Cluster->new('primary'); $node->init(allows_streaming => 1); $node->start; @@ -48,7 +50,15 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]), # Crash and restart the postmaster $node->stop('immediate'); +my $logstart = get_log_size($node); $node->start; +my $max_attempts = 360; +while ($max_attempts-- >= 0) +{ + last if (find_in_log($node, $reached_eow_pat, $logstart)); + sleep 0.5; +} +ok ($max_attempts >= 0, "end-of-wal is logged"); # Make sure we really got a new xid cmp_ok($node->safe_psql('postgres', 'SELECT pg_current_xact_id()'), @@ -61,4 +71,100 @@ is($node->safe_psql('postgres', qq[SELECT pg_xact_status('$xid');]), $stdin .= "\\q\n"; $tx->finish; # wait for psql to quit gracefully +my $segsize = $node->safe_psql('postgres', + qq[SELECT setting FROM pg_settings WHERE name = 'wal_segment_size';]); + +# make sure no records afterwards go to the next segment +$node->safe_psql('postgres', qq[ + SELECT pg_switch_wal(); + CHECKPOINT; + CREATE TABLE t(); +]); +$node->stop('immediate'); + +# identify REDO WAL file +my $cmd = "pg_controldata -D " . $node->data_dir(); +$cmd = ['pg_controldata', '-D', $node->data_dir()]; +$stdout = ''; +$stderr = ''; +IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr; +ok($stdout =~ /^Latest checkpoint's REDO WAL file:[ \t] *(.+)$/m, + "checkpoint file is identified"); +my $chkptfile = $1; + +# identify the last record +my $walfile = $node->data_dir() . "/pg_wal/$chkptfile"; +$cmd = ['pg_waldump', $walfile]; +$stdout = ''; +$stderr = ''; +my $lastrec; +IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr; +foreach my $l (split(/\r?\n/, $stdout)) +{ + $lastrec = $l; +} +ok(defined $lastrec, "last WAL record is extracted"); +ok($stderr =~ /end of WAL at ([0-9A-F\/]+): .* at \g1/, + "pg_waldump emits the correct ending message"); + +# read the last record LSN excluding leading zeroes +ok ($lastrec =~ /, lsn: 0\/0*([1-9A-F][0-9A-F]+),/, + "LSN of the last record identified"); +my $lastlsn = $1; + +# corrupt the last record +my $offset = hex($lastlsn) % $segsize; +open(my $segf, '+<', $walfile) or die "failed to open $walfile\n"; +seek($segf, $offset, 0); # halfway break the last record +print $segf "\0\0\0\0"; +close($segf); + +# pg_waldump complains about the corrupted record +$stdout = ''; +$stderr = ''; +IPC::Run::run $cmd, '>', \$stdout, '2>', \$stderr; +ok($stderr =~ /fatal: error in WAL record at 0\/$lastlsn: .* at 0\/$lastlsn/, + "pg_waldump emits the correct error message"); + +# also server complains +$logstart = get_log_size($node); +$node->start; +$max_attempts = 360; +while ($max_attempts-- >= 0) +{ + last if (find_in_log($node, "WARNING: invalid record length at 0/$lastlsn: wanted [0-9]+, got 0", + $logstart)); + sleep 0.5; +} +ok($max_attempts >= 0, "header error is logged at $lastlsn"); + +# no end-of-wal message should be seen this time +ok(!find_in_log($node, $reached_eow_pat, $logstart), + "false log message is not emitted"); + +$node->stop('immediate'); + done_testing(); + +#### helper routines +# return the size of logfile of $node in bytes +sub get_log_size +{ + my ($node) = @_; + + return (stat $node->logfile)[7]; +} + +# find $pat in logfile of $node after $off-th byte +sub find_in_log +{ + my ($node, $pat, $off) = @_; + + $off = 0 unless defined $off; + my $log = PostgreSQL::Test::Utils::slurp_file($node->logfile); + return 0 if (length($log) <= $off); + + $log = substr($log, $off); + + return $log =~ m/$pat/; +} -- 2.27.0 ^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2022-03-02 02:17 UTC | newest] Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2020-03-13 07:59 [PATCH v52 3/7] Make archiver process an auxiliary process Kyotaro Horiguchi <[email protected]> 2022-02-15 14:47 Re: Make mesage at end-of-recovery less scary. Ashutosh Sharma <[email protected]> 2022-02-17 07:50 ` Re: Make mesage at end-of-recovery less scary. Kyotaro Horiguchi <[email protected]> 2022-02-19 04:01 ` Re: Make mesage at end-of-recovery less scary. Ashutosh Sharma <[email protected]> 2022-03-02 02:17 ` Re: Make mesage at end-of-recovery less scary. Kyotaro Horiguchi <[email protected]>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox