public inbox for [email protected]help / color / mirror / Atom feed
[PATCH v46 3/7] Make archiver process an auxiliary process 13+ messages / 6 participants [nested] [flat]
* [PATCH v46 3/7] Make archiver process an auxiliary process @ 2020-03-13 07:59 Kyotaro Horiguchi <[email protected]> 0 siblings, 0 replies; 13+ 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 | 130 +++-------------------- src/backend/postmaster/postmaster.c | 50 +++++---- src/backend/storage/lmgr/proc.c | 1 + src/include/access/xlog.h | 3 + src/include/access/xlogarchive.h | 1 + src/include/miscadmin.h | 2 + src/include/postmaster/pgarch.h | 4 +- src/include/storage/pmsignal.h | 1 - src/include/storage/proc.h | 3 + 11 files changed, 69 insertions(+), 154 deletions(-) diff --git a/src/backend/access/transam/xlogarchive.c b/src/backend/access/transam/xlogarchive.c index 1c5a4f8b5a..d01859bde5 100644 --- a/src/backend/access/transam/xlogarchive.c +++ b/src/backend/access/transam/xlogarchive.c @@ -29,7 +29,9 @@ #include "storage/fd.h" #include "storage/ipc.h" #include "storage/lwlock.h" +#include "storage/latch.h" #include "storage/pmsignal.h" +#include "storage/proc.h" /* * Attempt to retrieve the specified file from off-line archival storage. @@ -490,8 +492,8 @@ XLogArchiveNotify(const char *xlog) } /* Notify archiver that it's got something to do */ - if (IsUnderPostmaster) - SendPostmasterSignal(PMSIGNAL_WAKEN_ARCHIVER); + if (IsUnderPostmaster && ProcGlobal->archiverLatch) + SetLatch(ProcGlobal->archiverLatch); } /* 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..9a2e21bf86 100644 --- a/src/backend/postmaster/pgarch.c +++ b/src/backend/postmaster/pgarch.c @@ -48,6 +48,7 @@ #include "storage/latch.h" #include "storage/pg_shmem.h" #include "storage/pmsignal.h" +#include "storage/procsignal.h" #include "utils/guc.h" #include "utils/ps_status.h" @@ -78,13 +79,11 @@ * Local data * ---------- */ -static time_t last_pgarch_start_time; static time_t last_sigterm_time = 0; /* * 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; /* ---------- @@ -95,8 +94,6 @@ static volatile sig_atomic_t ready_to_stop = false; 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); @@ -110,75 +107,6 @@ static void pgarch_archiveDone(char *xlog); * ------------------------------------------------------------ */ -/* - * 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; - - /* - * Do nothing if no archiver needed - */ - if (!XLogArchivingActive()) - return 0; - - /* - * 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; - -#ifdef EXEC_BACKEND - switch ((pgArchPid = pgarch_forkexec())) -#else - switch ((pgArchPid = fork_process())) -#endif - { - 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; - } - - /* shouldn't get here */ - return 0; -} - /* ------------------------------------------------------------ * Local functions called by archiver follow * ------------------------------------------------------------ @@ -212,14 +140,9 @@ pgarch_forkexec(void) #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 +154,26 @@ 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); + /* + * Advertise our latch that backends can use to wake us up while we're + * sleeping. + */ + ProcGlobal->archiverLatch = &MyProc->procLatch; pgarch_MainLoop(); exit(0); } -/* SIGUSR1 signal handler for archiver process */ -static void -pgarch_waken(SIGNAL_ARGS) -{ - int save_errno = errno; - - /* set flag that there is work to be done */ - wakened = true; - SetLatch(MyLatch); - - errno = save_errno; -} - /* SIGUSR2 signal handler for archiver process */ static void pgarch_waken_stop(SIGNAL_ARGS) @@ -282,14 +198,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 +236,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 +258,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; } /* diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index 7de27ee4e0..af91c313e2 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) @@ -1788,7 +1789,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) @@ -3027,7 +3028,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(); @@ -3162,20 +3163,16 @@ reaper(SIGNAL_ARGS) } /* - * 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. + * Was it the archiver? Normal exit can be ignored; we'll start a new + * one at the next iteration of the postmaster's main loop, if + * necessary. Any other exit condition is treated as a crash. */ if (pid == PgArchPID) { PgArchPID = 0; if (!EXIT_STATUS_0(exitstatus)) - LogChildExit(LOG, _("archiver process"), - pid, exitstatus); - if (PgArchStartupAllowed()) - PgArchPID = pgarch_start(); + HandleChildCrash(pid, exitstatus, + _("archiver process")); continue; } @@ -3423,7 +3420,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. @@ -3629,6 +3626,18 @@ HandleChildCrash(int pid, int exitstatus, const char *procname) signal_child(AutoVacPID, (SendStop ? SIGSTOP : SIGQUIT)); } + /* 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", + (SendStop ? "SIGSTOP" : "SIGQUIT"), + (int) PgArchPID))); + signal_child(PgArchPID, (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 @@ -3932,6 +3941,7 @@ PostmasterStateMachine(void) Assert(CheckpointerPID == 0); Assert(WalWriterPID == 0); Assert(AutoVacPID == 0); + Assert(PgArchPID == 0); /* syslogger is not considered here */ pmState = PM_NO_CHILDREN; } @@ -5160,7 +5170,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 @@ -5214,16 +5224,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) { @@ -5465,6 +5465,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/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index c87ffc6549..a1e51c5b99 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -182,6 +182,7 @@ InitProcGlobal(void) ProcGlobal->startupBufferPinWaitBufId = -1; ProcGlobal->walwriterLatch = NULL; ProcGlobal->checkpointerLatch = NULL; + ProcGlobal->archiverLatch = NULL; pg_atomic_init_u32(&ProcGlobal->procArrayGroupFirst, INVALID_PGPROCNO); pg_atomic_init_u32(&ProcGlobal->clogGroupFirst, INVALID_PGPROCNO); diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h index 75ec1073bd..551f518cc2 100644 --- a/src/include/access/xlog.h +++ b/src/include/access/xlog.h @@ -339,6 +339,9 @@ extern XLogRecPtr GetRedoRecPtr(void); extern XLogRecPtr GetInsertRecPtr(void); extern XLogRecPtr GetFlushRecPtr(void); extern XLogRecPtr GetLastImportantRecPtr(void); +extern void XLogArchiveWakeupStart(void); +extern void XLogArchiveWakeupEnd(void); +extern void XLogArchiveWakeup(void); extern void RemovePromoteSignalFiles(void); extern bool PromoteIsTriggered(void); diff --git a/src/include/access/xlogarchive.h b/src/include/access/xlogarchive.h index 3edd1a976c..1a59181cf9 100644 --- a/src/include/access/xlogarchive.h +++ b/src/include/access/xlogarchive.h @@ -25,6 +25,7 @@ extern void ExecuteRecoveryCommand(const char *command, const char *commandName, extern void KeepFileRestoredFromArchive(const char *path, const char *xlogfname); extern void XLogArchiveNotify(const char *xlog); extern void XLogArchiveNotifySeg(XLogSegNo segno); +extern void XLogArchiveWakeup(void); extern void XLogArchiveForceDone(const char *xlog); extern bool XLogArchiveCheckDone(const char *xlog); extern bool XLogArchiveIsBusy(const char *xlog); 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..385b002dfe 100644 --- a/src/include/postmaster/pgarch.h +++ b/src/include/postmaster/pgarch.h @@ -32,8 +32,6 @@ */ extern int pgarch_start(void); -#ifdef EXEC_BACKEND -extern void PgArchiverMain(int argc, char *argv[]) pg_attribute_noreturn(); -#endif +extern void PgArchiverMain(void) pg_attribute_noreturn(); #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 0786fcf103..430d438303 100644 --- a/src/include/storage/proc.h +++ b/src/include/storage/proc.h @@ -354,6 +354,9 @@ typedef struct PROC_HDR int startupProcPid; /* Buffer id of the buffer that Startup process waits for pin on, or -1 */ int startupBufferPinWaitBufId; + /* Archiver process's latch */ + Latch *archiverLatch; + /* Current shared estimate of appropriate spins_per_delay value */ } PROC_HDR; extern PGDLLIMPORT PROC_HDR *ProcGlobal; -- 2.27.0 ----Next_Part(Thu_Jan_14_15_14_25_2021_903)-- Content-Type: Text/X-Patch; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="v46-0004-Shared-memory-based-stats-collector.patch" ^ permalink raw reply [nested|flat] 13+ messages in thread
* stats.sql might fail due to shared buffers also used by parallel tests @ 2025-01-06 07:00 Alexander Lakhin <[email protected]> 0 siblings, 1 reply; 13+ messages in thread From: Alexander Lakhin @ 2025-01-06 07:00 UTC (permalink / raw) To: pgsql-hackers; +Cc: Andres Freund <[email protected]>; Melanie Plageman <[email protected]> Hello hackers, I'd like to share my investigation of one mysterious stats.sql failure occurred in December: [1]. The difference of the failure is: --- C:/prog/bf/root/HEAD/pgsql/src/test/regress/expected/stats.out 2024-09-18 19:31:14.665516500 +0000 +++ C:/prog/bf/root/HEAD/pgsql.build/testrun/recovery/027_stream_regress/data/results/stats.out 2024-12-17 09:57:08.944588500 +0000 @@ -1291,7 +1291,7 @@ SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes; ?column? ---------- - t + f (1 row) 027_stream_regress_primary.log contains: 2024-12-17 09:57:06.778 UTC [8568:109] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs FROM pg_stat_io WHERE object = 'relation' 2024-12-17 09:57:06.779 UTC [8568:110] pg_regress/stats LOG: statement: CREATE TABLE test_io_shared(a int); 2024-12-17 09:57:06.780 UTC [8568:111] pg_regress/stats LOG: statement: INSERT INTO test_io_shared SELECT i FROM generate_series(1,100)i; ... 2024-12-17 09:57:06.782 UTC [8568:115] pg_regress/stats LOG: statement: CHECKPOINT; 2024-12-17 09:57:06.794 UTC [3664:40] LOG: checkpoint starting: immediate force wait 2024-12-17 09:57:06.856 UTC [3664:41] LOG: checkpoint complete: wrote 0 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.062 s; sync files=0, longest=0.000 s, average=0.000 s; distance=1875 kB, estimate=52682 kB; lsn=0/14A2F410, redo lsn=0/14A2F3B8 2024-12-17 09:57:06.857 UTC [8568:116] pg_regress/stats LOG: statement: CHECKPOINT; 2024-12-17 09:57:06.857 UTC [3664:42] LOG: checkpoint starting: immediate force wait 2024-12-17 09:57:06.859 UTC [3664:43] LOG: checkpoint complete: wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=47414 kB; lsn=0/14A2F4E0, redo lsn=0/14A2F488 2024-12-17 09:57:06.859 UTC [8568:117] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs FROM pg_stat_io WHERE object = 'relation' 2024-12-17 09:57:06.860 UTC [8568:118] pg_regress/stats LOG: statement: SELECT 77693 > 77693; The corresponding test case (added by 10a082bf7, dated 2023-02-11) is: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs FROM pg_stat_io WHERE object = 'relation' \gset io_sum_shared_before_ ... CREATE TABLE test_io_shared(a int); INSERT INTO test_io_shared SELECT i FROM generate_series(1,100)i; ... CHECKPOINT; CHECKPOINT; ... SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs FROM pg_stat_get_backend_io(pg_backend_pid()) WHERE object = 'relation' \gset my_io_sum_shared_after_ SELECT :my_io_sum_shared_after_writes >= :my_io_sum_shared_before_writes; So, as we can see from the log above, both checkpoints wrote 0 buffers, moreover, no other process/backend wrote any buffers. After series of experiments, I found that this situation is possible when other backend steals shared buffers from checkpointer, without making new buffers dirty, and then delays flushing it's statistics. Please find attached a reproducer for this issue: I've added two sleeps to stats.sql and reduced parallel_schedule, but I believe it's a legal change, which doesn't affect the test case essentially. With bufchurn.sql running concurrently. and TEMP_CONFIG containing shared_buffers = 1MB (as in the 027_stream_regress test in question), I can see exactly the same failure: $ echo 'shared_buffers = 1MB' >/tmp/extra.config; TEMP_CONFIG=/tmp/extra.config make -s check # +++ regress check in src/test/regress +++ # initializing database system by copying initdb template # using temp instance on port 65312 with PID 129700 ok 1 - test_setup 356 ms ok 2 - create_index 1002 ms # parallel group (2 tests): stats bufchurn not ok 3 + stats 21176 ms ... diff -U3 .../src/test/regress/expected/stats.out .../src/test/regress/results/stats.out --- .../src/test/regress/expected/stats.out 2025-01-06 08:03:07.720275980 +0200 +++ .../src/test/regress/results/stats.out 2025-01-06 08:15:34.602170721 +0200 @@ -1321,7 +1321,7 @@ SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes; ?column? ---------- - t + f (1 row) ... [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-12-17%2008%3A59%3A44 Best regards, Alexander Attachments: [text/x-patch] stats-bufs-write-repro.patch (8.8K, ../../[email protected]/2-stats-bufs-write-repro.patch) download | inline diff: diff --git a/src/test/regress/expected/bufchurn.out b/src/test/regress/expected/bufchurn.out new file mode 100644 index 0000000000..e69de29bb2 diff --git a/src/test/regress/expected/stats.out b/src/test/regress/expected/stats.out index a0317b7208..651898b9f4 100644 --- a/src/test/regress/expected/stats.out +++ b/src/test/regress/expected/stats.out @@ -834,6 +834,12 @@ SELECT num_requested AS rqst_ckpts_before FROM pg_stat_checkpointer \gset SELECT wal_bytes AS wal_bytes_before FROM pg_stat_wal \gset CREATE TEMP TABLE test_stats_temp AS SELECT 17; DROP TABLE test_stats_temp; +SELECT pg_sleep(10); + pg_sleep +---------- + +(1 row) + -- Checkpoint twice: The checkpointer reports stats after reporting completion -- of the checkpoint. But after a second checkpoint we'll see at least the -- results of the first. @@ -1298,6 +1304,12 @@ SELECT :my_io_sum_shared_after_extends > :my_io_sum_shared_before_extends; t (1 row) +SELECT pg_sleep(10); + pg_sleep +---------- + +(1 row) + -- After a checkpoint, there should be some additional IOCONTEXT_NORMAL writes -- and fsyncs in the global stats (usually not for the backend). -- See comment above for rationale for two explicit CHECKPOINTs. diff --git a/src/test/regress/parallel_schedule b/src/test/regress/parallel_schedule index 1edd9e45eb..2142842a31 100644 --- a/src/test/regress/parallel_schedule +++ b/src/test/regress/parallel_schedule @@ -1,138 +1,4 @@ -# ---------- -# src/test/regress/parallel_schedule -# -# Most test scripts can be run after running just test_setup and possibly -# create_index. Exceptions to this rule are documented below. -# -# By convention, we put no more than twenty tests in any one parallel group; -# this limits the number of connections needed to run the tests. -# ---------- - -# required setup steps test: test_setup - -# ---------- -# The first group of parallel tests -# ---------- -test: boolean char name varchar text int2 int4 int8 oid float4 float8 bit numeric txid uuid enum money rangetypes pg_lsn regproc - -# ---------- -# The second group of parallel tests -# multirangetypes depends on rangetypes -# multirangetypes shouldn't run concurrently with type_sanity -# ---------- -test: strings md5 numerology point lseg line box path polygon circle date time timetz timestamp timestamptz interval inet macaddr macaddr8 multirangetypes - -# ---------- -# Another group of parallel tests -# geometry depends on point, lseg, line, box, path, polygon, circle -# horology depends on date, time, timetz, timestamp, timestamptz, interval -# ---------- -test: geometry horology tstypes regex type_sanity opr_sanity misc_sanity comments expressions unicode xid mvcc database stats_import - -# ---------- -# Load huge amounts of data -# We should split the data files into single files and then -# execute two copy tests in parallel, to check that copy itself -# is concurrent safe. -# ---------- -test: copy copyselect copydml copyencoding insert insert_conflict - -# ---------- -# More groups of parallel tests -# Note: many of the tests in later groups depend on create_index -# ---------- -test: create_function_c create_misc create_operator create_procedure create_table create_type create_schema -test: create_index create_index_spgist create_view index_including index_including_gist - -# ---------- -# Another group of parallel tests -# ---------- -test: create_aggregate create_function_sql create_cast constraints triggers select inherit typed_table vacuum drop_if_exists updatable_views roleattributes create_am hash_func errors infinite_recurse - -# ---------- -# sanity_check does a vacuum, affecting the sort order of SELECT * -# results. So it should not run parallel to other tests. -# ---------- -test: sanity_check - -# ---------- -# Another group of parallel tests -# aggregates depends on create_aggregate -# join depends on create_misc -# ---------- -test: select_into select_distinct select_distinct_on select_implicit select_having subselect union case join aggregates transactions random portals arrays btree_index hash_index update delete namespace prepared_xacts - -# ---------- -# Another group of parallel tests -# ---------- -test: brin gin gist spgist privileges init_privs security_label collate matview lock replica_identity rowsecurity object_address tablesample groupingsets drop_operator password identity generated_stored join_hash - -# ---------- -# Additional BRIN tests -# ---------- -test: brin_bloom brin_multi - -# ---------- -# Another group of parallel tests -# psql depends on create_am -# amutils depends on geometry, create_index_spgist, hash_index, brin -# ---------- -test: create_table_like alter_generic alter_operator misc async dbsize merge misc_functions sysviews tsrf tid tidscan tidrangescan collate.utf8 collate.icu.utf8 incremental_sort create_role without_overlaps - -# collate.linux.utf8 and collate.icu.utf8 tests cannot be run in parallel with each other -test: rules psql psql_crosstab amutils stats_ext collate.linux.utf8 collate.windows.win1252 - -# ---------- -# Run these alone so they don't run out of parallel workers -# select_parallel depends on create_misc -# ---------- -test: select_parallel -test: write_parallel -test: vacuum_parallel - -# no relation related tests can be put in this group -test: publication subscription - -# ---------- -# Another group of parallel tests -# select_views depends on create_view -# ---------- -test: select_views portals_p2 foreign_key cluster dependency guc bitmapops combocid tsearch tsdicts foreign_data window xmlmap functional_deps advisory_lock indirect_toast equivclass - -# ---------- -# Another group of parallel tests (JSON related) -# ---------- -test: json jsonb json_encoding jsonpath jsonpath_encoding jsonb_jsonpath sqljson sqljson_queryfuncs sqljson_jsontable - -# ---------- -# Another group of parallel tests -# with depends on create_misc -# NB: temp.sql does a reconnect which transiently uses 2 connections, -# so keep this parallel group to at most 19 tests -# ---------- -test: plancache limit plpgsql copy2 temp domain rangefuncs prepare conversion truncate alter_table sequence polymorphism rowtypes returning largeobject with xml - -# ---------- -# Another group of parallel tests -# -# The stats test resets stats, so nothing else needing stats access can be in -# this group. -# ---------- -test: partition_join partition_prune reloptions hash_part indexing partition_aggregate partition_info tuplesort explain compression memoize stats predicate - -# event_trigger depends on create_am and cannot run concurrently with -# any test that runs DDL -# oidjoins is read-only, though, and should run late for best coverage -test: oidjoins event_trigger - -# event_trigger_login cannot run concurrently with any other tests because -# on-login event handling could catch connection of a concurrent test. -test: event_trigger_login - -# this test also uses event triggers, so likewise run it by itself -test: fast_default - -# run tablespace test at the end because it drops the tablespace created during -# setup that other tests may use. -test: tablespace +test: create_index +test: stats bufchurn +# test: ministats bufchurn diff --git a/src/test/regress/sql/bufchurn.sql b/src/test/regress/sql/bufchurn.sql new file mode 100644 index 0000000000..c29ac4acf9 --- /dev/null +++ b/src/test/regress/sql/bufchurn.sql @@ -0,0 +1,22 @@ +SELECT pg_sleep(2); +CREATE TABLE t0(i int, t text); +ALTER TABLE t0 ALTER t SET STORAGE PLAIN; +INSERT INTO t0 SELECT g, g || repeat('x', 8000) FROM generate_series(1, 256) g; + +CREATE TABLE t1(i int, t text); +ALTER TABLE tl ALTER t SET STORAGE PLAIN; +INSERT INTO t1 SELECT g, g || repeat('x', 8000) FROM generate_series(1, 256) g; + +EXPLAIN ANALYZE SELECT SUM(i) FROM t0 GROUP BY t; +EXPLAIN ANALYZE SELECT SUM(i) FROM t1 GROUP BY t; + +\c - +SELECT 'SELECT pg_sleep(1);' FROM generate_series(1, 10) +\gexec + +BEGIN; +SELECT 'EXPLAIN ANALYZE SELECT SUM(i) FROM t0; EXPLAIN ANALYZE SELECT SUM(i) FROM t1;' FROM generate_series(1, 20) +\gexec + +SELECT pg_sleep(10); +ROLLBACK; diff --git a/src/test/regress/sql/stats.sql b/src/test/regress/sql/stats.sql index 399c72bbcf..fcec1be377 100644 --- a/src/test/regress/sql/stats.sql +++ b/src/test/regress/sql/stats.sql @@ -426,6 +426,7 @@ SELECT wal_bytes AS wal_bytes_before FROM pg_stat_wal \gset CREATE TEMP TABLE test_stats_temp AS SELECT 17; DROP TABLE test_stats_temp; +SELECT pg_sleep(10); -- Checkpoint twice: The checkpointer reports stats after reporting completion -- of the checkpoint. But after a second checkpoint we'll see at least the -- results of the first. @@ -632,6 +633,7 @@ SELECT sum(extends) AS my_io_sum_shared_after_extends WHERE context = 'normal' AND object = 'relation' \gset SELECT :my_io_sum_shared_after_extends > :my_io_sum_shared_before_extends; +SELECT pg_sleep(10); -- After a checkpoint, there should be some additional IOCONTEXT_NORMAL writes -- and fsyncs in the global stats (usually not for the backend). -- See comment above for rationale for two explicit CHECKPOINTs. ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-03 06:54 Shlok Kyal <[email protected]> parent: Alexander Lakhin <[email protected]> 0 siblings, 1 reply; 13+ messages in thread From: Shlok Kyal @ 2025-07-03 06:54 UTC (permalink / raw) To: Alexander Lakhin <[email protected]>; +Cc: pgsql-hackers; Andres Freund <[email protected]>; Melanie Plageman <[email protected]> On Mon, 6 Jan 2025 at 12:30, Alexander Lakhin <[email protected]> wrote: > > Hello hackers, > > I'd like to share my investigation of one mysterious stats.sql failure > occurred in December: [1]. > The difference of the failure is: > --- C:/prog/bf/root/HEAD/pgsql/src/test/regress/expected/stats.out 2024-09-18 19:31:14.665516500 +0000 > +++ C:/prog/bf/root/HEAD/pgsql.build/testrun/recovery/027_stream_regress/data/results/stats.out 2024-12-17 > 09:57:08.944588500 +0000 > @@ -1291,7 +1291,7 @@ > SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes; > ?column? > ---------- > - t > + f > (1 row) > > 027_stream_regress_primary.log contains: > 2024-12-17 09:57:06.778 UTC [8568:109] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs > FROM pg_stat_io > WHERE object = 'relation' > 2024-12-17 09:57:06.779 UTC [8568:110] pg_regress/stats LOG: statement: CREATE TABLE test_io_shared(a int); > 2024-12-17 09:57:06.780 UTC [8568:111] pg_regress/stats LOG: statement: INSERT INTO test_io_shared SELECT i FROM > generate_series(1,100)i; > ... > 2024-12-17 09:57:06.782 UTC [8568:115] pg_regress/stats LOG: statement: CHECKPOINT; > 2024-12-17 09:57:06.794 UTC [3664:40] LOG: checkpoint starting: immediate force wait > 2024-12-17 09:57:06.856 UTC [3664:41] LOG: checkpoint complete: wrote 0 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL > file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.062 s; sync files=0, longest=0.000 s, > average=0.000 s; distance=1875 kB, estimate=52682 kB; lsn=0/14A2F410, redo lsn=0/14A2F3B8 > 2024-12-17 09:57:06.857 UTC [8568:116] pg_regress/stats LOG: statement: CHECKPOINT; > 2024-12-17 09:57:06.857 UTC [3664:42] LOG: checkpoint starting: immediate force wait > 2024-12-17 09:57:06.859 UTC [3664:43] LOG: checkpoint complete: wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL > file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, > average=0.000 s; distance=0 kB, estimate=47414 kB; lsn=0/14A2F4E0, redo lsn=0/14A2F488 > 2024-12-17 09:57:06.859 UTC [8568:117] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs > FROM pg_stat_io > WHERE object = 'relation' > 2024-12-17 09:57:06.860 UTC [8568:118] pg_regress/stats LOG: statement: SELECT 77693 > 77693; > > The corresponding test case (added by 10a082bf7, dated 2023-02-11) is: > SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs > FROM pg_stat_io > WHERE object = 'relation' \gset io_sum_shared_before_ > ... > CREATE TABLE test_io_shared(a int); > INSERT INTO test_io_shared SELECT i FROM generate_series(1,100)i; > ... > CHECKPOINT; > CHECKPOINT; > ... > SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs > FROM pg_stat_get_backend_io(pg_backend_pid()) > WHERE object = 'relation' \gset my_io_sum_shared_after_ > SELECT :my_io_sum_shared_after_writes >= :my_io_sum_shared_before_writes; > > So, as we can see from the log above, both checkpoints wrote 0 buffers, > moreover, no other process/backend wrote any buffers. > > After series of experiments, I found that this situation is possible when > other backend steals shared buffers from checkpointer, without making new > buffers dirty, and then delays flushing it's statistics. > > Please find attached a reproducer for this issue: I've added two sleeps > to stats.sql and reduced parallel_schedule, but I believe it's a legal > change, which doesn't affect the test case essentially. > > With bufchurn.sql running concurrently. and TEMP_CONFIG containing > shared_buffers = 1MB (as in the 027_stream_regress test in question), I can > see exactly the same failure: > $ echo 'shared_buffers = 1MB' >/tmp/extra.config; TEMP_CONFIG=/tmp/extra.config make -s check > # +++ regress check in src/test/regress +++ > # initializing database system by copying initdb template > # using temp instance on port 65312 with PID 129700 > ok 1 - test_setup 356 ms > ok 2 - create_index 1002 ms > # parallel group (2 tests): stats bufchurn > not ok 3 + stats 21176 ms > ... > > diff -U3 .../src/test/regress/expected/stats.out .../src/test/regress/results/stats.out > --- .../src/test/regress/expected/stats.out 2025-01-06 08:03:07.720275980 +0200 > +++ .../src/test/regress/results/stats.out 2025-01-06 08:15:34.602170721 +0200 > @@ -1321,7 +1321,7 @@ > SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes; > ?column? > ---------- > - t > + f > (1 row) > ... > > [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-12-17%2008%3A59%3A44 > Hi Hackers, I have also encountered a similar buildfarm failure [1]. | 1/1 + subscription 142 ms FAIL 1/1 postgresql:regress / regress/regress ERROR 284.85s exit status 1 diff --strip-trailing-cr -U3 c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out --- c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out 2025-06-28 20:13:02 +0900 +++ c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out 2025-06-28 20:35:21 +0900 @@ -70,7 +70,7 @@ SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub'; ?column? ---------- - t + f (1 row) logs around this statement do not show unexpected thing: 2025-06-28 20:35:20.857 JST client backend[6092] pg_regress/subscription STATEMENT: CREATE SUBSCRIPTION regress_testsub CONNECTION 'testconn' PUBLICATION testpub; 2025-06-28 20:35:20.857 JST client backend[6092] pg_regress/subscription ERROR: publication name "foo" used more than once 2025-06-28 20:35:20.857 JST client backend[6092] pg_regress/subscription STATEMENT: CREATE SUBSCRIPTION regress_testsub CONNECTION 'dbname=regress_doesnotexist' PUBLICATION foo, testpub, foo WITH (connect = false); 2025-06-28 20:35:20.858 JST client backend[6092] pg_regress/subscription WARNING: subscription was created, but is not connected 2025-06-28 20:35:20.858 JST client backend[6092] pg_regress/subscription HINT: To initiate replication, you must manually create the replication slot, enable the subscription, and refresh the subscription. 2025-06-28 20:35:20.861 JST client backend[6092] pg_regress/subscription ERROR: subscription "regress_testsub" already exists In subscription.sql, I looked at the test. The statement are like: -- Reset the stats again and check if the new reset_stats is updated. SELECT stats_reset as prev_stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub' \gset SELECT pg_stat_reset_subscription_stats(oid) FROM pg_subscription WHERE subname = 'regress_testsub'; SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub'; So according to me, I suspect the following causes 1) The time difference between 'prev_stats_reset' and current 'stats_reset' value is less than 1 microseconds. 'stats_reset' is of type 'timestamp with time zone' and the content of it is like: '2025-06-30 21:01:07.925253+05:30'. So if the time difference between 'prev_stats_reset' and current 'stats_reset' is less than 1 microseconds. The query 'SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub'' might return 'false' instead of 'true'. But I was not able to reproduce such a scenario after multiple testing. Even in high end machines, it takes at least a few microseconds. Also there are multiple cases where we did similar timestamp comparison in 'stats.sql' as well. And, I didn't find any other failure related to such case. So, I feel this is not possible. 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats. We have a shared hash 'pgStatLocal.shared_hash'. If the entry reference (for the subscription) is not found while executing 'pg_stat_reset_subscription_stats(oid)'. It may not be able to reset the stats. Maybe somehow this shared hash is getting dropped.. Also, it could be failing due to the same reason as Alexander has reproduced in another case [2]. [1]: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-06-28%2011%3A02%3A30 [2]: https://www.postgresql.org/message-id/fe0391a8-dfa9-41c3-bf1c-7ea058e40f30%40gmail.com Thanks and Regards, Shlok Kyal ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-04 20:00 Alexander Lakhin <[email protected]> parent: Shlok Kyal <[email protected]> 0 siblings, 1 reply; 13+ messages in thread From: Alexander Lakhin @ 2025-07-04 20:00 UTC (permalink / raw) To: Shlok Kyal <[email protected]>; +Cc: pgsql-hackers; Andres Freund <[email protected]>; Melanie Plageman <[email protected]> Hello Shlok, 03.07.2025 09:54, Shlok Kyal wrote: > I have also encountered a similar buildfarm failure [1]. > > | 1/1 + subscription 142 ms FAIL > 1/1 postgresql:regress / regress/regress ERROR 284.85s exit status 1 > > diff --strip-trailing-cr -U3 > c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out > c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out > --- c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out > 2025-06-28 20:13:02 +0900 > +++ c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out > 2025-06-28 20:35:21 +0900 > @@ -70,7 +70,7 @@ > SELECT :'prev_stats_reset' < stats_reset FROM > pg_stat_subscription_stats WHERE subname = 'regress_testsub'; > ?column? > ---------- > - t > + f > (1 row) Thank you for your attention to this! Yes, I also noticed that failure, but could not reproduce it yet. > So according to me, I suspect the following causes > 1) The time difference between 'prev_stats_reset' and current > 'stats_reset' value is less than 1 microseconds. > 'stats_reset' is of type 'timestamp with time zone' and the content of > it is like: '2025-06-30 21:01:07.925253+05:30'. So if the time > difference between 'prev_stats_reset' and current 'stats_reset' is > less than 1 microseconds. The query 'SELECT :'prev_stats_reset' < > stats_reset FROM pg_stat_subscription_stats WHERE subname = > 'regress_testsub'' might return 'false' instead of 'true'. > But I was not able to reproduce such a scenario after multiple > testing. Even in high end machines, it takes at least a few > microseconds. Also there are multiple cases where we did similar > timestamp comparison in 'stats.sql' as well. And, I didn't find any > other failure related to such case. So, I feel this is not possible. Did you try that on Windows (hamerkop is a Windows animal)? IIUC, GetCurrentTimestamp() -> gettimeofday() implemented on Windows via GetSystemTimePreciseAsFileTime(), and it has 100ns resolution, according to [1]. I tried it on a Windows VM and saw the following numbers: SELECT :'prev_stats_reset' < stats_reset, :'prev_stats_reset', stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub'; ?column? | ?column? | stats_reset ----------+-------------------------------------+------------------------------------- t | Fri Jul 04 11:46:10.224323 2025 PDT | Fri Jul 04 11:46:10.224975 2025 PDT (1 row) that is, the difference is about 600 ns — if I could make the VM 6x faster or run the test on a bare metal, maybe I'd get the test failed. Although the overall duration of the subscription doesn't differ much: My VM: # parallel group (2 tests): subscription publication ok 164 + publication 806 ms ok 165 + subscription 210 ms vs hamerkop: # parallel group (2 tests): subscription publication ok 164 + publication 2383 ms not ok 165 + subscription 142 ms So probably the failure is caused by something else. > 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats. > We have a shared hash 'pgStatLocal.shared_hash'. If the entry > reference (for the subscription) is not found while executing > 'pg_stat_reset_subscription_stats(oid)'. It may not be able to reset > the stats. Maybe somehow this shared hash is getting dropped.. > Also, it could be failing due to the same reason as Alexander has I don't think 2) is relevant here, because shared buffers shouldn't affect subscription's statistics. [1] https://stackoverflow.com/questions/4444090/measuring-time-with-a-resolution-of-microseconds-in-c Best regards. Alexander ^ permalink raw reply [nested|flat] 13+ messages in thread
* RE: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-15 07:33 Hayato Kuroda (Fujitsu) <[email protected]> parent: Alexander Lakhin <[email protected]> 0 siblings, 1 reply; 13+ messages in thread From: Hayato Kuroda (Fujitsu) @ 2025-07-15 07:33 UTC (permalink / raw) To: 'Alexander Lakhin' <[email protected]>; Shlok Kyal <[email protected]>; +Cc: pgsql-hackers; Andres Freund <[email protected]>; Melanie Plageman <[email protected]> Dear Alexander, > > So according to me, I suspect the following causes > > 1) The time difference between 'prev_stats_reset' and current > > 'stats_reset' value is less than 1 microseconds. > > 'stats_reset' is of type 'timestamp with time zone' and the content of > > it is like: '2025-06-30 21:01:07.925253+05:30'. So if the time > > difference between 'prev_stats_reset' and current 'stats_reset' is > > less than 1 microseconds. The query 'SELECT :'prev_stats_reset' < > > stats_reset FROM pg_stat_subscription_stats WHERE subname = > > 'regress_testsub'' might return 'false' instead of 'true'. > > But I was not able to reproduce such a scenario after multiple > > testing. Even in high end machines, it takes at least a few > > microseconds. Also there are multiple cases where we did similar > > timestamp comparison in 'stats.sql' as well. And, I didn't find any > > other failure related to such case. So, I feel this is not possible. > > Did you try that on Windows (hamerkop is a Windows animal)? IIUC, > GetCurrentTimestamp() -> gettimeofday() implemented on Windows via > GetSystemTimePreciseAsFileTime(), and it has 100ns resolution, Hmm. I'm not familiar with the Windows environment, but I have the doubt for it. GetSystemTimePreciseAsFileTime() returns FILETIME structure, which represents the time UTC with 100-nanosecod intervals [1]. The stack overflow seemed to refer it. However, the document for GetSystemTimePreciseAsFileTime() says that the resolution is < 1 us [2]. Also, MS doc [3] does not say that GetSystemTimePreciseAsFileTime() returns value monotonically. Another API QueryPerformanceCounter() seems to have the monotony. A bit old document [4] also raised the possibility: ``` Consecutive calls may return the same result. The call time is less than the smallest increment of the system time. The granularity is in the sub-microsecond regime. The function may be used for time measurements but some care has to be taken: Time differences may be ZERO. ``` Also, what if the the system clock is modified during the test via NTP? > > 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats. > > We have a shared hash 'pgStatLocal.shared_hash'. If the entry > > reference (for the subscription) is not found while executing > > 'pg_stat_reset_subscription_stats(oid)'. It may not be able to reset > > the stats. Maybe somehow this shared hash is getting dropped.. > > Also, it could be failing due to the same reason as Alexander has > > I don't think 2) is relevant here, because shared buffers shouldn't affect > subscription's statistics. To confirm; we do not consider the possibility that pgstat_get_entry_ref() returns NULL right? [1]: https://learn.microsoft.com/en-us/windows/win32/api/minwinbase/ns-minwinbase-filetime [2]: https://learn.microsoft.com/en-us/windows/win32/api/sysinfoapi/nf-sysinfoapi-getsystemtimepreciseasf... [3]: https://learn.microsoft.com/en-us/windows/win32/sysinfo/acquiring-high-resolution-time-stamps [4]: http://www.windowstimestamp.com/description#:~:text=2.1.4.2.%C2%A0%C2%A0Desktop%20Applications%3A%20...) Best regards, Hayato Kuroda FUJITSU LIMITED ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-20 08:00 Alexander Lakhin <[email protected]> parent: Hayato Kuroda (Fujitsu) <[email protected]> 0 siblings, 3 replies; 13+ messages in thread From: Alexander Lakhin @ 2025-07-20 08:00 UTC (permalink / raw) To: Hayato Kuroda (Fujitsu) <[email protected]>; Yugo Nagata <[email protected]>; +Cc: pgsql-hackers; Shlok Kyal <[email protected]> Hello Kuroda-san, Thank you for your attention to this! 15.07.2025 10:33, Hayato Kuroda (Fujitsu) wrote: > GetSystemTimePreciseAsFileTime() returns FILETIME structure, which represents the > time UTC with 100-nanosecod intervals [1]. The stack overflow seemed to refer it. > However, the document for GetSystemTimePreciseAsFileTime() says that the > resolution is < 1 us [2]. Also, MS doc [3] does not say that > GetSystemTimePreciseAsFileTime() returns value monotonically. > Another API QueryPerformanceCounter() seems to have the monotony. > > A bit old document [4] also raised the possibility: > > ``` > Consecutive calls may return the same result. The call time is less than the > smallest increment of the system time. The granularity is in the sub-microsecond > regime. The function may be used for time measurements but some care has to be > taken: Time differences may be ZERO. > ``` > > Also, what if the the system clock is modified during the test via NTP? Yeah, I made a simple test for GetSystemTimePreciseAsFileTime() and confirmed that in my VM it provides sub-microsecond precision. Regarding NTP, I think the second failure of this ilk [1] makes this cause close to impossible. (Can't wait for the third one to gather more information.) >>> 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats. >>> We have a shared hash 'pgStatLocal.shared_hash'. If the entry >>> reference (for the subscription) is not found while executing >>> 'pg_stat_reset_subscription_stats(oid)'. It may not be able to reset >>> the stats. Maybe somehow this shared hash is getting dropped.. >>> Also, it could be failing due to the same reason as Alexander has >> I don't think 2) is relevant here, because shared buffers shouldn't affect >> subscription's statistics. > To confirm; we do not consider the possibility that pgstat_get_entry_ref() returns > NULL right? I've held a simple experiment with a modification like this: @@ -1078,6 +1078,7 @@ pgstat_reset_entry(PgStat_Kind kind, Oid dboid, uint64 objid, TimestampTz ts) Assert(!pgstat_get_kind_info(kind)->fixed_amount); entry_ref = pgstat_get_entry_ref(kind, dboid, objid, false, NULL); +if (rand() % 3 == 0) entry_ref = NULL; if (!entry_ref || entry_ref->shared_entry->dropped) and got several failures like: --- .../postgresql/src/test/regress/expected/subscription.out 2025-04-25 10:27:32.851554400 -0700 +++ .../postgresql/build/testrun/regress/regress/results/subscription.out 2025-07-20 00:05:05.667903300 -0700 @@ -56,7 +56,7 @@ SELECT subname, stats_reset IS NULL stats_reset_is_null FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub'; subname | stats_reset_is_null -----------------+--------------------- - regress_testsub | f + regress_testsub | t (1 row) -- Reset the stats again and check if the new reset_stats is updated. @@ -68,11 +68,9 @@ (1 row) SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub'; - ?column? ----------- - t -(1 row) - +ERROR: syntax error at or near ":" +LINE 1: SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscr... + --- .../postgresql/src/test/regress/expected/stats.out 2025-04-25 10:27:36.930322500 -0700 +++ .../postgresql/build/testrun/regress/regress/results/stats.out 2025-07-20 00:05:19.579864900 -0700 @@ -1720,7 +1720,7 @@ SELECT :my_io_stats_pre_reset > :my_io_stats_post_backend_reset; ?column? ---------- - t + f (1 row) ... Thus, if there is some issue with pgstat_get_entry_ref(), then it should be specific to subscriptions and come out in that place only (given the information we have now). So I still suspect some Windows/concrete animal's peculiarity. Nagata-san, could you please share the configuration of hamerkop? If it's running inside VM, what virtualization software is used? [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-09%2011%3A02%3A23 Best regards. Alexander ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-23 00:55 Yugo Nagata <[email protected]> parent: Alexander Lakhin <[email protected]> 2 siblings, 0 replies; 13+ messages in thread From: Yugo Nagata @ 2025-07-23 00:55 UTC (permalink / raw) To: Alexander Lakhin <[email protected]>; +Cc: Hayato Kuroda (Fujitsu) <[email protected]>; pgsql-hackers; Shlok Kyal <[email protected]>; [email protected] Hello Alexander, > Nagata-san, could you please share the configuration of hamerkop? If it's > running inside VM, what virtualization software is used? > > [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-09%2011%3A02%3A23 I am not the person in charge of it, so I added the responsible email address to the CC list. Takatsuka-san, could you please take care of this? Regards, Yugo Nagata -- Yugo Nagata <[email protected]> ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-23 04:00 Alexander Lakhin <[email protected]> parent: Alexander Lakhin <[email protected]> 2 siblings, 1 reply; 13+ messages in thread From: Alexander Lakhin @ 2025-07-23 04:00 UTC (permalink / raw) To: Hayato Kuroda (Fujitsu) <[email protected]>; +Cc: pgsql-hackers; Shlok Kyal <[email protected]>; Yugo Nagata <[email protected]> Hello Kuroda-san, 20.07.2025 11:00, Alexander Lakhin wrote: > > Yeah, I made a simple test for GetSystemTimePreciseAsFileTime() and > confirmed that in my VM it provides sub-microsecond precision. Regarding > NTP, I think the second failure of this ilk [1] makes this cause close to > impossible. (Can't wait for the third one to gather more information.) And here it is [1]: diff --strip-trailing-cr -U3 c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.out c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/results/stats.out --- c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.out 2025-07-22 20:08:30 +0900 +++ c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/results/stats.out 2025-07-22 20:30:47 +0900 @@ -3729,7 +3729,7 @@ name |pg_stat_get_function_calls|total_above_zero|self_above_zero --------------+--------------------------+----------------+--------------- -test_stat_func| 1|t |t +test_stat_func| 1|f |f (1 row) Not related to subscriptions this time, but still related to pg_stat and time measurement. There was the same looking failure on caiman, which is running on continuously updated Fedora: [2]. I could not reproduce that one either, but suspected the OS kernel: It had 6.14.0-0.rc3.20250219git6537cfb395f3.31.fc43.x86_64 at the moment of the failure and updated to 6.14.0-0.rc4.36.fc43.x86_64 on 2025-02-27. There was no failures of this kind since then. So I think we could observe such anomalies if, say, the OS kernel can't read system clock in time (stalls for a millisecond when accessing it)... [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-22%2011%3A02%3A15 [2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=caiman&dt=2025-02-23%2006%3A54%3A54 Best regards, Alexander ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-23 05:48 TAKATSUKA Haruka <[email protected]> parent: Alexander Lakhin <[email protected]> 2 siblings, 1 reply; 13+ messages in thread From: TAKATSUKA Haruka @ 2025-07-23 05:48 UTC (permalink / raw) To: Alexander Lakhin <[email protected]>; +Cc: Hayato Kuroda (Fujitsu) <[email protected]>; pgsql-hackers; Shlok Kyal <[email protected]>; [email protected] Hello Alexander, On Wed, 23 Jul 2025 00:55:37 +0000 Yugo Nagata - Buildfarm <[email protected]> wrote: > > Nagata-san, could you please share the configuration of hamerkop? If it's > > running inside VM, what virtualization software is used? It's vmware ESXi 7.0.3 (21930508). This Windows enable auto-synchronize with 'time.windows.com'. VMware Tools 12.1.5 build 20735119 is installed in the VM. Thanks, Haruka Takatsuka > > [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-09%2011%3A02%3A23 > > I am not the person in charge of it, so I added the responsible email address to the CC list. > Takatsuka-san, could you please take care of this? > > Regards, > Yugo Nagata > > -- > Yugo Nagata <[email protected]> > Cache content lost ^ permalink raw reply [nested|flat] 13+ messages in thread
* RE: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-23 06:15 Hayato Kuroda (Fujitsu) <[email protected]> parent: Alexander Lakhin <[email protected]> 0 siblings, 1 reply; 13+ messages in thread From: Hayato Kuroda (Fujitsu) @ 2025-07-23 06:15 UTC (permalink / raw) To: 'Alexander Lakhin' <[email protected]>; +Cc: pgsql-hackers; Shlok Kyal <[email protected]>; Yugo Nagata <[email protected]> Dear Alexander, > And here it is [1]: > diff --strip-trailing-cr -U3 > c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.ou > t > c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/res > ults/stats.out > --- > c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.ou > t 2025-07-22 20:08:30 +0900 > +++ > c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/res > ults/stats.out 2025-07-22 20:30:47 +0900 > @@ -3729,7 +3729,7 @@ > > name |pg_stat_get_function_calls|total_above_zero|self_above_zero > --------------+--------------------------+----------------+--------------- > -test_stat_func| 1|t |t > +test_stat_func| 1|f |f > (1 row) > > Not related to subscriptions this time, but still related to pg_stat and > time measurement. It looks like for me that we measured the execution time of the function in millisecond but it was "zero", right? > So I think we could observe such anomalies if, say, the OS kernel can't > read system clock in time (stalls for a millisecond when accessing it)... I also feel like that. But if so, how should we fix tests? We must remove all stuff which assumes the time is monotonic? Best regards, Hayato Kuroda FUJITSU LIMITED ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-23 20:00 Alexander Lakhin <[email protected]> parent: TAKATSUKA Haruka <[email protected]> 0 siblings, 1 reply; 13+ messages in thread From: Alexander Lakhin @ 2025-07-23 20:00 UTC (permalink / raw) To: TAKATSUKA Haruka <[email protected]>; +Cc: Hayato Kuroda (Fujitsu) <[email protected]>; pgsql-hackers; Shlok Kyal <[email protected]>; [email protected] Hello Takatsuka-san, 23.07.2025 08:48, TAKATSUKA Haruka wrote: > Hello Alexander, > > On Wed, 23 Jul 2025 00:55:37 +0000 > Yugo Nagata - Buildfarm<[email protected]> wrote: > >>> Nagata-san, could you please share the configuration of hamerkop? If it's >>> running inside VM, what virtualization software is used? > It's vmware ESXi 7.0.3 (21930508). > This Windows enable auto-synchronize with 'time.windows.com'. > VMware Tools 12.1.5 build 20735119 is installed in the VM. Thank you for your prompt response! I used VirtualBox, not VMWare, when trying to reproduce the issue, maybe that's the reason why I failed. It looks like VMWare has it's own specifics related to timekeeping: [1]. Maybe you could try tools.syncTime = "0" by any chance? There is also an interesting note in VMware Tools 11 docs [2]: If the clock on the guest operating system is ahead of the clock on the host, VMware Tools causes the clock on the guest to run more slowly until the clocks are synchronized. But still it's hard to say without experimentation whether this can cause the observed effect. [1] https://knowledge.broadcom.com/external/article?legacyId=1318 [2] https://techdocs.broadcom.com/us/en/vmware-cis/vsphere/tools/11-1-0/vmware-tools-administration-11-1... Best regards, Alexander ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-24 00:49 TAKATSUKA Haruka <[email protected]> parent: Alexander Lakhin <[email protected]> 0 siblings, 0 replies; 13+ messages in thread From: TAKATSUKA Haruka @ 2025-07-24 00:49 UTC (permalink / raw) To: Alexander Lakhin <[email protected]>; +Cc: Hayato Kuroda (Fujitsu) <[email protected]>; pgsql-hackers; Shlok Kyal <[email protected]>; [email protected] On Wed, 23 Jul 2025 23:00:00 +0300 Alexander Lakhin <[email protected]> wrote: {snip} > >>> Nagata-san, could you please share the configuration of hamerkop? If it's > >>> running inside VM, what virtualization software is used? > > It's vmware ESXi 7.0.3 (21930508). > > This Windows enable auto-synchronize with 'time.windows.com'. > > VMware Tools 12.1.5 build 20735119 is installed in the VM. > > Thank you for your prompt response! > > I used VirtualBox, not VMWare, when trying to reproduce the issue, maybe > that's the reason why I failed. It looks like VMWare has it's own > specifics related to timekeeping: [1]. > > Maybe you could try tools.syncTime = "0" by any chance? It has been already tools.syncTime = "0" so far. I confirmed the following GUI setting. VM Options VMware Tools Time "Synchronize guest time with host": unchecked Thanks, Haruka Takatsuka ^ permalink raw reply [nested|flat] 13+ messages in thread
* Re: stats.sql might fail due to shared buffers also used by parallel tests @ 2025-07-26 09:00 Alexander Lakhin <[email protected]> parent: Hayato Kuroda (Fujitsu) <[email protected]> 0 siblings, 0 replies; 13+ messages in thread From: Alexander Lakhin @ 2025-07-26 09:00 UTC (permalink / raw) To: Hayato Kuroda (Fujitsu) <[email protected]>; TAKATSUKA Haruka <[email protected]>; +Cc: pgsql-hackers; Shlok Kyal <[email protected]>; Yugo Nagata <[email protected]> Hello Kuroda-san and Takatsuka-san, 24.07.2025 03:49, TAKATSUKA Haruka wrote: > {snip} >> Maybe you could try tools.syncTime = "0" by any chance? > It has been already tools.syncTime = "0" so far. > I confirmed the following GUI setting. > ... 23.07.2025 09:15, Hayato Kuroda (Fujitsu) wrote: > It looks like for me that we measured the execution time of the function in > millisecond but it was "zero", right? Yes, my understanding is the same. >> So I think we could observe such anomalies if, say, the OS kernel can't >> read system clock in time (stalls for a millisecond when accessing it)... > I also feel like that. But if so, how should we fix tests? We must remove all > stuff which assumes the time is monotonic? From what Takatsuka-san shared on hamerkop's configuration, I still suspect there could be some platform specifics there. I've found another interesting reading on the subject, which describes effects of CPU pressure and mentions other low-level parameters, e. g. monitor_control.virtual_rdtsc: [1]. Probably there could be some experiments performed there to measure the maximum timer resolution (e. g. with a simple program attached). I also observed a failure of pg_stat_statements on ARMv7 device in the past: --- .../contrib/pg_stat_statements/expected/entry_timestamp.out 2024-04-11 07:20:32.563588101 +0300 +++ .../contrib/pg_stat_statements/results/entry_timestamp.out 2024-04-15 11:16:00.217396694 +0300 @@ -45,7 +45,7 @@ WHERE query LIKE '%STMTTS%'; total | minmax_plan_zero | minmax_exec_zero | minmax_stats_since_after_ref | stats_since_after_ref -------+------------------+------------------+------------------------------+----------------------- - 2 | 0 | 0 | 0 | 0 + 2 | 0 | 1 | 0 | 0 (1 row) with clocksource = 32k_counter, which gave me the maximum resolution 0.030517 sec. So if to choose fixing tests, then it's not clear to me, what lowest timer resolution to consider acceptable. [1] https://www.vmware.com/docs/vmware_timekeeping Best regards, Alexander Attachments: [text/x-csrc] test-gst.c (951B, ../../[email protected]/3-test-gst.c) download | inline: #include <windows.h> #define FILETIME_UNITS_PER_SEC 10000000L #define FILETIME_UNITS_PER_USEC 10 void main(int argc, char *argv[]) { FILETIME ft1, ft2; ULARGE_INTEGER uli1, uli2; int r = 0; int n = (argc > 1) ? atol(argv[1]) : 0; GetSystemTimePreciseAsFileTime(&ft1); for (long int i = 0; i < n; i++) r += i; GetSystemTimePreciseAsFileTime(&ft2); uli1.LowPart = ft1.dwLowDateTime; uli1.HighPart = ft1.dwHighDateTime; long usec1 = (long) (((uli1.QuadPart) % FILETIME_UNITS_PER_SEC) / FILETIME_UNITS_PER_USEC); uli2.LowPart = ft2.dwLowDateTime; uli2.HighPart = ft2.dwHighDateTime; long usec2 = (long) (((uli2.QuadPart) % FILETIME_UNITS_PER_SEC) / FILETIME_UNITS_PER_USEC); printf("usec1: %llu, usec2: %llu, usec2 - usec1: %d, uli2 - uli1: %ld, r: %d\n", usec1, usec2, usec2 - usec1, (long)(uli2.QuadPart - uli1.QuadPart), r); } ^ permalink raw reply [nested|flat] 13+ messages in thread
end of thread, other threads:[~2025-07-26 09:00 UTC | newest] Thread overview: 13+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2020-03-13 07:59 [PATCH v46 3/7] Make archiver process an auxiliary process Kyotaro Horiguchi <[email protected]> 2025-01-06 07:00 stats.sql might fail due to shared buffers also used by parallel tests Alexander Lakhin <[email protected]> 2025-07-03 06:54 ` Re: stats.sql might fail due to shared buffers also used by parallel tests Shlok Kyal <[email protected]> 2025-07-04 20:00 ` Re: stats.sql might fail due to shared buffers also used by parallel tests Alexander Lakhin <[email protected]> 2025-07-15 07:33 ` RE: stats.sql might fail due to shared buffers also used by parallel tests Hayato Kuroda (Fujitsu) <[email protected]> 2025-07-20 08:00 ` Re: stats.sql might fail due to shared buffers also used by parallel tests Alexander Lakhin <[email protected]> 2025-07-23 00:55 ` Re: stats.sql might fail due to shared buffers also used by parallel tests Yugo Nagata <[email protected]> 2025-07-23 04:00 ` Re: stats.sql might fail due to shared buffers also used by parallel tests Alexander Lakhin <[email protected]> 2025-07-23 06:15 ` RE: stats.sql might fail due to shared buffers also used by parallel tests Hayato Kuroda (Fujitsu) <[email protected]> 2025-07-26 09:00 ` Re: stats.sql might fail due to shared buffers also used by parallel tests Alexander Lakhin <[email protected]> 2025-07-23 05:48 ` Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests TAKATSUKA Haruka <[email protected]> 2025-07-23 20:00 ` Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests Alexander Lakhin <[email protected]> 2025-07-24 00:49 ` Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests TAKATSUKA Haruka <[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