Re: O(n^2) system calls in RemoveOldXlogFiles()
Hi, Thanks for pushing! Sorry to not get around to a review before... On 2021-01-15 11:42:50 +0900, Michael Paquier wrote: > On Fri, Jan 15, 2021 at 03:25:24PM +1300, Thomas Munro wrote: > > Thanks Michael! Another notch for the unnecessary system call > > hitlist: https://wiki.postgresql.org/wiki/Syscall_Reduction > > A quick question. How much does it matter in terms of > micro-performance for this code path depending on max/min_wal_size? I can't see it being a problem here. Disision-by-non-constant is expensive, but syscalls are more expensive. And journalled filesystem operations like renames are *much* more expensive. > Andres has mentioned its aio work, without telling any numbers. I only found it while working on the AIO stuff, it's not really dependant on it. I saw significant performance drops in the last part of a checkpoint in both aio / master, but additional debugging output I had in the aio branch made it obvious that it's not actuall the buffer sync where the time is spent. > "No backpatch is done per the lack of field complaints." Because there's no real way to attribute the slowdown to WAL file recycling in production workloads on master, I don't think we could really expect field complaints. Everyone will just attribute the slowdown to BufferSync() or file sync. I think the way we currently emit WAL timings is quite quite unhelpful. The fact that we attribute CheckpointWriteDelay() to the write time makes it nearly useless until you're at the point the checkpoint can't be completed in time. Similarly, the "sync" time" covers many things that aren't syncing... Greetings, Andres Freund
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Fri, Jan 15, 2021 at 03:25:24PM +1300, Thomas Munro wrote: > Thanks Michael! Another notch for the unnecessary system call > hitlist: https://wiki.postgresql.org/wiki/Syscall_Reduction A quick question. How much does it matter in terms of micro-performance for this code path depending on max/min_wal_size? Andres has mentioned its aio work, without telling any numbers. -- Michael signature.asc Description: PGP signature
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Fri, Jan 15, 2021 at 3:07 PM Michael Paquier wrote: > On Wed, Jan 13, 2021 at 04:27:25PM +0900, Michael Paquier wrote: > > I have been looking again at that, and the rebased version that Andres > > has provided would take care of that. Any thoughts? > > Hearing nothing, I have applied the thing on HEAD after more tests and > more reads of the code. Thanks Michael! Another notch for the unnecessary system call hitlist: https://wiki.postgresql.org/wiki/Syscall_Reduction
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Wed, Jan 13, 2021 at 04:27:25PM +0900, Michael Paquier wrote: > I have been looking again at that, and the rebased version that Andres > has provided would take care of that. Any thoughts? Hearing nothing, I have applied the thing on HEAD after more tests and more reads of the code. -- Michael signature.asc Description: PGP signature
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Tue, Jan 12, 2021 at 12:10:24PM -0300, Alvaro Herrera wrote: > Apparently b2a5545bd63f changed; before that commit, that code > (including the quoted comment) was all in RemoveOldXlogFiles, and > endlogSegNo was calculated only once. But ISTM that even with that > formulation it had the problem you point out. The real problem is the > loop hidden inside InstallXLogFileSegment(). I am not sure to get your point here. The purposes of the two incrementations in InstallXLogFileSegment() and RemoveXlogFile() are different, still the former incrementation makes the recycling done by the latter faster, -- Michael signature.asc Description: PGP signature
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Tue, Jan 12, 2021 at 11:30:13PM +1300, Thomas Munro wrote:
> I haven't heard any user complaints, and I'd personally be happy with
> a fix on master only.
I have been looking again at that, and the rebased version that Andres
has provided would take care of that. Any thoughts?
--
Michael
From 0a8fb2599283b9703466b79f0fd490b3a565ff62 Mon Sep 17 00:00:00 2001
From: Michael Paquier
Date: Wed, 13 Jan 2021 16:23:57 +0900
Subject: [PATCH] Fix O(recycled_segments^2) stat() calls while recycling WAL
files.
Author: Michael Paquier
Reviewed-By: Andres Freund
Discussion: https://postgr.es/m/CAB7nPqTB3VcKSSrW2Qj59tYYR2H4+n=5pzbdwou+x9iqvnm...@mail.gmail.com
Backpatch:
---
src/backend/access/transam/xlog.c | 60 +++
1 file changed, 30 insertions(+), 30 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index b18257c198..1bc6c9683d 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -930,7 +930,7 @@ static void XLogFileClose(void);
static void PreallocXlogFiles(XLogRecPtr endptr);
static void RemoveTempXlogFiles(void);
static void RemoveOldXlogFiles(XLogSegNo segno, XLogRecPtr lastredoptr, XLogRecPtr endptr);
-static void RemoveXlogFile(const char *segname, XLogRecPtr lastredoptr, XLogRecPtr endptr);
+static void RemoveXlogFile(const char *segname, XLogSegNo *endlogSegNo, XLogSegNo recycleSegNo);
static void UpdateLastRemovedPtr(char *filename);
static void ValidateXLOGDirectoryStructure(void);
static void CleanupBackupHistory(void);
@@ -4055,6 +4055,12 @@ RemoveOldXlogFiles(XLogSegNo segno, XLogRecPtr lastredoptr, XLogRecPtr endptr)
DIR *xldir;
struct dirent *xlde;
char lastoff[MAXFNAMELEN];
+ XLogSegNo endlogSegNo;
+ XLogSegNo recycleSegNo;
+
+ /* Initialize info about where to try to recycle to */
+ XLByteToSeg(endptr, endlogSegNo, wal_segment_size);
+ recycleSegNo = XLOGfileslop(lastredoptr);
/*
* Construct a filename of the last segment to be kept. The timeline ID
@@ -4093,7 +4099,7 @@ RemoveOldXlogFiles(XLogSegNo segno, XLogRecPtr lastredoptr, XLogRecPtr endptr)
/* Update the last removed location in shared memory first */
UpdateLastRemovedPtr(xlde->d_name);
-RemoveXlogFile(xlde->d_name, lastredoptr, endptr);
+RemoveXlogFile(xlde->d_name, , recycleSegNo);
}
}
}
@@ -4123,13 +4129,21 @@ RemoveNonParentXlogFiles(XLogRecPtr switchpoint, TimeLineID newTLI)
struct dirent *xlde;
char switchseg[MAXFNAMELEN];
XLogSegNo endLogSegNo;
+ XLogSegNo switchLogSegNo;
+ XLogSegNo recycleSegNo;
- XLByteToPrevSeg(switchpoint, endLogSegNo, wal_segment_size);
+ /*
+ * Initialize info about where to begin the work. This will recycle,
+ * somewhat arbitrarily, 10 future segments.
+ */
+ XLByteToPrevSeg(switchpoint, switchLogSegNo, wal_segment_size);
+ XLByteToSeg(switchpoint, endLogSegNo, wal_segment_size);
+ recycleSegNo = endLogSegNo + 10;
/*
* Construct a filename of the last segment to be kept.
*/
- XLogFileName(switchseg, newTLI, endLogSegNo, wal_segment_size);
+ XLogFileName(switchseg, newTLI, switchLogSegNo, wal_segment_size);
elog(DEBUG2, "attempting to remove WAL segments newer than log file %s",
switchseg);
@@ -4157,7 +4171,7 @@ RemoveNonParentXlogFiles(XLogRecPtr switchpoint, TimeLineID newTLI)
* - but seems safer to let them be archived and removed later.
*/
if (!XLogArchiveIsReady(xlde->d_name))
-RemoveXlogFile(xlde->d_name, InvalidXLogRecPtr, switchpoint);
+RemoveXlogFile(xlde->d_name, , recycleSegNo);
}
}
@@ -4167,36 +4181,22 @@ RemoveNonParentXlogFiles(XLogRecPtr switchpoint, TimeLineID newTLI)
/*
* Recycle or remove a log file that's no longer needed.
*
- * endptr is current (or recent) end of xlog, and lastredoptr is the
- * redo pointer of the last checkpoint. These are used to determine
- * whether we want to recycle rather than delete no-longer-wanted log files.
- * If lastredoptr is not known, pass invalid, and the function will recycle,
- * somewhat arbitrarily, 10 future segments.
+ * segname is the name of the segment to recycle or remove. endlogSegNo
+ * is the segment number of the current (or recent) end of WAL. recycleSegNo
+ * is the segment number to recycle up to.
+ *
+ * endlogSegNo gets incremented if the segment is recycled so as it is not
+ * checked again with future callers of this function.
*/
static void
-RemoveXlogFile(const char *segname, XLogRecPtr lastredoptr, XLogRecPtr endptr)
+RemoveXlogFile(const char *segname, XLogSegNo *endlogSegNo,
+ XLogSegNo recycleSegNo)
{
char path[MAXPGPATH];
#ifdef WIN32
char newpath[MAXPGPATH];
#endif
struct stat statbuf;
- XLogSegNo endlogSegNo;
- XLogSegNo recycleSegNo;
-
- if (wal_recycle)
- {
- /*
- * Initialize info about where to try to recycle to.
- */
- XLByteToSeg(endptr, endlogSegNo, wal_segment_size);
- if (lastredoptr == InvalidXLogRecPtr)
- recycleSegNo = endlogSegNo + 10;
Re: O(n^2) system calls in RemoveOldXlogFiles()
On 2021-Jan-11, Thomas Munro wrote: > I didn't check the migration history of this code but it seems that > endlogSegNo doesn't currently have the right scoping to achieve the > goal of that last comment, so checkpoints finish up repeatedly search > for the next free slot, starting at the low end each time, Apparently b2a5545bd63f changed; before that commit, that code (including the quoted comment) was all in RemoveOldXlogFiles, and endlogSegNo was calculated only once. But ISTM that even with that formulation it had the problem you point out. The real problem is the loop hidden inside InstallXLogFileSegment(). -- Álvaro Herrera
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Tue, Jan 12, 2021 at 8:27 PM Michael Paquier wrote: > Yeah, this rings a bell. I never went back to it even if the thing > looks rather clean at quick glance (not tested), but I may be able > to spend some cycles on that. I don't think that's critical enough > for a backpatch, so doing something only on HEAD is fine by me. > What's your take? I haven't heard any user complaints, and I'd personally be happy with a fix on master only.
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Tue, Jan 12, 2021 at 07:15:21PM +1300, Thomas Munro wrote: > Hah, I even knew that, apparently, but forgot. Adding Michael who > wrote a patch. It'd be nice to fix this, at least in 14. Yeah, this rings a bell. I never went back to it even if the thing looks rather clean at quick glance (not tested), but I may be able to spend some cycles on that. I don't think that's critical enough for a backpatch, so doing something only on HEAD is fine by me. What's your take? -- Michael signature.asc Description: PGP signature
Re: O(n^2) system calls in RemoveOldXlogFiles()
On Tue, Jan 12, 2021 at 6:55 PM Andres Freund wrote: > I found this before as well: > https://postgr.es/m/CAB7nPqTB3VcKSSrW2Qj59tYYR2H4+n=5pzbdwou+x9iqvnm...@mail.gmail.com Hah, I even knew that, apparently, but forgot. Adding Michael who wrote a patch. It'd be nice to fix this, at least in 14.
Re: O(n^2) system calls in RemoveOldXlogFiles()
Hi,
On 2021-01-11 16:35:56 +1300, Thomas Munro wrote:
> I noticed that RemoveXlogFile() has this code:
>
> /*
> * Before deleting the file, see if it can be recycled as a future log
> * segment. Only recycle normal files, pg_standby for example can
> create
> * symbolic links pointing to a separate archive directory.
> */
> if (wal_recycle &&
> endlogSegNo <= recycleSegNo &&
> lstat(path, ) == 0 && S_ISREG(statbuf.st_mode) &&
> InstallXLogFileSegment(, path,
>true,
> recycleSegNo, true))
> {
> ereport(DEBUG2,
> (errmsg("recycled write-ahead log file
> \"%s\"",
> segname)));
> CheckpointStats.ckpt_segs_recycled++;
> /* Needn't recheck that slot on future iterations */
> endlogSegNo++;
> }
>
> I didn't check the migration history of this code but it seems that
> endlogSegNo doesn't currently have the right scoping to achieve the
> goal of that last comment, so checkpoints finish up repeatedly search
> for the next free slot, starting at the low end each time, like so:
>
> stat("pg_wal/0001004F", {st_mode=S_IFREG|0600,
> st_size=16777216, ...}) = 0
> ...
> stat("pg_wal/00010073", 0x7fff98b9e060) = -1 ENOENT
> (No such file or directory)
>
> stat("pg_wal/0001004F", {st_mode=S_IFREG|0600,
> st_size=16777216, ...}) = 0
> ...
> stat("pg_wal/00010074", 0x7fff98b9e060) = -1 ENOENT
> (No such file or directory)
>
> ... and so on until we've recycled all our recyclable segments. Ouch.
I found this before as well:
https://postgr.es/m/CAB7nPqTB3VcKSSrW2Qj59tYYR2H4+n=5pzbdwou+x9iqvnm...@mail.gmail.com
I did put a hastily rebased version of that commit in my aio branch
during development:
https://github.com/anarazel/postgres/commit/b3cc8adacf7860add8cc62ec373ac955d9d12992
Greetings,
Andres Freund
O(n^2) system calls in RemoveOldXlogFiles()
Hi,
I noticed that RemoveXlogFile() has this code:
/*
* Before deleting the file, see if it can be recycled as a future log
* segment. Only recycle normal files, pg_standby for example can create
* symbolic links pointing to a separate archive directory.
*/
if (wal_recycle &&
endlogSegNo <= recycleSegNo &&
lstat(path, ) == 0 && S_ISREG(statbuf.st_mode) &&
InstallXLogFileSegment(, path,
true,
recycleSegNo, true))
{
ereport(DEBUG2,
(errmsg("recycled write-ahead log file \"%s\"",
segname)));
CheckpointStats.ckpt_segs_recycled++;
/* Needn't recheck that slot on future iterations */
endlogSegNo++;
}
I didn't check the migration history of this code but it seems that
endlogSegNo doesn't currently have the right scoping to achieve the
goal of that last comment, so checkpoints finish up repeatedly search
for the next free slot, starting at the low end each time, like so:
stat("pg_wal/0001004F", {st_mode=S_IFREG|0600,
st_size=16777216, ...}) = 0
...
stat("pg_wal/00010073", 0x7fff98b9e060) = -1 ENOENT
(No such file or directory)
stat("pg_wal/0001004F", {st_mode=S_IFREG|0600,
st_size=16777216, ...}) = 0
...
stat("pg_wal/00010074", 0x7fff98b9e060) = -1 ENOENT
(No such file or directory)
... and so on until we've recycled all our recyclable segments. Ouch.
