Hello!
Found a periodic spike growth of the checkpoint_req counter on replica by 20-30
units
after large insert (~350Mb) on master.
Reproduction on master and replica with default conf:
1) execute the command "insert into test values (generate_series(1,1E7));".
This leads to the table's growth by about 350Mb during about 15 secs (on my pc).
2)The wal records start coming to the replica, and when their number exceeds a
certain limit, a request is emitted to the checkpointer process to create
restartpoint on the replica and checkpoint_req is incremented. With default
settings, this limit is 42 segments.
3) Restartpoint creation fails because a new restartpoint can only be created
if the replica has received new WAL records about the checkpoint from the
moment of the previous restartpoint. But there were no such records.
4) When the next WAL segment is received by replica, the next request is
generated to create a restartpoint on the replica, and so on.
5) Finally, a WAL record about the checkpoint arrives on the replica,
restartpoint is created and the growth of checkpoint_req stops.
The described process can be observed in the log with additional debugging. See
insert_1E7_once.log attached. This
log is for v13 but master has the same behavior.
Can we treat such behavior as a bug?
If so it seems possible to check if a creating of restartpoint is obviously
impossible before sending request and don't send it at all if so.
The patch applied tries to fix it.
With best regards.
--
Anton A. Melnikov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
022-09-04 21:09:45.160 MSK [2424110] LOG: Start CFS version 0.54 supported compression algorithms pglz,zlib encryption disabled GC enabled
2022-09-04 21:09:45.168 MSK [2424110] LOG: starting PostgreSQL 13.6 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit
2022-09-04 21:09:45.168 MSK [2424110] LOG: listening on IPv4 address "0.0.0.0", port 54131
2022-09-04 21:09:45.168 MSK [2424110] LOG: listening on IPv6 address "::", port 54131
2022-09-04 21:09:45.177 MSK [2424110] LOG: listening on Unix socket "/tmp/.s.PGSQL.54131"
2022-09-04 21:09:45.187 MSK [2424150] LOG: database system was interrupted; last known up at 2022-09-04 21:09:44 MSK
2022-09-04 21:09:45.282 MSK [2424150] LOG: entering standby mode
2022-09-04 21:09:45.292 MSK [2424150] LOG: redo starts at 0/2000028
2022-09-04 21:09:45.296 MSK [2424150] LOG: consistent recovery state reached at 0/2000198
2022-09-04 21:09:45.296 MSK [2424110] LOG: database system is ready to accept read only connections
2022-09-04 21:09:45.307 MSK [2424233] LOG: started streaming WAL from primary at 0/3000000 on timeline 1
2022-09-04 21:09:45.341 MSK [2424259] LOG: Start 1 background garbage collection workers for CFS
2022-09-04 21:10:26.653 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 43, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:10:26.653 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 0, done: 0, failed: 0.
Now: 41. Last_chkpt_time: 0. Elapsed secs: 41. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:10:26.653 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:10:26.669 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:10:28.926 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 44, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:10:28.926 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 1, done: 1, failed: 0.
Now: 43. Last_chkpt_time: -244. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:10:28.926 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:10:29.176 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:10:30.014 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 45, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:10:30.014 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 2, done: 2, failed: 0.
Now: 45. Last_chkpt_time: -242. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:10:30.014 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:10:30.058 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:10:45.072 MSK [2424224] LOG: @@@@@@@@@@@@Checkpoint requested by time! Now: 60. Last_chkpt_time: -240. Elapsed secs: 300. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:10:45.072 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:10:45.077 MSK [2424224] LOG: !!!Checkpoint NOT performed!!!
2022-09-04 21:11:00.092 MSK [2424224] LOG: @@@@@@@@@@@@Checkpoint requested by time! Now: 75. Last_chkpt_time: -225. Elapsed secs: 300. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:00.092 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:00.092 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:15.104 MSK [2424224] LOG: @@@@@@@@@@@@Checkpoint requested by time! Now: 90. Last_chkpt_time: -210. Elapsed secs: 300. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:15.104 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:15.113 MSK [2424224] LOG: !!!Checkpoint NOT performed!!!
2022-09-04 21:11:16.187 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 46, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:16.187 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 6, done: 6, failed: 0.
Now: 91. Last_chkpt_time: -195. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:16.188 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:16.192 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:17.455 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 47, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:17.455 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 7, done: 7, failed: 0.
Now: 92. Last_chkpt_time: -194. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:17.455 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:17.459 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:18.672 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 48, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:18.672 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 8, done: 8, failed: 0.
Now: 93. Last_chkpt_time: -193. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:18.672 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:18.676 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:20.049 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 49, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:20.049 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 9, done: 9, failed: 0.
Now: 95. Last_chkpt_time: -192. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:20.049 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:20.054 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:21.405 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 50, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:21.405 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 10, done: 10, failed: 0.
Now: 96. Last_chkpt_time: -190. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:21.405 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:21.411 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:22.939 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 51, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:22.939 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 11, done: 11, failed: 0.
Now: 97. Last_chkpt_time: -189. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:22.939 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:22.944 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:24.395 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 52, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:24.395 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 12, done: 12, failed: 0.
Now: 99. Last_chkpt_time: -188. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:24.395 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:24.400 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:25.860 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 53, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:25.861 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 13, done: 13, failed: 0.
Now: 100. Last_chkpt_time: -186. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:25.861 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:25.865 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:27.336 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 54, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:27.336 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 14, done: 14, failed: 0.
Now: 102. Last_chkpt_time: -185. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:27.336 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:27.343 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:28.797 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 55, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:28.798 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 15, done: 15, failed: 0.
Now: 103. Last_chkpt_time: -183. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:28.798 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:28.802 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:31.371 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 56, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:31.372 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 16, done: 16, failed: 0.
Now: 106. Last_chkpt_time: -182. Elapsed secs: 288. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:31.372 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:31.378 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:32.836 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 57, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:32.836 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 17, done: 17, failed: 0.
Now: 107. Last_chkpt_time: -179. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:32.836 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:32.841 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:34.323 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 58, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:34.324 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 18, done: 18, failed: 0.
Now: 109. Last_chkpt_time: -178. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:34.324 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:34.328 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:35.754 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 59, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:35.754 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 19, done: 19, failed: 0.
Now: 110. Last_chkpt_time: -176. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:35.754 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:35.761 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:36.737 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 60, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:36.737 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 20, done: 20, failed: 0.
Now: 111. Last_chkpt_time: -175. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:36.737 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:36.741 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:37.750 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 61, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:37.750 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 21, done: 21, failed: 0.
Now: 112. Last_chkpt_time: -174. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:37.750 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:37.756 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:38.799 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 62, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:38.799 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 22, done: 22, failed: 0.
Now: 113. Last_chkpt_time: -173. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:38.799 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:38.807 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:39.749 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 63, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:39.749 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 23, done: 23, failed: 0.
Now: 114. Last_chkpt_time: -172. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:39.749 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:39.755 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:40.839 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 64, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:40.839 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 24, done: 24, failed: 0.
Now: 115. Last_chkpt_time: -171. Elapsed secs: 286. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:40.839 MSK [2424224] LOG: !!!This is restartpoint!!!
2022-09-04 21:11:40.844 MSK [2424224] LOG: !!!Restartpoint NOT performed!!!
2022-09-04 21:11:42.205 MSK [2424150] LOG: &&&&&&&&&&&&&&&&!!!Request a restartpoint if we've replayed too much xlog!!!
readSegNo: 65, old_segno: 2, CheckPointSegments: 42
2022-09-04 21:11:42.205 MSK [2424224] LOG: Checkpoint requested by wal. Checkpoints already started: 25, done: 25, failed: 0.
Now: 117. Last_chkpt_time: -170. Elapsed secs: 287. CheckPointTimeout: 300. CheckPointWarning: 30
2022-09-04 21:11:42.205 MSK [2424224] LOG: !!!This is restartpoint!!!
commit 62b447282d7436642984005627f966f93f4a2439
Author: Anton A. Melnikov <a.melni...@postgrespro.ru>
Date: Tue Sep 6 12:18:56 2022 +0300
Remove burst growth of the checkpoint_req on replica.
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 7a710e6490..0c7510bca5 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -8880,3 +8880,24 @@ SetWalWriterSleeping(bool sleeping)
XLogCtl->WalWriterSleeping = sleeping;
SpinLockRelease(&XLogCtl->info_lck);
}
+
+/*
+ * Update the WalWriterSleeping flag.
+ */
+bool IsNewCheckpointWALRecs(void)
+{
+ bool result = false;
+ /*
+ * Get the last safe checkpoint record and check if
+ * there is a new checkpoint WAL records since the
+ * last restartpoint.
+ */
+ SpinLockAcquire(&XLogCtl->info_lck);
+ if (!XLogRecPtrIsInvalid(XLogCtl->lastCheckPointRecPtr)
+ && XLogCtl->lastCheckPoint.redo >
+ ControlFile->checkPointCopy.redo)
+ result = true;
+ SpinLockRelease(&XLogCtl->info_lck);
+
+ return result;
+}
diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c
index ae2af5ae3d..2502e4f726 100644
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -3194,7 +3194,15 @@ XLogPageRead(XLogReaderState *xlogreader, XLogRecPtr targetPagePtr, int reqLen,
{
(void) GetRedoRecPtr();
if (XLogCheckpointNeeded(readSegNo))
- RequestCheckpoint(CHECKPOINT_CAUSE_XLOG);
+ {
+ /*
+ * If there is no new checkpoint WAL records since the
+ * last restartpoint the creation of new one
+ * will certainly fail, so skip it.
+ */
+ if (IsNewCheckpointWALRecs())
+ RequestCheckpoint(CHECKPOINT_CAUSE_XLOG);
+ }
}
}
diff --git a/src/include/access/xlogrecovery.h b/src/include/access/xlogrecovery.h
index 0aa85d90e8..d1431ab9b0 100644
--- a/src/include/access/xlogrecovery.h
+++ b/src/include/access/xlogrecovery.h
@@ -82,6 +82,7 @@ extern void XLogRecoveryShmemInit(void);
extern void InitWalRecovery(ControlFileData *ControlFile, bool *wasShutdownPtr, bool *haveBackupLabel, bool *haveTblspcMap);
extern void PerformWalRecovery(void);
+extern bool IsNewCheckpointWALRecs(void);
/*
* FinishWalRecovery() returns this. It contains information about the point
