public inbox for [email protected]  
help / color / mirror / Atom feed
[PATCH v4 2/2] Do COPY FROM encoding conversion/verification in larger chunks.
40+ messages / 5 participants
[nested] [flat]

* [PATCH v4 2/2] Do COPY FROM encoding conversion/verification in larger chunks.
@ 2021-02-07 18:09  Heikki Linnakangas <[email protected]>
  0 siblings, 0 replies; 40+ messages in thread

From: Heikki Linnakangas @ 2021-02-07 18:09 UTC (permalink / raw)

NOTE: This changes behavior in one corner-case: if client and server
encodings are the same single-byte encoding (e.g. latin1), previously the
input would not be checked for zero bytes ('\0'). Any fields containing
zero bytes would be truncated at the zero. But if encoding conversion was
needed, the conversion routine would throw an error on the zero. After
this commit, the input is always checked for zeros.
---
 src/backend/commands/copyfrom.c          |  80 ++--
 src/backend/commands/copyfromparse.c     | 515 +++++++++++++++++------
 src/include/commands/copyfrom_internal.h |  62 +--
 src/include/mb/pg_wchar.h                |  22 +-
 4 files changed, 500 insertions(+), 179 deletions(-)

diff --git a/src/backend/commands/copyfrom.c b/src/backend/commands/copyfrom.c
index c39cc736ed2..37bbf7dc293 100644
--- a/src/backend/commands/copyfrom.c
+++ b/src/backend/commands/copyfrom.c
@@ -3,6 +3,12 @@
  * copyfrom.c
  *		COPY <table> FROM file/program/client
  *
+ * This file contains routines needed to efficiently load tuples into a
+ * table.  That includes looking up the correct partition, firing triggers,
+ * calling the table AM function to insert the data, and updating indexes.
+ * Reading data from the input file or client and parsing it into Datums
+ * is handled in copyfromparse.c.
+ *
  * Portions Copyright (c) 1996-2021, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
@@ -23,6 +29,7 @@
 #include "access/tableam.h"
 #include "access/xact.h"
 #include "access/xlog.h"
+#include "catalog/namespace.h"
 #include "commands/copy.h"
 #include "commands/copyfrom_internal.h"
 #include "commands/progress.h"
@@ -87,7 +94,7 @@ typedef struct CopyMultiInsertInfo
 	List	   *multiInsertBuffers; /* List of tracked CopyMultiInsertBuffers */
 	int			bufferedTuples; /* number of tuples buffered over all buffers */
 	int			bufferedBytes;	/* number of bytes from all buffered tuples */
-	CopyFromState	cstate;			/* Copy state for this CopyMultiInsertInfo */
+	CopyFromState cstate;		/* Copy state for this CopyMultiInsertInfo */
 	EState	   *estate;			/* Executor state used for COPY */
 	CommandId	mycid;			/* Command Id used for COPY */
 	int			ti_options;		/* table insert options */
@@ -107,7 +114,7 @@ static void ClosePipeFromProgram(CopyFromState cstate);
 void
 CopyFromErrorCallback(void *arg)
 {
-	CopyFromState	cstate = (CopyFromState) arg;
+	CopyFromState cstate = (CopyFromState) arg;
 	char		curlineno_str[32];
 
 	snprintf(curlineno_str, sizeof(curlineno_str), UINT64_FORMAT,
@@ -149,15 +156,9 @@ CopyFromErrorCallback(void *arg)
 			/*
 			 * Error is relevant to a particular line.
 			 *
-			 * If line_buf still contains the correct line, and it's already
-			 * transcoded, print it. If it's still in a foreign encoding, it's
-			 * quite likely that the error is precisely a failure to do
-			 * encoding conversion (ie, bad data). We dare not try to convert
-			 * it, and at present there's no way to regurgitate it without
-			 * conversion. So we have to punt and just report the line number.
+			 * If line_buf still contains the correct line, print it.
 			 */
-			if (cstate->line_buf_valid &&
-				(cstate->line_buf_converted || !cstate->need_transcoding))
+			if (cstate->line_buf_valid)
 			{
 				char	   *lineval;
 
@@ -300,7 +301,7 @@ CopyMultiInsertBufferFlush(CopyMultiInsertInfo *miinfo,
 	MemoryContext oldcontext;
 	int			i;
 	uint64		save_cur_lineno;
-	CopyFromState	cstate = miinfo->cstate;
+	CopyFromState cstate = miinfo->cstate;
 	EState	   *estate = miinfo->estate;
 	CommandId	mycid = miinfo->mycid;
 	int			ti_options = miinfo->ti_options;
@@ -1186,7 +1187,7 @@ BeginCopyFrom(ParseState *pstate,
 			  List *attnamelist,
 			  List *options)
 {
-	CopyFromState	cstate;
+	CopyFromState cstate;
 	bool		pipe = (filename == NULL);
 	TupleDesc	tupDesc;
 	AttrNumber	num_phys_attrs,
@@ -1214,7 +1215,7 @@ BeginCopyFrom(ParseState *pstate,
 	oldcontext = MemoryContextSwitchTo(cstate->copycontext);
 
 	/* Extract options from the statement node tree */
-	ProcessCopyOptions(pstate, &cstate->opts, true /* is_from */, options);
+	ProcessCopyOptions(pstate, &cstate->opts, true /* is_from */ , options);
 
 	/* Process the target relation */
 	cstate->rel = rel;
@@ -1305,15 +1306,20 @@ BeginCopyFrom(ParseState *pstate,
 		cstate->file_encoding = cstate->opts.file_encoding;
 
 	/*
-	 * Set up encoding conversion info.  Even if the file and server encodings
-	 * are the same, we must apply pg_any_to_server() to validate data in
-	 * multibyte encodings.
+	 * Look up encoding conversion function.
 	 */
-	cstate->need_transcoding =
-		(cstate->file_encoding != GetDatabaseEncoding() ||
-		 pg_database_encoding_max_length() > 1);
-	/* See Multibyte encoding comment above */
-	cstate->encoding_embeds_ascii = PG_ENCODING_IS_CLIENT_ONLY(cstate->file_encoding);
+	if (cstate->file_encoding == GetDatabaseEncoding() ||
+		cstate->file_encoding == PG_SQL_ASCII ||
+		GetDatabaseEncoding() == PG_SQL_ASCII)
+	{
+		cstate->need_transcoding = false;
+	}
+	else
+	{
+		cstate->need_transcoding = true;
+		cstate->conversion_proc = FindDefaultConversionProc(cstate->file_encoding,
+															GetDatabaseEncoding());
+	}
 
 	cstate->copy_src = COPY_FILE;	/* default */
 
@@ -1324,7 +1330,6 @@ BeginCopyFrom(ParseState *pstate,
 	oldcontext = MemoryContextSwitchTo(cstate->copycontext);
 
 	/* Initialize state variables */
-	cstate->reached_eof = false;
 	cstate->eol_type = EOL_UNKNOWN;
 	cstate->cur_relname = RelationGetRelationName(cstate->rel);
 	cstate->cur_lineno = 0;
@@ -1332,19 +1337,36 @@ BeginCopyFrom(ParseState *pstate,
 	cstate->cur_attval = NULL;
 
 	/*
-	 * Set up variables to avoid per-attribute overhead.  attribute_buf and
-	 * raw_buf are used in both text and binary modes, but we use line_buf
-	 * only in text mode.
+	 * Allocate buffers for the input pipeline.
+	 *
+	 * attribute_buf and raw_buf are used in both text and binary modes, but
+	 * input_buf and line_buf only in text mode.
 	 */
-	initStringInfo(&cstate->attribute_buf);
-	cstate->raw_buf = (char *) palloc(RAW_BUF_SIZE + 1);
+	cstate->raw_buf = palloc(RAW_BUF_SIZE);
 	cstate->raw_buf_index = cstate->raw_buf_len = 0;
+	cstate->raw_reached_eof = false;
+
 	if (!cstate->opts.binary)
 	{
+		/*
+		 * If encoding conversion is needed, we need another buffer to hold
+		 * the converted input data.  Otherwise, we can just point input_buf
+		 * to the same buffer as raw_buf.
+		 */
+		if (cstate->need_transcoding)
+		{
+			cstate->input_buf = (char *) palloc(INPUT_BUF_SIZE + 1);
+			cstate->input_buf_index = cstate->input_buf_len = 0;
+		}
+		else
+			cstate->input_buf = cstate->raw_buf;
+		cstate->input_reached_eof = false;
+
 		initStringInfo(&cstate->line_buf);
-		cstate->line_buf_converted = false;
 	}
 
+	initStringInfo(&cstate->attribute_buf);
+
 	/* Assign range table, we'll need it in CopyFrom. */
 	if (pstate)
 		cstate->range_table = pstate->p_rtable;
@@ -1563,7 +1585,7 @@ ClosePipeFromProgram(CopyFromState cstate)
 		 * should not report that as an error.  Otherwise, SIGPIPE indicates a
 		 * problem.
 		 */
-		if (!cstate->reached_eof &&
+		if (!cstate->raw_reached_eof &&
 			wait_result_is_signal(pclose_rc, SIGPIPE))
 			return;
 
diff --git a/src/backend/commands/copyfromparse.c b/src/backend/commands/copyfromparse.c
index 315b16fd7af..e4f85c88792 100644
--- a/src/backend/commands/copyfromparse.c
+++ b/src/backend/commands/copyfromparse.c
@@ -3,6 +3,49 @@
  * copyfromparse.c
  *		Parse CSV/text/binary format for COPY FROM.
  *
+ * This file contains routines to parse the text, CSV and binary input
+ * formats.  The main entry point is NextCopyFrom(), which parses the
+ * next input line and returns it as Datums.
+ *
+ * In text/CSV mode, the parsing happens in multiple stages:
+ *
+ * [data source] --> raw_buf --> input_buf --> line_buf --> attribute_buf
+ *                1.          2.            3.           4.
+ *
+ * 1. CopyLoadRawBuf() reads raw data from the input file or client, and
+ * places it into 'raw_buf'.
+ *
+ * 2. CopyConvertBuf() calls the encoding conversion function to convert
+ * the data in 'raw_buf' from client to server encoding, placing the
+ * converted result in 'input_buf'.
+ *
+ * 3. CopyReadLine() parses the data in 'input_buf', one line at a time.
+ * It is responsible for finding the next newline marker, taking quote and
+ * escape characters into account according to the COPY options.  The line
+ * is copied into 'line_buf', with quotes and escape characters still intact.
+ *
+ * 4. CopyReadAttributesText/CSV() function takes the input line from
+ * 'line_buf', and splits it into fields, unescaping the data as required.
+ * The fields are stored in 'attribute_buf', and 'raw_fields' array holds
+ * pointers to each field.
+ *
+ * If encoding conversion is not required, a shortcut is taken in step 2 to
+ * avoid copying the data unnecessarily.  The 'input_buf' pointer is set to
+ * point directly to 'raw_buf', so that CopyLoadRawBuf() loads the raw data
+ * directly into 'input_buf'.  CopyConvertBuf() then merely validates that
+ * the data is valid in the current encoding.
+ *
+ * In binary mode, the pipeline is much simpler.  Input is loaded into
+ * into 'raw_buf', and encoding conversion is done in the datatype-specific
+ * receive functions, if required.  'input_buf' and 'line_buf' are not used,
+ * but 'attribute_buf' is used as a temporary buffer to hold one attribute's
+ * data when it's passed the receive function.
+ *
+ * 'raw_buf' is always 64 kB in size (RAW_BUF_SIZE).  'input_buf' is also
+ * 64 kB (INPUT_BUF_SIZE), if encoding conversion is required.  'line_buf'
+ * and 'attribute_buf' are expanded on demand, to hold the longest line
+ * encountered so far.
+ *
  * Portions Copyright (c) 1996-2021, PostgreSQL Global Development Group
  * Portions Copyright (c) 1994, Regents of the University of California
  *
@@ -35,7 +78,7 @@
 #define OCTVALUE(c) ((c) - '0')
 
 /*
- * These macros centralize code used to process line_buf and raw_buf buffers.
+ * These macros centralize code used to process line_buf and input_buf buffers.
  * They are macros because they often do continue/break control and to avoid
  * function call overhead in tight COPY loops.
  *
@@ -53,9 +96,9 @@
 #define IF_NEED_REFILL_AND_NOT_EOF_CONTINUE(extralen) \
 if (1) \
 { \
-	if (raw_buf_ptr + (extralen) >= copy_buf_len && !hit_eof) \
+	if (input_buf_ptr + (extralen) >= copy_buf_len && !hit_eof) \
 	{ \
-		raw_buf_ptr = prev_raw_ptr; /* undo fetch */ \
+		input_buf_ptr = prev_raw_ptr; /* undo fetch */ \
 		need_data = true; \
 		continue; \
 	} \
@@ -65,10 +108,10 @@ if (1) \
 #define IF_NEED_REFILL_AND_EOF_BREAK(extralen) \
 if (1) \
 { \
-	if (raw_buf_ptr + (extralen) >= copy_buf_len && hit_eof) \
+	if (input_buf_ptr + (extralen) >= copy_buf_len && hit_eof) \
 	{ \
 		if (extralen) \
-			raw_buf_ptr = copy_buf_len; /* consume the partial character */ \
+			input_buf_ptr = copy_buf_len; /* consume the partial character */ \
 		/* backslash just before EOF, treat as data char */ \
 		result = true; \
 		break; \
@@ -77,17 +120,17 @@ if (1) \
 
 /*
  * Transfer any approved data to line_buf; must do this to be sure
- * there is some room in raw_buf.
+ * there is some room in input_buf.
  */
 #define REFILL_LINEBUF \
 if (1) \
 { \
-	if (raw_buf_ptr > cstate->raw_buf_index) \
+	if (input_buf_ptr > cstate->input_buf_index) \
 	{ \
 		appendBinaryStringInfo(&cstate->line_buf, \
-							 cstate->raw_buf + cstate->raw_buf_index, \
-							   raw_buf_ptr - cstate->raw_buf_index); \
-		cstate->raw_buf_index = raw_buf_ptr; \
+							 cstate->input_buf + cstate->input_buf_index, \
+							   input_buf_ptr - cstate->input_buf_index); \
+		cstate->input_buf_index = input_buf_ptr; \
 	} \
 } else ((void) 0)
 
@@ -95,7 +138,7 @@ if (1) \
 #define NO_END_OF_COPY_GOTO \
 if (1) \
 { \
-	raw_buf_ptr = prev_raw_ptr + 1; \
+	input_buf_ptr = prev_raw_ptr + 1; \
 	goto not_end_of_copy; \
 } else ((void) 0)
 
@@ -118,7 +161,7 @@ static int	CopyGetData(CopyFromState cstate, void *databuf,
 						int minread, int maxread);
 static inline bool CopyGetInt32(CopyFromState cstate, int32 *val);
 static inline bool CopyGetInt16(CopyFromState cstate, int16 *val);
-static bool CopyLoadRawBuf(CopyFromState cstate);
+static void CopyLoadInputBuf(CopyFromState cstate);
 static int	CopyReadBinaryData(CopyFromState cstate, char *dest, int nbytes);
 
 void
@@ -226,7 +269,7 @@ CopyGetData(CopyFromState cstate, void *databuf, int minread, int maxread)
 						(errcode_for_file_access(),
 						 errmsg("could not read from COPY file: %m")));
 			if (bytesread == 0)
-				cstate->reached_eof = true;
+				cstate->raw_reached_eof = true;
 			break;
 		case COPY_OLD_FE:
 
@@ -247,7 +290,7 @@ CopyGetData(CopyFromState cstate, void *databuf, int minread, int maxread)
 			bytesread = minread;
 			break;
 		case COPY_NEW_FE:
-			while (maxread > 0 && bytesread < minread && !cstate->reached_eof)
+			while (maxread > 0 && bytesread < minread && !cstate->raw_reached_eof)
 			{
 				int			avail;
 
@@ -275,7 +318,7 @@ CopyGetData(CopyFromState cstate, void *databuf, int minread, int maxread)
 							break;
 						case 'c':	/* CopyDone */
 							/* COPY IN correctly terminated by frontend */
-							cstate->reached_eof = true;
+							cstate->raw_reached_eof = true;
 							return bytesread;
 						case 'f':	/* CopyFail */
 							ereport(ERROR,
@@ -361,34 +404,303 @@ CopyGetInt16(CopyFromState cstate, int16 *val)
 
 
 /*
- * CopyLoadRawBuf loads some more data into raw_buf
+ * Perform encoding conversion on data in 'raw_buf', writing the converted
+ * data into 'input_buf'.
  *
- * Returns true if able to obtain at least one more byte, else false.
+ * On entry, there must be some data to convert in 'raw_buf'.
+ */
+static void
+CopyConvertBuf(CopyFromState cstate)
+{
+	/*
+	 * If the file and server encoding are the same, no encoding conversion is
+	 * required.  However, we still need to verify that the input is valid for
+	 * the encoding.
+	 */
+	if (!cstate->need_transcoding)
+	{
+		/*
+		 * When conversion is not required, input_buf and raw_buf are the
+		 * same.  raw_buf_len is the total number of bytes in the buffer, and
+		 * input_buf_len tracks how many of those bytes have already been
+		 * verified.
+		 */
+		int			preverifiedlen = cstate->input_buf_len;
+		int			unverifiedlen = cstate->raw_buf_len - cstate->input_buf_len;
+		int			nverified;
+
+		if (unverifiedlen == 0)
+		{
+			/*
+			 * If no more raw data is coming, report the EOF to the caller.
+			 */
+			if (cstate->raw_reached_eof)
+				cstate->input_reached_eof = true;
+			return;
+		}
+
+		/*
+		 * Verify the new data, including any residual unverified bytes from
+		 * previous round.
+		 */
+		nverified = pg_encoding_verifymbstr(cstate->file_encoding,
+											cstate->raw_buf + preverifiedlen,
+											unverifiedlen);
+		if (nverified == 0)
+		{
+			/*
+			 * Could not verify anything.
+			 *
+			 * If there is no more raw input data coming, it means that there
+			 * was an incomplete multi-byte sequence at the end.  Also, if
+			 * there's "enough" input left, we should be able to verify at
+			 * least one character, and a failure to do so means that we've
+			 * hit an invalid byte sequence.
+			 */
+			if (cstate->raw_reached_eof || unverifiedlen >= pg_database_encoding_max_length())
+				cstate->input_reached_error = true;
+			return;
+		}
+		cstate->input_buf_len += nverified;
+	}
+	else
+	{
+		/*
+		 * Encoding conversion is needed.
+		 */
+		int			nbytes;
+		unsigned char *src;
+		int			srclen;
+		unsigned char *dst;
+		int			dstlen;
+		int			convertedlen;
+
+		if (RAW_BUF_BYTES(cstate) == 0)
+		{
+			/*
+			 * If no more raw data is coming, report the EOF to the caller.
+			 */
+			if (cstate->raw_reached_eof)
+				cstate->input_reached_eof = true;
+			return;
+		}
+
+		/*
+		 * First, copy down any unprocessed data.
+		 */
+		nbytes = INPUT_BUF_BYTES(cstate);
+		if (nbytes > 0 && cstate->input_buf_index > 0)
+			memmove(cstate->input_buf, cstate->input_buf + cstate->input_buf_index,
+					nbytes);
+		cstate->input_buf_index = 0;
+		cstate->input_buf_len = nbytes;
+		cstate->input_buf[nbytes] = '\0';
+
+		src = (unsigned char *) cstate->raw_buf + cstate->raw_buf_index;
+		srclen = cstate->raw_buf_len - cstate->raw_buf_index;
+		dst = (unsigned char *) cstate->input_buf + cstate->input_buf_len;
+		dstlen = INPUT_BUF_SIZE - cstate->input_buf_len + 1;
+
+		/*
+		 * Do the conversion.  This might stop short, if there is an invalid
+		 * byte sequence in the input.  We'll convert as much as we can in
+		 * that case.
+		 *
+		 * Note: Even if we hit an invalid byte sequence, we don't report the
+		 * error until all the valid bytes have been consumed.  The input
+		 * might contain an end-of-input marker (\.), and we don't want to
+		 * report an error if the invalid byte sequence is after the
+		 * end-of-input marker.  We might unnecessarily convert some data
+		 * after the end-of-input marker as long as it's valid for the
+		 * encoding, but that's harmless.
+		 */
+		convertedlen = pg_do_encoding_conversion_buf(cstate->conversion_proc,
+													 cstate->file_encoding,
+													 GetDatabaseEncoding(),
+													 src, srclen,
+													 dst, dstlen,
+													 true);
+		if (convertedlen == 0)
+		{
+			/*
+			 * Could not convert anything.  If there is no more raw input data
+			 * coming, it means that there was an incomplete multi-byte
+			 * sequence at the end.  Also, if there is plenty of input left,
+			 * we should be able to convert at least one character, so a
+			 * failure to do so must mean that we've hit a byte sequence
+			 * that's invalid.
+			 */
+			if (cstate->raw_reached_eof || srclen >= MAX_CONVERSION_INPUT_LENGTH)
+				cstate->input_reached_error = true;
+			return;
+		}
+		cstate->raw_buf_index += convertedlen;
+		cstate->input_buf_len += strlen((char *) dst);
+	}
+}
+
+/*
+ * Report an encoding or conversion error.
+ */
+static void
+CopyConversionError(CopyFromState cstate)
+{
+	Assert(cstate->raw_buf_len > 0);
+	Assert(cstate->input_reached_error);
+
+	if (!cstate->need_transcoding)
+	{
+		/*
+		 * Everything up to input_buf_len was successfully verified, and
+		 * input_buf_len points to the invalid or incomplete character.
+		 */
+		report_invalid_encoding(cstate->file_encoding,
+								cstate->raw_buf + cstate->input_buf_len,
+								cstate->raw_buf_len - cstate->input_buf_len);
+	}
+	else
+	{
+		/*
+		 * raw_buf_index points to the invalid or untranslatable character. We
+		 * let the conversion routine report the error, because it can provide
+		 * a more specific error message than we could here.  An earlier call
+		 * to the conversion routine in CopyConvertBuf() detected that there
+		 * is an error, now we call the conversion routine again with
+		 * noError=false, to have it throw the error.
+		 */
+		unsigned char *src;
+		int			srclen;
+		unsigned char *dst;
+		int			dstlen;
+
+		src = (unsigned char *) cstate->raw_buf + cstate->raw_buf_index;
+		srclen = cstate->raw_buf_len - cstate->raw_buf_index;
+		dst = (unsigned char *) cstate->input_buf + cstate->input_buf_len;
+		dstlen = INPUT_BUF_SIZE - cstate->input_buf_len + 1;
+
+		(void) pg_do_encoding_conversion_buf(cstate->conversion_proc,
+											 cstate->file_encoding,
+											 GetDatabaseEncoding(),
+											 src, srclen,
+											 dst, dstlen,
+											 false);
+
+		/*
+		 * The conversion routine should have reported an error, so this
+		 * should not be reached.
+		 */
+		elog(ERROR, "encoding conversion failed without error");
+	}
+}
+
+/*
+ * Load more data from data source to raw_buf.
  *
  * If RAW_BUF_BYTES(cstate) > 0, the unprocessed bytes are moved to the start
- * of the buffer and then we load more data after that.  This case occurs only
- * when a multibyte character crosses a bufferload boundary.
+ * of the buffer and then we load more data after that.
  */
-static bool
+static void
 CopyLoadRawBuf(CopyFromState cstate)
 {
-	int			nbytes = RAW_BUF_BYTES(cstate);
+	int			nbytes;
 	int			inbytes;
 
-	/* Copy down the unprocessed data if any. */
-	if (nbytes > 0)
+	/*
+	 * In text mode, if encoding conversion is not required, raw_buf and
+	 * input_buf point to the same buffer.  Their len/index better agree, too.
+	 */
+	if (cstate->raw_buf == cstate->input_buf)
+	{
+		Assert(!cstate->need_transcoding);
+		Assert(cstate->raw_buf_index == cstate->input_buf_index);
+		Assert(cstate->input_buf_len <= cstate->raw_buf_len);
+	}
+
+	/*
+	 * Copy down the unprocessed data if any.
+	 */
+	nbytes = RAW_BUF_BYTES(cstate);
+	if (nbytes > 0 && cstate->raw_buf_index > 0)
 		memmove(cstate->raw_buf, cstate->raw_buf + cstate->raw_buf_index,
 				nbytes);
+	cstate->raw_buf_len -= cstate->raw_buf_index;
+	cstate->raw_buf_index = 0;
+
+	/*
+	 * If raw_buf and input_buf are in fact the same buffer, adjust the
+	 * input_buf variables, too.
+	 */
+	if (cstate->raw_buf == cstate->input_buf)
+	{
+		cstate->input_buf_len -= cstate->input_buf_index;
+		cstate->input_buf_index = 0;
+	}
 
-	inbytes = CopyGetData(cstate, cstate->raw_buf + nbytes,
-						  1, RAW_BUF_SIZE - nbytes);
+	/* Load more data */
+	inbytes = CopyGetData(cstate, cstate->raw_buf + cstate->raw_buf_len,
+						  1, RAW_BUF_SIZE - cstate->raw_buf_len);
 	nbytes += inbytes;
 	cstate->raw_buf[nbytes] = '\0';
-	cstate->raw_buf_index = 0;
 	cstate->raw_buf_len = nbytes;
+
 	cstate->bytes_processed += inbytes;
 	pgstat_progress_update_param(PROGRESS_COPY_BYTES_PROCESSED, cstate->bytes_processed);
-	return (inbytes > 0);
+
+	if (inbytes == 0)
+		cstate->raw_reached_eof = true;
+}
+
+/*
+ * CopyLoadInputBuf loads some more data into input_buf
+ *
+ * On return, at least one more input character is loaded into
+ * input_buf, or input_reached_eof is set.
+ *
+ * If INPUT_BUF_BYTES(cstate) > 0, the unprocessed bytes are moved to the start
+ * of the buffer and then we load more data after that.
+ */
+static void
+CopyLoadInputBuf(CopyFromState cstate)
+{
+	int			nbytes = INPUT_BUF_BYTES(cstate);
+
+	/*
+	 * The caller has updated input_buf_index to indicate how much of the
+	 * input has been consumed and isn't needed anymore.  If input_buf is the
+	 * same physical area as raw_buf, updated raw_buf_index accordingly.
+	 */
+	if (cstate->raw_buf == cstate->input_buf)
+	{
+		Assert(!cstate->need_transcoding);
+		Assert(cstate->input_buf_index >= cstate->raw_buf_index);
+		cstate->raw_buf_index = cstate->input_buf_index;
+	}
+
+	for (;;)
+	{
+		/* If we now have some unconverted data, try to convert it. */
+		CopyConvertBuf(cstate);
+
+		/* If we now have some more input bytes ready, return them */
+		if (INPUT_BUF_BYTES(cstate) > nbytes)
+			return;
+
+		/*
+		 * If we reached an invalid byte sequence, or we're at an incomplete
+		 * multi-byte character but there is no more raw input data, report
+		 * conversion error.
+		 */
+		if (cstate->input_reached_error)
+			CopyConversionError(cstate);
+
+		/* no more input, and everything has been converted */
+		if (cstate->input_reached_eof)
+			break;
+
+		/* Try to load more raw data */
+		Assert(!cstate->raw_reached_eof);
+		CopyLoadRawBuf(cstate);
+	}
 }
 
 /*
@@ -423,7 +735,8 @@ CopyReadBinaryData(CopyFromState cstate, char *dest, int nbytes)
 			/* Load more data if buffer is empty. */
 			if (RAW_BUF_BYTES(cstate) == 0)
 			{
-				if (!CopyLoadRawBuf(cstate))
+				CopyLoadRawBuf(cstate);
+				if (cstate->raw_reached_eof)
 					break;		/* EOF */
 			}
 
@@ -697,10 +1010,7 @@ CopyReadLine(CopyFromState cstate)
 	bool		result;
 
 	resetStringInfo(&cstate->line_buf);
-	cstate->line_buf_valid = true;
-
-	/* Mark that encoding conversion hasn't occurred yet */
-	cstate->line_buf_converted = false;
+	cstate->line_buf_valid = false;
 
 	/* Parse data and transfer into line_buf */
 	result = CopyReadLineText(cstate);
@@ -714,10 +1024,17 @@ CopyReadLine(CopyFromState cstate)
 		 */
 		if (cstate->copy_src == COPY_NEW_FE)
 		{
+			int			inbytes;
+
 			do
 			{
-				cstate->raw_buf_index = cstate->raw_buf_len;
-			} while (CopyLoadRawBuf(cstate));
+				inbytes = CopyGetData(cstate, cstate->input_buf,
+									  1, INPUT_BUF_SIZE);
+			} while (inbytes > 0);
+			cstate->input_buf_index = 0;
+			cstate->input_buf_len = 0;
+			cstate->raw_buf_index = 0;
+			cstate->raw_buf_len = 0;
 		}
 	}
 	else
@@ -754,25 +1071,8 @@ CopyReadLine(CopyFromState cstate)
 		}
 	}
 
-	/* Done reading the line.  Convert it to server encoding. */
-	if (cstate->need_transcoding)
-	{
-		char	   *cvt;
-
-		cvt = pg_any_to_server(cstate->line_buf.data,
-							   cstate->line_buf.len,
-							   cstate->file_encoding);
-		if (cvt != cstate->line_buf.data)
-		{
-			/* transfer converted data back to line_buf */
-			resetStringInfo(&cstate->line_buf);
-			appendBinaryStringInfo(&cstate->line_buf, cvt, strlen(cvt));
-			pfree(cvt);
-		}
-	}
-
 	/* Now it's safe to use the buffer in error messages */
-	cstate->line_buf_converted = true;
+	cstate->line_buf_valid = true;
 
 	return result;
 }
@@ -783,13 +1083,12 @@ CopyReadLine(CopyFromState cstate)
 static bool
 CopyReadLineText(CopyFromState cstate)
 {
-	char	   *copy_raw_buf;
-	int			raw_buf_ptr;
+	char	   *copy_input_buf;
+	int			input_buf_ptr;
 	int			copy_buf_len;
 	bool		need_data = false;
 	bool		hit_eof = false;
 	bool		result = false;
-	char		mblen_str[2];
 
 	/* CSV variables */
 	bool		first_char_in_line = true;
@@ -807,8 +1106,6 @@ CopyReadLineText(CopyFromState cstate)
 			escapec = '\0';
 	}
 
-	mblen_str[1] = '\0';
-
 	/*
 	 * The objective of this loop is to transfer the entire next input line
 	 * into line_buf.  Hence, we only care for detecting newlines (\r and/or
@@ -821,18 +1118,25 @@ CopyReadLineText(CopyFromState cstate)
 	 * These four characters, and the CSV escape and quote characters, are
 	 * assumed the same in frontend and backend encodings.
 	 *
-	 * For speed, we try to move data from raw_buf to line_buf in chunks
-	 * rather than one character at a time.  raw_buf_ptr points to the next
-	 * character to examine; any characters from raw_buf_index to raw_buf_ptr
-	 * have been determined to be part of the line, but not yet transferred to
-	 * line_buf.
+	 * The input has already been converted to the database encoding.  All
+	 * supported server encodings have the property that all bytes in a
+	 * multi-byte sequence have the high bit set, so a multibyte character
+	 * cannot contain any newline or escape characters embedded in the
+	 * multibyte sequence.  Therefore, we can process the input byte-by-byte,
+	 * regardless of the encoding.
 	 *
-	 * For a little extra speed within the loop, we copy raw_buf and
-	 * raw_buf_len into local variables.
+	 * For speed, we try to move data from input_buf to line_buf in chunks
+	 * rather than one character at a time.  input_buf_ptr points to the next
+	 * character to examine; any characters from input_buf_index to
+	 * input_buf_ptr have been determined to be part of the line, but not yet
+	 * transferred to line_buf.
+	 *
+	 * For a little extra speed within the loop, we copy input_buf and
+	 * input_buf_len into local variables.
 	 */
-	copy_raw_buf = cstate->raw_buf;
-	raw_buf_ptr = cstate->raw_buf_index;
-	copy_buf_len = cstate->raw_buf_len;
+	copy_input_buf = cstate->input_buf;
+	input_buf_ptr = cstate->input_buf_index;
+	copy_buf_len = cstate->input_buf_len;
 
 	for (;;)
 	{
@@ -849,24 +1153,24 @@ CopyReadLineText(CopyFromState cstate)
 		 * cstate->copy_src != COPY_OLD_FE, but it hardly seems worth it,
 		 * considering the size of the buffer.
 		 */
-		if (raw_buf_ptr >= copy_buf_len || need_data)
+		if (input_buf_ptr >= copy_buf_len || need_data)
 		{
 			REFILL_LINEBUF;
 
 			/*
-			 * Try to read some more data.  This will certainly reset
-			 * raw_buf_index to zero, and raw_buf_ptr must go with it.
+			 * Try to read some more data.
 			 */
-			if (!CopyLoadRawBuf(cstate))
-				hit_eof = true;
-			raw_buf_ptr = 0;
-			copy_buf_len = cstate->raw_buf_len;
+			CopyLoadInputBuf(cstate);
+			/* update our local variables */
+			hit_eof = cstate->input_reached_eof;
+			input_buf_ptr = cstate->input_buf_index;
+			copy_buf_len = cstate->input_buf_len;
 
 			/*
 			 * If we are completely out of data, break out of the loop,
 			 * reporting EOF.
 			 */
-			if (copy_buf_len <= 0)
+			if (INPUT_BUF_BYTES(cstate) <= 0)
 			{
 				result = true;
 				break;
@@ -875,8 +1179,8 @@ CopyReadLineText(CopyFromState cstate)
 		}
 
 		/* OK to fetch a character */
-		prev_raw_ptr = raw_buf_ptr;
-		c = copy_raw_buf[raw_buf_ptr++];
+		prev_raw_ptr = input_buf_ptr;
+		c = copy_input_buf[input_buf_ptr++];
 
 		if (cstate->opts.csv_mode)
 		{
@@ -930,16 +1234,16 @@ CopyReadLineText(CopyFromState cstate)
 				 * If need more data, go back to loop top to load it.
 				 *
 				 * Note that if we are at EOF, c will wind up as '\0' because
-				 * of the guaranteed pad of raw_buf.
+				 * of the guaranteed pad of input_buf.
 				 */
 				IF_NEED_REFILL_AND_NOT_EOF_CONTINUE(0);
 
 				/* get next char */
-				c = copy_raw_buf[raw_buf_ptr];
+				c = copy_input_buf[input_buf_ptr];
 
 				if (c == '\n')
 				{
-					raw_buf_ptr++;	/* eat newline */
+					input_buf_ptr++;	/* eat newline */
 					cstate->eol_type = EOL_CRNL;	/* in case not set yet */
 				}
 				else
@@ -1006,14 +1310,14 @@ CopyReadLineText(CopyFromState cstate)
 			/* -----
 			 * get next character
 			 * Note: we do not change c so if it isn't \., we can fall
-			 * through and continue processing for file encoding.
+			 * through and continue processing.
 			 * -----
 			 */
-			c2 = copy_raw_buf[raw_buf_ptr];
+			c2 = copy_input_buf[input_buf_ptr];
 
 			if (c2 == '.')
 			{
-				raw_buf_ptr++;	/* consume the '.' */
+				input_buf_ptr++;	/* consume the '.' */
 
 				/*
 				 * Note: if we loop back for more data here, it does not
@@ -1025,7 +1329,7 @@ CopyReadLineText(CopyFromState cstate)
 					/* Get the next character */
 					IF_NEED_REFILL_AND_NOT_EOF_CONTINUE(0);
 					/* if hit_eof, c2 will become '\0' */
-					c2 = copy_raw_buf[raw_buf_ptr++];
+					c2 = copy_input_buf[input_buf_ptr++];
 
 					if (c2 == '\n')
 					{
@@ -1050,7 +1354,7 @@ CopyReadLineText(CopyFromState cstate)
 				/* Get the next character */
 				IF_NEED_REFILL_AND_NOT_EOF_CONTINUE(0);
 				/* if hit_eof, c2 will become '\0' */
-				c2 = copy_raw_buf[raw_buf_ptr++];
+				c2 = copy_input_buf[input_buf_ptr++];
 
 				if (c2 != '\r' && c2 != '\n')
 				{
@@ -1075,11 +1379,11 @@ CopyReadLineText(CopyFromState cstate)
 				 * Transfer only the data before the \. into line_buf, then
 				 * discard the data and the \. sequence.
 				 */
-				if (prev_raw_ptr > cstate->raw_buf_index)
+				if (prev_raw_ptr > cstate->input_buf_index)
 					appendBinaryStringInfo(&cstate->line_buf,
-										   cstate->raw_buf + cstate->raw_buf_index,
-										   prev_raw_ptr - cstate->raw_buf_index);
-				cstate->raw_buf_index = raw_buf_ptr;
+										   cstate->input_buf + cstate->input_buf_index,
+										   prev_raw_ptr - cstate->input_buf_index);
+				cstate->input_buf_index = input_buf_ptr;
 				result = true;	/* report EOF */
 				break;
 			}
@@ -1095,15 +1399,8 @@ CopyReadLineText(CopyFromState cstate)
 				 * backslashes are not special, so we want to process the
 				 * character after the backslash just like a normal character,
 				 * so we don't increment in those cases.
-				 *
-				 * Set 'c' to skip whole character correctly in multi-byte
-				 * encodings.  If we don't have the whole character in the
-				 * buffer yet, we might loop back to process it, after all,
-				 * but that's OK because multi-byte characters cannot have any
-				 * special meaning.
 				 */
-				raw_buf_ptr++;
-				c = c2;
+				input_buf_ptr++;
 			}
 		}
 
@@ -1114,30 +1411,6 @@ CopyReadLineText(CopyFromState cstate)
 		 * value, while in non-CSV mode, \. cannot be a data value.
 		 */
 not_end_of_copy:
-
-		/*
-		 * Process all bytes of a multi-byte character as a group.
-		 *
-		 * We only support multi-byte sequences where the first byte has the
-		 * high-bit set, so as an optimization we can avoid this block
-		 * entirely if it is not set.
-		 */
-		if (cstate->encoding_embeds_ascii && IS_HIGHBIT_SET(c))
-		{
-			int			mblen;
-
-			/*
-			 * It is enough to look at the first byte in all our encodings, to
-			 * get the length.  (GB18030 is a bit special, but still works for
-			 * our purposes; see comment in pg_gb18030_mblen())
-			 */
-			mblen_str[0] = c;
-			mblen = pg_encoding_mblen(cstate->file_encoding, mblen_str);
-
-			IF_NEED_REFILL_AND_NOT_EOF_CONTINUE(mblen - 1);
-			IF_NEED_REFILL_AND_EOF_BREAK(mblen - 1);
-			raw_buf_ptr += mblen - 1;
-		}
 		first_char_in_line = false;
 	}							/* end of outer loop */
 
diff --git a/src/include/commands/copyfrom_internal.h b/src/include/commands/copyfrom_internal.h
index e37942df391..5c110ce5b92 100644
--- a/src/include/commands/copyfrom_internal.h
+++ b/src/include/commands/copyfrom_internal.h
@@ -53,17 +53,6 @@ typedef enum CopyInsertMethod
 /*
  * This struct contains all the state variables used throughout a COPY FROM
  * operation.
- *
- * Multi-byte encodings: all supported client-side encodings encode multi-byte
- * characters by having the first byte's high bit set. Subsequent bytes of the
- * character can have the high bit not set. When scanning data in such an
- * encoding to look for a match to a single-byte (ie ASCII) character, we must
- * use the full pg_encoding_mblen() machinery to skip over multibyte
- * characters, else we might find a false match to a trailing byte. In
- * supported server encodings, there is no possibility of a false match, and
- * it's faster to make useless comparisons to trailing bytes than it is to
- * invoke pg_encoding_mblen() to skip over them. encoding_embeds_ascii is true
- * when we have to do it the hard way.
  */
 typedef struct CopyFromStateData
 {
@@ -71,13 +60,11 @@ typedef struct CopyFromStateData
 	CopySource	copy_src;		/* type of copy source */
 	FILE	   *copy_file;		/* used if copy_src == COPY_FILE */
 	StringInfo	fe_msgbuf;		/* used if copy_src == COPY_NEW_FE */
-	bool		reached_eof;	/* true if we read to end of copy data (not
-								 * all copy_src types maintain this) */
 
 	EolType		eol_type;		/* EOL type of input */
 	int			file_encoding;	/* file or remote side's character encoding */
 	bool		need_transcoding;	/* file encoding diff from server? */
-	bool		encoding_embeds_ascii;	/* ASCII can be non-first byte? */
+	Oid			conversion_proc;
 
 	/* parameters from the COPY command */
 	Relation	rel;			/* relation to copy from */
@@ -132,31 +119,52 @@ typedef struct CopyFromStateData
 
 	/*
 	 * Similarly, line_buf holds the whole input line being processed. The
-	 * input cycle is first to read the whole line into line_buf, convert it
-	 * to server encoding there, and then extract the individual attribute
-	 * fields into attribute_buf.  line_buf is preserved unmodified so that we
-	 * can display it in error messages if appropriate.  (In binary mode,
-	 * line_buf is not used.)
+	 * input cycle is first to read the whole line into line_buf, and then
+	 * extract the individual attribute fields into attribute_buf.  line_buf
+	 * is preserved unmodified so that we can display it in error messages if
+	 * appropriate.  (In binary mode, line_buf is not used.)
 	 */
 	StringInfoData line_buf;
-	bool		line_buf_converted; /* converted to server encoding? */
 	bool		line_buf_valid; /* contains the row being processed? */
 
 	/*
-	 * Finally, raw_buf holds raw data read from the data source (file or
-	 * client connection).  In text mode, CopyReadLine parses this data
-	 * sufficiently to locate line boundaries, then transfers the data to
-	 * line_buf and converts it.  In binary mode, CopyReadBinaryData fetches
-	 * appropriate amounts of data from this buffer.  In both modes, we
-	 * guarantee that there is a \0 at raw_buf[raw_buf_len].
+	 * input_buf holds input data, already converted to database encoding.
+	 *
+	 * In text mode, CopyReadLine parses this data sufficiently to locate line
+	 * boundaries, then transfers the data to line_buf.  In binary mode,
+	 * CopyReadBinaryData fetches appropriate amounts of data from this
+	 * buffer.  In both modes, we guarantee that there is a \0 at
+	 * input_buf[input_buf_len].
+	 */
+#define INPUT_BUF_SIZE 65536	/* we palloc INPUT_BUF_SIZE+1 bytes */
+	char	   *input_buf;
+	int			input_buf_index;	/* next byte to process */
+	int			input_buf_len;	/* total # of bytes stored */
+	bool		input_reached_eof;	/* true if we reached EOF */
+	bool		input_reached_error;	/* true if a conversion error happened */
+	/* Shorthand for number of unconsumed bytes available in input_buf */
+#define INPUT_BUF_BYTES(cstate) ((cstate)->input_buf_len - (cstate)->input_buf_index)
+
+	/*
+	 * raw_buf holds raw input data read from the data source (file or client
+	 * connection), not yet converted to the database encoding.  Like with
+	 * 'input_buf', we guarantee that there is a \0 at raw_buf[raw_buf_len].
+	 *
+	 * If the encoding conversion is not required, the input data is read
+	 * directly into 'input_buf', and raw_buf is not used.  In that case,
+	 * input_buf_len tracks the number of bytes verified to be valid in the
+	 * encoding, and raw_buf_len is the total # of bytes stored in the buffer.
 	 */
 #define RAW_BUF_SIZE 65536		/* we palloc RAW_BUF_SIZE+1 bytes */
 	char	   *raw_buf;
 	int			raw_buf_index;	/* next byte to process */
 	int			raw_buf_len;	/* total # of bytes stored */
-	uint64		bytes_processed;/* number of bytes processed so far */
+	bool		raw_reached_eof;	/* true if we reached EOF */
+
 	/* Shorthand for number of unconsumed bytes available in raw_buf */
 #define RAW_BUF_BYTES(cstate) ((cstate)->raw_buf_len - (cstate)->raw_buf_index)
+
+	uint64		bytes_processed;	/* number of bytes processed so far */
 } CopyFromStateData;
 
 extern void ReceiveCopyBegin(CopyFromState cstate);
diff --git a/src/include/mb/pg_wchar.h b/src/include/mb/pg_wchar.h
index bbce9071dfc..2377934faf6 100644
--- a/src/include/mb/pg_wchar.h
+++ b/src/include/mb/pg_wchar.h
@@ -306,15 +306,33 @@ typedef enum pg_enc
 
 /*
  * When converting strings between different encodings, we assume that space
- * for converted result is 4-to-1 growth in the worst case. The rate for
+ * for converted result is 4-to-1 growth in the worst case.  The rate for
  * currently supported encoding pairs are within 3 (SJIS JIS X0201 half width
- * kanna -> UTF8 is the worst case).  So "4" should be enough for the moment.
+ * kana -> UTF8 is the worst case).  So "4" should be enough for the moment.
  *
  * Note that this is not the same as the maximum character width in any
  * particular encoding.
  */
 #define MAX_CONVERSION_GROWTH  4
 
+/*
+ * Maximum byte length of a string that's required in any encoding to convert
+ * at least one character to any other encoding.  In other words, if you feed
+ * MAX_CONVERSION_INPUT_LENGTH bytes to any encoding conversion function, it
+ * is guaranteed to be able to convert something without needing more input
+ * (assuming the input is valid).
+ *
+ * Currently, the maximum case is the conversion UTF8 -> SJIS JIS X0201 half
+ * width kana, where a pair of UTF-8 characters is converted into a single
+ * SHIFT_JIS_2004 character (the reverse of the worst case for
+ * MAX_CONVERSION_GROWTH).  It needs 6 bytes of input.  In theory, a
+ * user-defined conversion function might have more complicated cases, although
+ * for the reverse mapping you would probably also need to bump up
+ * MAX_CONVERSION_GROWTH.  But there is no need to be stingy here, so make it
+ * generous.
+ */
+#define MAX_CONVERSION_INPUT_LENGTH	16
+
 /*
  * Maximum byte length of the string equivalent to any one Unicode code point,
  * in any backend encoding.  The current value assumes that a 4-byte UTF-8
-- 
2.30.0


--------------1D68F301AB7A25998BA3365F--





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-02-28 05:41  Michael Paquier <[email protected]>
  2 siblings, 2 replies; 40+ messages in thread

From: Michael Paquier @ 2025-02-28 05:41 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: [email protected]

On Wed, Feb 26, 2025 at 09:48:50AM +0000, Bertrand Drouvot wrote:
> Yeah I think that makes sense, done that way in the attached.
> 
> Speaking about physical walsender, I moved the test to 001_stream_rep.pl instead
> (would also fail without the fix).

Hmm.  I was doing some more checks with this patch, and on closer look
I am wondering if the location you have chosen for the stats reports
is too aggressive: this requires a LWLock for the WAL sender backend
type taken in exclusive mode, with each step of WalSndLoop() taken
roughly each time a record or a batch of records is sent.  A single
installcheck with a primary/standby setup can lead to up to 50k stats
report calls.

With smaller records, the loop can become hotter, can't it?  Also,
there can be a high number of WAL senders on a single node, and I've
heard of some customers with complex logical decoding deployments with
dozens of logical WAL senders.  Isn't there a risk of having this code
path become a point of contention?  It seems to me that we should
benchmark this change more carefully, perhaps even reduce the
frequency of the report calls.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-02-28 08:44  Michael Paquier <[email protected]>
  parent: Michael Paquier <[email protected]>
  1 sibling, 0 replies; 40+ messages in thread

From: Michael Paquier @ 2025-02-28 08:44 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: [email protected]

On Fri, Feb 28, 2025 at 02:41:34PM +0900, Michael Paquier wrote:
> With smaller records, the loop can become hotter, can't it?  Also,
> there can be a high number of WAL senders on a single node, and I've
> heard of some customers with complex logical decoding deployments with
> dozens of logical WAL senders.  Isn't there a risk of having this code
> path become a point of contention?  It seems to me that we should
> benchmark this change more carefully, perhaps even reduce the
> frequency of the report calls.

One idea here would be to have on a single host one server with a set
of N pg_receivewal processes dumping their WAL segments into a tmpfs,
while a single session generates a bunch of records with a minimal
size using pg_logical_emit_message().  Monitoring the maximum
replication lag with pg_stat_replication and looking at some perf
profiles of the cluster should show how these stats reports affect the
replication setup efficiency. 
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-02-28 10:39  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  1 sibling, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-02-28 10:39 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: [email protected]

Hi,

On Fri, Feb 28, 2025 at 02:41:34PM +0900, Michael Paquier wrote:
> On Wed, Feb 26, 2025 at 09:48:50AM +0000, Bertrand Drouvot wrote:
> > Yeah I think that makes sense, done that way in the attached.
> > 
> > Speaking about physical walsender, I moved the test to 001_stream_rep.pl instead
> > (would also fail without the fix).
> 
> Hmm.  I was doing some more checks with this patch, and on closer look
> I am wondering if the location you have chosen for the stats reports
> is too aggressive: this requires a LWLock for the WAL sender backend
> type taken in exclusive mode, with each step of WalSndLoop() taken
> roughly each time a record or a batch of records is sent.  A single
> installcheck with a primary/standby setup can lead to up to 50k stats
> report calls.

Yeah, what I can observe (installcheck with a primary/standby):

- extras flush are called about 70K times.

Among those 70K:

- about 575 are going after the "have_iostats" check in pgstat_io_flush_cb()
- about 575 are going after the PendingBackendStats pg_memory_is_all_zeros()
check in pgstat_flush_backend() (makes sense due to the above)
- about 575 are going after the PendingBackendStats.pending_io pg_memory_is_all_zeros()
check in pgstat_flush_backend_entry_io() (makes sense due to the above)

It means that only a very few of them are "really" flushing IO stats.

> With smaller records, the loop can become hotter, can't it?  Also,
> there can be a high number of WAL senders on a single node, and I've
> heard of some customers with complex logical decoding deployments with
> dozens of logical WAL senders.  Isn't there a risk of having this code
> path become a point of contention?  It seems to me that we should
> benchmark this change more carefully, perhaps even reduce the
> frequency of the report calls.

That sounds a good idea to measure the impact of those extra calls and see
if we'd need to mitigate the impacts. I'll collect some data.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com






^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-03 01:51  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-03-03 01:51 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: [email protected]

On Fri, Feb 28, 2025 at 10:39:31AM +0000, Bertrand Drouvot wrote:
> That sounds a good idea to measure the impact of those extra calls and see
> if we'd need to mitigate the impacts. I'll collect some data.

Thanks.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-03 11:54  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 2 replies; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-03 11:54 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: [email protected]

Hi,

On Mon, Mar 03, 2025 at 10:51:19AM +0900, Michael Paquier wrote:
> On Fri, Feb 28, 2025 at 10:39:31AM +0000, Bertrand Drouvot wrote:
> > That sounds a good idea to measure the impact of those extra calls and see
> > if we'd need to mitigate the impacts. I'll collect some data.

So I did some tests using only one walsender (given the fact that the extra
lock you mentioned above is "only" for this particular backend).

=== Test with pg_receivewal

I was using one pg_receivewal process and did some tests that way:

pgbench -n -c8 -j8 -T60 -f <(echo "SELECT pg_logical_emit_message(true, 'test', repeat('0', 1));";)

I did not measure any noticeable extra lag (I did measure the time it took
for pg_size_pretty(sent_lsn - write_lsn) from pg_stat_replication to be back
to zero).

During the pgbench run a "perf record --call-graph fp -p <walsender_pid>" would
report (perf report -n):

1. pgstat_flush_backend() appears at about 3%
2. pg_memory_is_all_zeros() at about 2.8%
3. pgstat_flush_io() at about 0.4%

So it does not look like what we're adding here can be seen as a primary bottleneck.

That said it looks like that there is room for improvment in pgstat_flush_backend()
and that relying on a "have_iostats" like variable would be better than those
pg_memory_is_all_zeros() calls.

That's done in 0001 attached, by doing so, pgstat_flush_backend() now appears at
about 0.2%.

=== Test with pg_recvlogical

Now it does not look like pg_receivewal had a lot of IO stats to report (looking at
pg_stat_get_backend_io() output for the walsender).

Doing the same test with "pg_recvlogical -d postgres -S logical_slot -f /dev/null  --start"
reports much more IO stats.

What I observe without the "have_iostats" optimization is:

1. I did not measure any noticeable extra lag
2. pgstat_flush_io() at about 5.5% (pgstat_io_flush_cb() at about 5.3%)
3  pgstat_flush_backend() at about 4.8%

and with the "have_iostats" optimization I now see pgstat_flush_backend() at
about 2.51%.

So it does not look like what we're adding here can be seen as a primary bottleneck
but that is probably worth implementing the "have_iostats" optimization attached.

Also, while I did not measure any noticeable extra lag, given the fact that 
pgstat_flush_io() shows at about 5.5% and pgstat_flush_backend() at about 2.5%,
that could still make sense to reduce the frequency of the flush calls, thoughts?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com


Attachments:

  [text/x-diff] v3-0001-Flush-the-IO-statistics-of-active-walsenders.patch (2.9K, ../../[email protected]/2-v3-0001-Flush-the-IO-statistics-of-active-walsenders.patch)
  download | inline diff:
From 226f767f90e82ee128319f43226d4d0056756fa9 Mon Sep 17 00:00:00 2001
From: Bertrand Drouvot <[email protected]>
Date: Tue, 25 Feb 2025 10:18:05 +0000
Subject: [PATCH v3 1/2] Flush the IO statistics of active walsenders

The walsender does not flush its IO statistics until it exits.
The issue is there since pg_stat_io has been introduced in a9c70b46dbe.
This commits:

1. ensures it does not wait to exit to flush its IO statistics
2. adds a test for a physical walsender (a logical walsender had the same issue
but the fix is in the same code path)
---
 src/backend/replication/walsender.c   |  7 +++++++
 src/test/recovery/t/001_stream_rep.pl | 14 ++++++++++++++
 2 files changed, 21 insertions(+)
  26.8% src/backend/replication/
  73.1% src/test/recovery/t/

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 446d10c1a7d..9ddf111af25 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -90,6 +90,7 @@
 #include "utils/guc.h"
 #include "utils/memutils.h"
 #include "utils/pg_lsn.h"
+#include "utils/pgstat_internal.h"
 #include "utils/ps_status.h"
 #include "utils/timeout.h"
 #include "utils/timestamp.h"
@@ -2829,6 +2830,12 @@ WalSndLoop(WalSndSendDataCallback send_data)
 		/* Send keepalive if the time has come */
 		WalSndKeepaliveIfNecessary();
 
+		/*
+		 * Report IO statistics
+		 */
+		pgstat_flush_io(false);
+		(void) pgstat_flush_backend(false, PGSTAT_BACKEND_FLUSH_IO);
+
 		/*
 		 * Block if we have unsent data.  XXX For logical replication, let
 		 * WalSndWaitForWal() handle any other blocking; idle receivers need
diff --git a/src/test/recovery/t/001_stream_rep.pl b/src/test/recovery/t/001_stream_rep.pl
index ee57d234c86..aea32f68b79 100644
--- a/src/test/recovery/t/001_stream_rep.pl
+++ b/src/test/recovery/t/001_stream_rep.pl
@@ -42,6 +42,9 @@ $node_standby_2->init_from_backup($node_standby_1, $backup_name,
 	has_streaming => 1);
 $node_standby_2->start;
 
+# To check that an active walsender updates its IO statistics below.
+$node_primary->safe_psql('postgres', "SELECT pg_stat_reset_shared('io')");
+
 # Create some content on primary and check its presence in standby nodes
 $node_primary->safe_psql('postgres',
 	"CREATE TABLE tab_int AS SELECT generate_series(1,1002) AS a");
@@ -69,6 +72,17 @@ ALTER EVENT TRIGGER on_login_trigger ENABLE ALWAYS;
 $node_primary->wait_for_replay_catchup($node_standby_1);
 $node_standby_1->wait_for_replay_catchup($node_standby_2, $node_primary);
 
+# Ensure an active walsender updates its IO statistics.
+is( $node_primary->safe_psql(
+		'postgres',
+		qq(SELECT sum(reads) > 0
+       FROM pg_catalog.pg_stat_io
+       WHERE backend_type = 'walsender'
+       AND object = 'wal')
+	),
+	qq(t),
+	"Check that the walsender updates its IO statistics");
+
 my $result =
   $node_standby_1->safe_psql('postgres', "SELECT count(*) FROM tab_int");
 print "standby 1: $result\n";
-- 
2.34.1



  [text/x-diff] v3-0002-Add-a-new-backend_has_iostats-global-variable.patch (2.6K, ../../[email protected]/3-v3-0002-Add-a-new-backend_has_iostats-global-variable.patch)
  download | inline diff:
From 42cce18fd4565118c430bdd422f509361c8f86e5 Mon Sep 17 00:00:00 2001
From: Bertrand Drouvot <[email protected]>
Date: Mon, 3 Mar 2025 10:02:40 +0000
Subject: [PATCH v3 2/2] Add a new backend_has_iostats global variable

It behaves as the existing have_iostats and replace the existing pg_memory_is_all_zeros()
calls in flushing backend stats functions. Indeed some perf measurements report
that those calls are responsible for a large part of the flushing backend stats
functions.
---
 src/backend/utils/activity/pgstat_backend.c | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)
 100.0% src/backend/utils/activity/

diff --git a/src/backend/utils/activity/pgstat_backend.c b/src/backend/utils/activity/pgstat_backend.c
index a9343b7b59e..0ae3a1d4d23 100644
--- a/src/backend/utils/activity/pgstat_backend.c
+++ b/src/backend/utils/activity/pgstat_backend.c
@@ -37,6 +37,7 @@
  * memory allocation.
  */
 static PgStat_BackendPending PendingBackendStats;
+static bool backend_has_iostats = false;
 
 /*
  * Utility routines to report I/O stats for backends, kept here to avoid
@@ -68,6 +69,8 @@ pgstat_count_backend_io_op(IOObject io_object, IOContext io_context,
 
 	PendingBackendStats.pending_io.counts[io_object][io_context][io_op] += cnt;
 	PendingBackendStats.pending_io.bytes[io_object][io_context][io_op] += bytes;
+
+	backend_has_iostats = true;
 }
 
 /*
@@ -150,8 +153,7 @@ pgstat_flush_backend_entry_io(PgStat_EntryRef *entry_ref)
 	 * statistics.  In this case, avoid unnecessarily modifying the stats
 	 * entry.
 	 */
-	if (pg_memory_is_all_zeros(&PendingBackendStats.pending_io,
-							   sizeof(struct PgStat_PendingIO)))
+	if (!backend_has_iostats)
 		return;
 
 	shbackendent = (PgStatShared_Backend *) entry_ref->shared_stats;
@@ -182,6 +184,8 @@ pgstat_flush_backend_entry_io(PgStat_EntryRef *entry_ref)
 	 * Clear out the statistics buffer, so it can be re-used.
 	 */
 	MemSet(&PendingBackendStats.pending_io, 0, sizeof(PgStat_PendingIO));
+
+	backend_has_iostats = false;
 }
 
 /*
@@ -198,8 +202,7 @@ pgstat_flush_backend(bool nowait, bits32 flags)
 	if (!pgstat_tracks_backend_bktype(MyBackendType))
 		return false;
 
-	if (pg_memory_is_all_zeros(&PendingBackendStats,
-							   sizeof(struct PgStat_BackendPending)))
+	if (!pgstat_backend_have_pending_cb())
 		return false;
 
 	entry_ref = pgstat_get_entry_ref_locked(PGSTAT_KIND_BACKEND, InvalidOid,
@@ -222,8 +225,7 @@ pgstat_flush_backend(bool nowait, bits32 flags)
 bool
 pgstat_backend_have_pending_cb(void)
 {
-	return (!pg_memory_is_all_zeros(&PendingBackendStats,
-									sizeof(struct PgStat_BackendPending)));
+	return backend_has_iostats;
 }
 
 /*
-- 
2.34.1



^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-10 00:23  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  1 sibling, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-03-10 00:23 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: [email protected]

On Mon, Mar 03, 2025 at 11:54:39AM +0000, Bertrand Drouvot wrote:
> So it does not look like what we're adding here can be seen as a primary bottleneck
> but that is probably worth implementing the "have_iostats" optimization attached.
> 
> Also, while I did not measure any noticeable extra lag, given the fact that 
> pgstat_flush_io() shows at about 5.5% and pgstat_flush_backend() at about 2.5%,
> that could still make sense to reduce the frequency of the flush calls, thoughts?

Okay.  The number of reports really worry me anyway as proposed in the
patch.  It's not really complicated to see dozens of pgstats calls in
a single millisecond in the WAL sender, even with some of the
regression tests.  That's more present in the logirep scenarios, it
seems..

For example, here are some numbers based on some elog() calls planted
in walreceiver.c, looking at the logs of the TAP tests.  Through a
single check-world, I am able to gather the following information:
- The location proposed by the patch leads to 680k stats reports,
in WalSndLoop() because the "Block if we have unsent data".  Some
tests show quite some contention.
- A different location, in WalSndLoop() just before WalSndWait() leads
to 59k calls.  And there's some contention in the logirep tests..
- I've spotted a third candidate which looks pretty solid, actually:
WalSndWaitForWal() before WalSndWait().  This leads to 2.9k reports in
the whole test suite, with much less contention in the reports.  These
can still be rather frequent, up to ~50 calls per seconds, but that's
really less than the two others.

Stats data is useful as long as it is possible to get an idea of how
the system behaves, particularly with a steady workload.  More
frequent reports are useful for spikey data detection, showing more
noise.  Still, too many reports may cause the part gathering the
reports to become a bottleneck, while we want it to offer hints about
bottlenecks.  So I would argue in favor of a more conservative choice
in the back branches than what the patch is proposing.  Choice 3 i'm
quoting above is tempting by design: not too much, still frequent
enough to offer enough relevant information in the stats.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-10 14:52  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-10 14:52 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: [email protected]

Hi,

On Mon, Mar 10, 2025 at 09:23:50AM +0900, Michael Paquier wrote:
> On Mon, Mar 03, 2025 at 11:54:39AM +0000, Bertrand Drouvot wrote:
> > So it does not look like what we're adding here can be seen as a primary bottleneck
> > but that is probably worth implementing the "have_iostats" optimization attached.
> > 
> > Also, while I did not measure any noticeable extra lag, given the fact that 
> > pgstat_flush_io() shows at about 5.5% and pgstat_flush_backend() at about 2.5%,
> > that could still make sense to reduce the frequency of the flush calls, thoughts?
> 
> - I've spotted a third candidate which looks pretty solid, actually:
> WalSndWaitForWal() before WalSndWait().  This leads to 2.9k reports in
> the whole test suite, with much less contention in the reports.  These
> can still be rather frequent, up to ~50 calls per seconds, but that's
> really less than the two others.
> 
> Stats data is useful as long as it is possible to get an idea of how
> the system behaves, particularly with a steady workload.  More
> frequent reports are useful for spikey data detection, showing more
> noise.  Still, too many reports may cause the part gathering the
> reports to become a bottleneck, while we want it to offer hints about
> bottlenecks.  So I would argue in favor of a more conservative choice
> in the back branches than what the patch is proposing.

Yeah, fully agree. Anyway, having so many frequent stats reports makes little sense.

> Choice 3 i'm
> quoting above is tempting by design: not too much, still frequent
> enough to offer enough relevant information in the stats.

Yeah, I also agree that we should reduce the number of "reports". I'll look
at the third option.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-11 06:10  Bertrand Drouvot <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-11 06:10 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: [email protected]

Hi,

On Mon, Mar 10, 2025 at 02:52:42PM +0000, Bertrand Drouvot wrote:
> Hi,
> 
> On Mon, Mar 10, 2025 at 09:23:50AM +0900, Michael Paquier wrote:
> > On Mon, Mar 03, 2025 at 11:54:39AM +0000, Bertrand Drouvot wrote:
> > > So it does not look like what we're adding here can be seen as a primary bottleneck
> > > but that is probably worth implementing the "have_iostats" optimization attached.
> > > 
> > > Also, while I did not measure any noticeable extra lag, given the fact that 
> > > pgstat_flush_io() shows at about 5.5% and pgstat_flush_backend() at about 2.5%,
> > > that could still make sense to reduce the frequency of the flush calls, thoughts?
> > 
> > - I've spotted a third candidate which looks pretty solid, actually:
> > WalSndWaitForWal() before WalSndWait().  This leads to 2.9k reports in
> > the whole test suite, with much less contention in the reports.  These
> > can still be rather frequent, up to ~50 calls per seconds, but that's
> > really less than the two others.
> > 
> > Stats data is useful as long as it is possible to get an idea of how
> > the system behaves, particularly with a steady workload.  More
> > frequent reports are useful for spikey data detection, showing more
> > noise.  Still, too many reports may cause the part gathering the
> > reports to become a bottleneck, while we want it to offer hints about
> > bottlenecks.  So I would argue in favor of a more conservative choice
> > in the back branches than what the patch is proposing.
> 
> Yeah, fully agree. Anyway, having so many frequent stats reports makes little sense.
> 
> > Choice 3 i'm
> > quoting above is tempting by design: not too much, still frequent
> > enough to offer enough relevant information in the stats.
> 
> Yeah, I also agree that we should reduce the number of "reports". I'll look
> at the third option.

WalSndWaitForWal() is being used only for logical walsender. So we'd need to 
find another location for the physical walsender case. One option is to keep the
WalSndLoop() location and control the reports frequency.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-13 09:31  Bertrand Drouvot <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-13 09:31 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: [email protected]

Hi,

On Tue, Mar 11, 2025 at 06:10:32AM +0000, Bertrand Drouvot wrote:
> WalSndWaitForWal() is being used only for logical walsender. So we'd need to 
> find another location for the physical walsender case. One option is to keep the
> WalSndLoop() location and control the reports frequency.

I ended up with an idea in the same vein as your third one, but let's do it
in WalSndLoop() instead for both logical and physical walsenders. The idea
is to report the stats when the walsender is caught up or has pending data to
send. Also, we do flush only periodically (based on PGSTAT_MIN_INTERVAL).

Remarks/Questions:

1. maybe relying on PGSTAT_IDLE_INTERVAL would make more sense? In both case
PGSTAT_MIN_INTERVAL or PGSTAT_MIN_INTERVAL, I'm not sure there is a need to 
update the related doc.

2. bonus point to make it here is that we don't need an extra call to
GetCurrentTimestamp(). We simply assign the one that is already done to "now".

3. add to use poll_query_until() has I've seen failures on the CI whith this
new approach. Also moving the test far away from the stats reset to to minimize
the risk of polling for too long.

With the attached in place, the number of times the stats are being flushed
reduce drastically but still seems enough to get an accurate idea of the walsender
IO activity. Thoughts?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-13 11:33  Xuneng Zhou <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  1 sibling, 1 reply; 40+ messages in thread

From: Xuneng Zhou @ 2025-03-13 11:33 UTC (permalink / raw)
  To: [email protected]; +Cc: Michael Paquier <[email protected]>; Andres Freund <[email protected]>

Forgot to cc...

---------- Forwarded message ---------
发件人: Xuneng Zhou <[email protected]>
Date: 2025年3月13日周四 19:15
Subject: Re: [BUG]: the walsender does not update its IO statistics until
it exits
To: Bertrand Drouvot <[email protected]>


Hi,

Thanks for working on this! I'm glad to see that the patch (
https://www.postgresql.org/message-id/flat/Z3zqc4o09dM/[email protected])
has been committed.

Regarding patch 0001, the optimization in pgstat_backend_have_pending_cb
looks good:

bool
pgstat_backend_have_pending_cb(void)
{
- return (!pg_memory_is_all_zeros(&PendingBackendStats,
- sizeof(struct PgStat_BackendPending)));
+ return backend_has_iostats;
}

Additionally, the function pgstat_flush_backend includes the check:

+ if (!pgstat_backend_have_pending_cb())
    return false;

However, I think we might need to revise the comment (and possibly the
function name) for clarity:

/*
 * Check if there are any backend stats waiting to be flushed.
 */

Originally, this function was intended to check multiple types of backend
statistics, which made sense when PendingBackendStats was the centralized
structure for various pending backend stats. However, since
PgStat_PendingWalStats was removed from PendingBackendStats earlier, and
now this patch introduces the backend_has_iostats variable, the scope of
this function appears even narrower. This narrowed functionality no longer
aligns closely with the original function name and its associated comment.




Bertrand Drouvot <[email protected]> 于2025年3月3日周一 19:54写道:

> Hi,
>
> On Mon, Mar 03, 2025 at 10:51:19AM +0900, Michael Paquier wrote:
> > On Fri, Feb 28, 2025 at 10:39:31AM +0000, Bertrand Drouvot wrote:
> > > That sounds a good idea to measure the impact of those extra calls and
> see
> > > if we'd need to mitigate the impacts. I'll collect some data.
>
> So I did some tests using only one walsender (given the fact that the extra
> lock you mentioned above is "only" for this particular backend).
>
> === Test with pg_receivewal
>
> I was using one pg_receivewal process and did some tests that way:
>
> pgbench -n -c8 -j8 -T60 -f <(echo "SELECT pg_logical_emit_message(true,
> 'test', repeat('0', 1));";)
>
> I did not measure any noticeable extra lag (I did measure the time it took
> for pg_size_pretty(sent_lsn - write_lsn) from pg_stat_replication to be
> back
> to zero).
>
> During the pgbench run a "perf record --call-graph fp -p <walsender_pid>"
> would
> report (perf report -n):
>
> 1. pgstat_flush_backend() appears at about 3%
> 2. pg_memory_is_all_zeros() at about 2.8%
> 3. pgstat_flush_io() at about 0.4%
>
> So it does not look like what we're adding here can be seen as a primary
> bottleneck.
>
> That said it looks like that there is room for improvment in
> pgstat_flush_backend()
> and that relying on a "have_iostats" like variable would be better than
> those
> pg_memory_is_all_zeros() calls.
>
> That's done in 0001 attached, by doing so, pgstat_flush_backend() now
> appears at
> about 0.2%.
>
> === Test with pg_recvlogical
>
> Now it does not look like pg_receivewal had a lot of IO stats to report
> (looking at
> pg_stat_get_backend_io() output for the walsender).
>
> Doing the same test with "pg_recvlogical -d postgres -S logical_slot -f
> /dev/null  --start"
> reports much more IO stats.
>
> What I observe without the "have_iostats" optimization is:
>
> 1. I did not measure any noticeable extra lag
> 2. pgstat_flush_io() at about 5.5% (pgstat_io_flush_cb() at about 5.3%)
> 3  pgstat_flush_backend() at about 4.8%
>
> and with the "have_iostats" optimization I now see pgstat_flush_backend()
> at
> about 2.51%.
>
> So it does not look like what we're adding here can be seen as a primary
> bottleneck
> but that is probably worth implementing the "have_iostats" optimization
> attached.
>
> Also, while I did not measure any noticeable extra lag, given the fact
> that
> pgstat_flush_io() shows at about 5.5% and pgstat_flush_backend() at about
> 2.5%,
> that could still make sense to reduce the frequency of the flush calls,
> thoughts?
>
> Regards,
>
> --
> Bertrand Drouvot
> PostgreSQL Contributors Team
> RDS Open Source Databases
> Amazon Web Services: https://aws.amazon.com
>


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-13 11:35  Xuneng Zhou <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Xuneng Zhou @ 2025-03-13 11:35 UTC (permalink / raw)
  To: pgsql-hackers

Sorry, forgot to cc this one too.

---------- Forwarded message ---------
发件人: Xuneng Zhou <[email protected]>
Date: 2025年3月13日周四 19:29
Subject: Re: [BUG]: the walsender does not update its IO statistics until
it exits
To: Bertrand Drouvot <[email protected]>


Hi,
Given that PGSTAT_MIN_INTERVAL is the go-to setting for stats flushes
 * Unless called with 'force', pending stats updates are flushed happen once
 * per PGSTAT_MIN_INTERVAL (1000ms). When not forced, stats flushes do not
 * block on lock acquisition, except if stats updates have been pending for
 * longer than PGSTAT_MAX_INTERVAL (60000ms).
 *
 * Whenever pending stats updates remain at the end of pgstat_report_stat()
a
 * suggested idle timeout is returned. Currently this is always
 * PGSTAT_IDLE_INTERVAL (10000ms). Callers can use the returned time to set
up
 * a timeout after which to call pgstat_report_stat(true), but are not
 * required to do so.

 I am curious about the reason for this:


> 1. maybe relying on PGSTAT_IDLE_INTERVAL would make more sense? In both
> case
> PGSTAT_MIN_INTERVAL or PGSTAT_MIN_INTERVAL, I'm not sure there is a need to
> update the related doc.
>
>
PGSTAT_IDLE_INTERVAL seems to reduce the frequency even more.

>
> With the attached in place, the number of times the stats are being flushed
> reduce drastically but still seems enough to get an accurate idea of the
> walsender
> IO activity. Thoughts?
>
>
>


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-13 13:18  Bertrand Drouvot <[email protected]>
  parent: Xuneng Zhou <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-13 13:18 UTC (permalink / raw)
  To: Xuneng Zhou <[email protected]>; +Cc: [email protected]; Michael Paquier <[email protected]>; Andres Freund <[email protected]>

Hi,

On Thu, Mar 13, 2025 at 07:33:24PM +0800, Xuneng Zhou wrote:
> Regarding patch 0001, the optimization in pgstat_backend_have_pending_cb
> looks good:

Thanks for looking at it!

> bool
> pgstat_backend_have_pending_cb(void)
> {
> - return (!pg_memory_is_all_zeros(&PendingBackendStats,
> - sizeof(struct PgStat_BackendPending)));
> + return backend_has_iostats;
> }
> 
> Additionally, the function pgstat_flush_backend includes the check:
> 
> + if (!pgstat_backend_have_pending_cb())
>     return false;
> 
> However, I think we might need to revise the comment (and possibly the
> function name) for clarity:
> 
> /*
>  * Check if there are any backend stats waiting to be flushed.
>  */

The comment is not exactly this one on the current HEAD, it looks like that you're
looking at a previous version of the core code.

> Originally, this function was intended to check multiple types of backend
> statistics, which made sense when PendingBackendStats was the centralized
> structure for various pending backend stats. However, since
> PgStat_PendingWalStats was removed from PendingBackendStats earlier, and
> now this patch introduces the backend_has_iostats variable, the scope of
> this function appears even narrower. This narrowed functionality no longer
> aligns closely with the original function name and its associated comment.

I don't think so, as since 76def4cdd7c, a pgstat_backend_wal_have_pending() check
has been added to pgstat_backend_have_pending_cb(). You're probably looking at
a version prior to 76def4cdd7c.

This particular sub-patch needs a rebase though, done in the attached. 0001
remains unchanged as compared to the v4 one just shared up-thread. If 0001 goes
in, merging 0002 would be less beneficial (as compared to v3).

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-13 13:19  Bertrand Drouvot <[email protected]>
  parent: Xuneng Zhou <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-13 13:19 UTC (permalink / raw)
  To: Xuneng Zhou <[email protected]>; +Cc: pgsql-hackers

Hi,

On Thu, Mar 13, 2025 at 07:35:24PM +0800, Xuneng Zhou wrote:
> Hi,
> Given that PGSTAT_MIN_INTERVAL is the go-to setting for stats flushes
>  * Unless called with 'force', pending stats updates are flushed happen once
>  * per PGSTAT_MIN_INTERVAL (1000ms). When not forced, stats flushes do not
>  * block on lock acquisition, except if stats updates have been pending for
>  * longer than PGSTAT_MAX_INTERVAL (60000ms).
>  *
>  * Whenever pending stats updates remain at the end of pgstat_report_stat()
> a
>  * suggested idle timeout is returned. Currently this is always
>  * PGSTAT_IDLE_INTERVAL (10000ms). Callers can use the returned time to set
> up
>  * a timeout after which to call pgstat_report_stat(true), but are not
>  * required to do so.
> 
>  I am curious about the reason for this:

Thanks for looking at it!

> > 1. maybe relying on PGSTAT_IDLE_INTERVAL would make more sense? In both
> > case
> > PGSTAT_MIN_INTERVAL or PGSTAT_MIN_INTERVAL, I'm not sure there is a need to
> > update the related doc.
> >
> >
> PGSTAT_IDLE_INTERVAL seems to reduce the frequency even more.

Yeah, I think that PGSTAT_MIN_INTERVAL is the one to use (that's why that's the 
one the patch is using). I just mentioned PGSTAT_IDLE_INTERVAL as an open door
for conversation in case one prefers a "larger" frequency. 

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-18 08:11  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-03-18 08:11 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Xuneng Zhou <[email protected]>; [email protected]; Andres Freund <[email protected]>

On Thu, Mar 13, 2025 at 01:18:45PM +0000, Bertrand Drouvot wrote:
> This particular sub-patch needs a rebase though, done in the attached. 0001
> remains unchanged as compared to the v4 one just shared up-thread. If 0001 goes
> in, merging 0002 would be less beneficial (as compared to v3).

PgStat_PendingIO is already quite large, could get larger, and the
backend stats would be a natural victim of that.  What you are
proposing in v4-0002 is beneficial in any case outside of the specific
problem of this thread with WAL senders.  It is new code on HEAD and
pgstat_flush_backend_entry_io() being the only entry point where IO
data is appended makes it easy to reason about.  Just to say that I am
planning to apply this part on HEAD.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-18 09:51  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-18 09:51 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Xuneng Zhou <[email protected]>; [email protected]; Andres Freund <[email protected]>

Hi,

On Tue, Mar 18, 2025 at 05:11:02PM +0900, Michael Paquier wrote:
> On Thu, Mar 13, 2025 at 01:18:45PM +0000, Bertrand Drouvot wrote:
> > This particular sub-patch needs a rebase though, done in the attached. 0001
> > remains unchanged as compared to the v4 one just shared up-thread. If 0001 goes
> > in, merging 0002 would be less beneficial (as compared to v3).
> 
> PgStat_PendingIO is already quite large, could get larger, and the
> backend stats would be a natural victim of that.  What you are
> proposing in v4-0002 is beneficial in any case outside of the specific
> problem of this thread with WAL senders.

Yeah, I also think it makes sense independently of what has been discussed
in this thread.

> Just to say that I am planning to apply this part on HEAD.

Thanks!

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-18 11:14  Xuneng Zhou <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Xuneng Zhou @ 2025-03-18 11:14 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: pgsql-hackers; Michael Paquier <[email protected]>; Andres Freund <[email protected]>

Hi,

I performed some tests using elog(no so sure whether this is the proper way
to do it) to monitor the new method. Here are the findings:

• With PGSTAT_MIN_INTERVAL set to 1000ms, the number of flush reports was
reduced to approximately 40–50 during the installcheck test suite.

• With PGSTAT_IDLE_INTERVAL set to 10000ms, the reports dropped to fewer
than 5.

• In contrast, the previous approach—flushing after every
WalSndKeepaliveIfNecessary()—resulted in roughly 50,000 flushes.

This reduction is significant, so the overhead from the flush reports is no
longer a concern. However, we still need to determine whether this
frequency is sufficient to capture the system’s state during periods of
high WAL activity. Based on my tests, using PGSTAT_MIN_INTERVAL seems to
provide a better balance than PGSTAT_IDLE_INTERVAL.

>
> > > 1. maybe relying on PGSTAT_IDLE_INTERVAL would make more sense? In both
> > > case
> > > PGSTAT_MIN_INTERVAL or PGSTAT_MIN_INTERVAL, I'm not sure there is a
> need to
> > > update the related doc.
> > >
> > >
> > PGSTAT_IDLE_INTERVAL seems to reduce the frequency even more.
>
> Yeah, I think that PGSTAT_MIN_INTERVAL is the one to use (that's why
> that's the
> one the patch is using). I just mentioned PGSTAT_IDLE_INTERVAL as an open
> door
> for conversation in case one prefers a "larger" frequency.
>
>


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-18 14:45  Bertrand Drouvot <[email protected]>
  parent: Xuneng Zhou <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-18 14:45 UTC (permalink / raw)
  To: Xuneng Zhou <[email protected]>; +Cc: pgsql-hackers; Michael Paquier <[email protected]>; Andres Freund <[email protected]>

Hi,

On Tue, Mar 18, 2025 at 07:14:12PM +0800, Xuneng Zhou wrote:
> Hi,
> 
> I performed some tests using elog

Thanks for the testing!

> (no so sure whether this is the proper way
> to do it) to monitor the new method.

Well that simple enough and that works well if the goal is just to "count" ;-)

> Here are the findings:
> 
> • With PGSTAT_MIN_INTERVAL set to 1000ms, the number of flush reports was
> reduced to approximately 40–50 during the installcheck test suite.
> 
> • With PGSTAT_IDLE_INTERVAL set to 10000ms, the reports dropped to fewer
> than 5.
> 
> • In contrast, the previous approach—flushing after every
> WalSndKeepaliveIfNecessary()—resulted in roughly 50,000 flushes.
> 
> This reduction is significant, so the overhead from the flush reports is no
> longer a concern.

Yeah I did observe and do think the same.

> However, we still need to determine whether this
> frequency is sufficient to capture the system’s state during periods of
> high WAL activity.

I think that reporting at PGSTAT_MIN_INTERVAL is fine and more than enough. I
mean, I 'm not sure that there is a real use case to query the statistics related
view at more than a second interval anyway. Or are you concerned that we may not
enter the "When the WAL sender is caught up or has pending data to send" frequently
enough?

> Based on my tests, using PGSTAT_MIN_INTERVAL seems to
> provide a better balance than PGSTAT_IDLE_INTERVAL.

Same here.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-18 23:19  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-03-18 23:19 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Xuneng Zhou <[email protected]>; [email protected]; Andres Freund <[email protected]>

On Tue, Mar 18, 2025 at 09:51:14AM +0000, Bertrand Drouvot wrote:
> Thanks!

Done that part for now.  It will be possible to look at the bug fix
after the release freeze as it impacts stable branches as well.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-19 01:53  Xuneng Zhou <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Xuneng Zhou @ 2025-03-19 01:53 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: pgsql-hackers; Andres Freund <[email protected]>; Michael Paquier <[email protected]>

Hi,

I am OK with PGSTAT_MIN_INTERVAL. It has been used for flushing other
statistics as well. And monitoring systems are generally configured to poll
at one-second or longer intervals.

>
> I think that reporting at PGSTAT_MIN_INTERVAL is fine and more than
> enough. I
> mean, I 'm not sure that there is a real use case to query the statistics
> related
> view at more than a second interval anyway.


I think these two conditions are good too. In a busy system, they are met
frequently, so the flush routine will be executed at least once every
second. Conversely, when WAL generation is low, there's simply less data to
record, and the flush frequency naturally decreases.



> Or are you concerned that we may not
> enter the "When the WAL sender is caught up or has pending data to send"
> frequently
> enough?
>
> > Based on my tests, using PGSTAT_MIN_INTERVAL seems to
> > provide a better balance than PGSTAT_IDLE_INTERVAL.
>
> Same here.
>
>


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-19 05:26  Michael Paquier <[email protected]>
  parent: Xuneng Zhou <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-03-19 05:26 UTC (permalink / raw)
  To: Xuneng Zhou <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; pgsql-hackers; Andres Freund <[email protected]>

On Wed, Mar 19, 2025 at 09:53:16AM +0800, Xuneng Zhou wrote:
> I think these two conditions are good too. In a busy system, they are met
> frequently, so the flush routine will be executed at least once every
> second. Conversely, when WAL generation is low, there's simply less data to
> record, and the flush frequency naturally decreases.

Hmm, yeah, perhaps this is acceptable.  The changes in pgstat.c seem
inconsistent, though, only moving the min interval while the max and
idle times stay around.

This also make me wonder if we should work towards extending
pgstat_report_stat(), so as we save in GetCurrentTimestamp() while
making the internals still local to pgstat.c.  Or perhaps not in the
scope of a backpatchable design.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-19 05:26  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 0 replies; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-19 05:26 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Xuneng Zhou <[email protected]>; [email protected]; Andres Freund <[email protected]>

Hi,

On Wed, Mar 19, 2025 at 08:19:42AM +0900, Michael Paquier wrote:
> 
> Done that part for now.

Thanks!

> It will be possible to look at the bug fix
> after the release freeze as it impacts stable branches as well.

Yes, let's do that. Adding a reminder on my side.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-19 05:50  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-19 05:50 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Xuneng Zhou <[email protected]>; pgsql-hackers; Andres Freund <[email protected]>

Hi,

On Wed, Mar 19, 2025 at 02:26:47PM +0900, Michael Paquier wrote:
> On Wed, Mar 19, 2025 at 09:53:16AM +0800, Xuneng Zhou wrote:
> > I think these two conditions are good too. In a busy system, they are met
> > frequently, so the flush routine will be executed at least once every
> > second. Conversely, when WAL generation is low, there's simply less data to
> > record, and the flush frequency naturally decreases.
> 
> Hmm, yeah, perhaps this is acceptable.  The changes in pgstat.c seem
> inconsistent, though, only moving the min interval while the max and
> idle times stay around.

That's right. OTOH that sounds weird to move the others 2: that would create 
wider visibility for them without real needs. That's not a big issue,
but could impact extensions or friends that would start using those should we
change their values in the future. 

Another option could be to create a dedicated one in walsender.c but I'm not
sure I like it more.

> This also make me wonder if we should work towards extending
> pgstat_report_stat(), so as we save in GetCurrentTimestamp() while
> making the internals still local to pgstat.c.  Or perhaps not in the
> scope of a backpatchable design.

I see. I think I'd vote for making the same changes on HEAD and the STABLE branches
as a first step. And then think about a new "design" that could be part of the
ideas suggested by Andres in [1]. Thoughts?

Regards,

[1]: https://www.postgresql.org/message-id/erpzwxoptqhuptdrtehqydzjapvroumkhh7lc6poclbhe7jk7l%40l3yfsq5q4...

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-19 08:00  Xuneng Zhou <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Xuneng Zhou @ 2025-03-19 08:00 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; Michael Paquier <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]

Hi,
Moving the other two provides a more complete view of the settings. For
newcomers(like me) to the codebase, seeing all three related values in one
place helps avoid a narrow view of the settings.

But I am not sure that I understand the cons of this well.

Bertrand Drouvot <[email protected]> 于2025年3月19日周三 13:50写道:

> Hi,
>
> On Wed, Mar 19, 2025 at 02:26:47PM +0900, Michael Paquier wrote:
> > On Wed, Mar 19, 2025 at 09:53:16AM +0800, Xuneng Zhou wrote:
> > > I think these two conditions are good too. In a busy system, they are
> met
> > > frequently, so the flush routine will be executed at least once every
> > > second. Conversely, when WAL generation is low, there's simply less
> data to
> > > record, and the flush frequency naturally decreases.
> >
> > Hmm, yeah, perhaps this is acceptable.  The changes in pgstat.c seem
> > inconsistent, though, only moving the min interval while the max and
> > idle times stay around.
>
> That's right. OTOH that sounds weird to move the others 2: that would
> create
> wider visibility for them without real needs. That's not a big issue,
> but could impact extensions or friends that would start using those should
> we
> change their values in the future.
>

 The current name of the min interval appears consistent within the context
of the surrounding code in this patch.

Another option could be to create a dedicated one in walsender.c but I'm not
> sure I like it more.
>
>


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-23 23:41  Michael Paquier <[email protected]>
  parent: Xuneng Zhou <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-03-23 23:41 UTC (permalink / raw)
  To: Xuneng Zhou <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; Andres Freund <[email protected]>; [email protected]

On Wed, Mar 19, 2025 at 04:00:49PM +0800, Xuneng Zhou wrote:
> Hi,
> Moving the other two provides a more complete view of the settings. For
> newcomers(like me) to the codebase, seeing all three related values in one
> place helps avoid a narrow view of the settings.
> 
> But I am not sure that I understand the cons of this well.

While I don't disagree with the use of a hardcoded interval of time to
control timing the flush of the WAL sender stats, do we really need to
rely on the timing defined by pgstat.c?  Wouldn't it be simpler to
assign one in walsender.c and pick up a different, perhaps higher,
value?

At the end the timestamp calculations are free because we can rely on
the existing call of GetCurrentTimestamp() for the physical WAL
senders to get an idea of the current time.  For the logical WAL
senders, perhaps we'd better do the reports in WalSndWaitForWal(),
actually.  There is also a call to GetCurrentTimestamp() that we can
rely on in this path.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-03-31 13:05  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-03-31 13:05 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

Hi,

On Mon, Mar 24, 2025 at 08:41:20AM +0900, Michael Paquier wrote:
> On Wed, Mar 19, 2025 at 04:00:49PM +0800, Xuneng Zhou wrote:
> > Hi,
> > Moving the other two provides a more complete view of the settings. For
> > newcomers(like me) to the codebase, seeing all three related values in one
> > place helps avoid a narrow view of the settings.
> > 
> > But I am not sure that I understand the cons of this well.
> 
> While I don't disagree with the use of a hardcoded interval of time to
> control timing the flush of the WAL sender stats, do we really need to
> rely on the timing defined by pgstat.c?

No but I thought it could make sense.

> Wouldn't it be simpler to
> assign one in walsender.c and pick up a different, perhaps higher,
> value?

I don't have a strong opinion on it so done as suggested above in the attached.

I think that the 1s value is fine because: 1. it is consistent with 
PGSTAT_MIN_INTERVAL and 2. it already needs that the sender is caught up or
has pending data to send (means it could be higher than 1s already). That said,
I don't think that would hurt if you think of a higher value.

> At the end the timestamp calculations are free because we can rely on
> the existing call of GetCurrentTimestamp() for the physical WAL
> senders to get an idea of the current time.

Yup

> For the logical WAL
> senders, perhaps we'd better do the reports in WalSndWaitForWal(),
> actually.  There is also a call to GetCurrentTimestamp() that we can
> rely on in this path.

I think it's better to flush the stats in a shared code path. I think it's
easier to maintain and that there is no differences between logical and
physical walsenders that would justify to flush the stats in specific code
paths.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-03 03:55  vignesh C <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: vignesh C @ 2025-04-03 03:55 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Michael Paquier <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

On Mon, 31 Mar 2025 at 18:35, Bertrand Drouvot
<[email protected]> wrote:
>
> Hi,
>
> On Mon, Mar 24, 2025 at 08:41:20AM +0900, Michael Paquier wrote:
> > On Wed, Mar 19, 2025 at 04:00:49PM +0800, Xuneng Zhou wrote:
> > > Hi,
> > > Moving the other two provides a more complete view of the settings. For
> > > newcomers(like me) to the codebase, seeing all three related values in one
> > > place helps avoid a narrow view of the settings.
> > >
> > > But I am not sure that I understand the cons of this well.
> >
> > While I don't disagree with the use of a hardcoded interval of time to
> > control timing the flush of the WAL sender stats, do we really need to
> > rely on the timing defined by pgstat.c?
>
> No but I thought it could make sense.
>
> > Wouldn't it be simpler to
> > assign one in walsender.c and pick up a different, perhaps higher,
> > value?
>
> I don't have a strong opinion on it so done as suggested above in the attached.
>
> I think that the 1s value is fine because: 1. it is consistent with
> PGSTAT_MIN_INTERVAL and 2. it already needs that the sender is caught up or
> has pending data to send (means it could be higher than 1s already). That said,
> I don't think that would hurt if you think of a higher value.
>
> > At the end the timestamp calculations are free because we can rely on
> > the existing call of GetCurrentTimestamp() for the physical WAL
> > senders to get an idea of the current time.
>
> Yup
>
> > For the logical WAL
> > senders, perhaps we'd better do the reports in WalSndWaitForWal(),
> > actually.  There is also a call to GetCurrentTimestamp() that we can
> > rely on in this path.
>
> I think it's better to flush the stats in a shared code path. I think it's
> easier to maintain and that there is no differences between logical and
> physical walsenders that would justify to flush the stats in specific code
> paths.

Couple of suggestions:
1) I felt we can include a similar verification for one of the logical
replication tests too:
+# Wait for the walsender to update its IO statistics.

+# Has to be done before the next restart and far enough from the
+# pg_stat_reset_shared('io') to minimize the risk of polling for too long.
+$node_primary->poll_query_until(
+ 'postgres',
+ qq[SELECT sum(reads) > 0
+       FROM pg_catalog.pg_stat_io
+       WHERE backend_type = 'walsender'
+       AND object = 'wal']
+  )
+  or die
+  "Timed out while waiting for the walsender to update its IO statistics";
+

2) We can comment this in a single line itself:
+ /*
+ * Report IO statistics
+ */

Regards,
Vignesh





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-03 07:24  Bertrand Drouvot <[email protected]>
  parent: vignesh C <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-04-03 07:24 UTC (permalink / raw)
  To: vignesh C <[email protected]>; +Cc: Michael Paquier <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

Hi,

On Thu, Apr 03, 2025 at 09:25:02AM +0530, vignesh C wrote:
> On Mon, 31 Mar 2025 at 18:35, Bertrand Drouvot
> <[email protected]> wrote:
> >
> Couple of suggestions:

Thanks for looking at it!

> 1) I felt we can include a similar verification for one of the logical
> replication tests too:
> +# Wait for the walsender to update its IO statistics.
> 
> +# Has to be done before the next restart and far enough from the
> +# pg_stat_reset_shared('io') to minimize the risk of polling for too long.
> +$node_primary->poll_query_until(
> + 'postgres',
> + qq[SELECT sum(reads) > 0
> +       FROM pg_catalog.pg_stat_io
> +       WHERE backend_type = 'walsender'
> +       AND object = 'wal']
> +  )
> +  or die
> +  "Timed out while waiting for the walsender to update its IO statistics";
> +

Initially ([1]) it was added in 035_standby_logical_decoding.pl. But this
test (035) is already racy enough that I felt better to move it to 001_stream_rep.pl
(see [2]) instead.

I don't think that's a big issue as the code path being changed in the patch is
shared between logical and physical walsenders. That said that would not hurt to
add a logical walsender test, but I would prefer it to be outside
035_standby_logical_decoding.pl. Do you have a suggestion for the location of
such a test?

> 2) We can comment this in a single line itself:
> + /*
> + * Report IO statistics
> + */

Right, but:

- it's already done that way in walsender.c (see "Try to flush any pending output to the client"
for example).
- the exact same comment is written that way in pgstat_bgwriter.c and
pgstat_checkpointer.c

So that I just copy/paste it.

[1]: https://www.postgresql.org/message-id/Z73IsKBceoVd4t55%40ip-10-97-1-34.eu-west-3.compute.internal
[2]: https://www.postgresql.org/message-id/Z77jgvhwOu9S0a5r%40ip-10-97-1-34.eu-west-3.compute.internal

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-03 09:53  vignesh C <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: vignesh C @ 2025-04-03 09:53 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Michael Paquier <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

On Thu, 3 Apr 2025 at 12:54, Bertrand Drouvot
<[email protected]> wrote:
>
> Hi,
>
> On Thu, Apr 03, 2025 at 09:25:02AM +0530, vignesh C wrote:
> > On Mon, 31 Mar 2025 at 18:35, Bertrand Drouvot
> > <[email protected]> wrote:
> > >
> > Couple of suggestions:
>
> Thanks for looking at it!
>
> > 1) I felt we can include a similar verification for one of the logical
> > replication tests too:
> > +# Wait for the walsender to update its IO statistics.
> >
> > +# Has to be done before the next restart and far enough from the
> > +# pg_stat_reset_shared('io') to minimize the risk of polling for too long.
> > +$node_primary->poll_query_until(
> > + 'postgres',
> > + qq[SELECT sum(reads) > 0
> > +       FROM pg_catalog.pg_stat_io
> > +       WHERE backend_type = 'walsender'
> > +       AND object = 'wal']
> > +  )
> > +  or die
> > +  "Timed out while waiting for the walsender to update its IO statistics";
> > +
>
> Initially ([1]) it was added in 035_standby_logical_decoding.pl. But this
> test (035) is already racy enough that I felt better to move it to 001_stream_rep.pl
> (see [2]) instead.
>
> I don't think that's a big issue as the code path being changed in the patch is
> shared between logical and physical walsenders. That said that would not hurt to
> add a logical walsender test, but I would prefer it to be outside
> 035_standby_logical_decoding.pl. Do you have a suggestion for the location of
> such a test?

Can we add it to one of the subscription tests, such as 001_rep_changes.pl?

Regards,
Vignesh





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-04 05:01  Bertrand Drouvot <[email protected]>
  parent: vignesh C <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-04-04 05:01 UTC (permalink / raw)
  To: vignesh C <[email protected]>; +Cc: Michael Paquier <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

Hi,

On Thu, Apr 03, 2025 at 03:23:31PM +0530, vignesh C wrote:
> Can we add it to one of the subscription tests, such as 001_rep_changes.pl?

Yeah that sounds like a good place for it. Done in the attached.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-04 16:03  vignesh C <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: vignesh C @ 2025-04-04 16:03 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Michael Paquier <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

On Fri, 4 Apr 2025 at 10:31, Bertrand Drouvot
<[email protected]> wrote:
>
> Hi,
>
> On Thu, Apr 03, 2025 at 03:23:31PM +0530, vignesh C wrote:
> > Can we add it to one of the subscription tests, such as 001_rep_changes.pl?
>
> Yeah that sounds like a good place for it. Done in the attached.

The new test added currently passes even without the patch. It would
be ideal to have a test that fails without the patch and passes once
the patch is applied.

Regards,
Vignesh





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-07 06:31  Michael Paquier <[email protected]>
  parent: vignesh C <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-04-07 06:31 UTC (permalink / raw)
  To: vignesh C <[email protected]>; +Cc: Bertrand Drouvot <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

On Fri, Apr 04, 2025 at 09:33:46PM +0530, vignesh C wrote:
> The new test added currently passes even without the patch. It would
> be ideal to have a test that fails without the patch and passes once
> the patch is applied.

Right.  The subscription test and logical WAL senders passes without
the patch, because we are able to catch some WAL activity through
pgoutput.  The recovery test for physical WAL sender fails without the
patch on timeout.

We could need something more advanced here for the logical case, where
we could use pg_recvlogical started in the background with a hardcoded
endpos, or just kill the pg_recvlogical command once we have checked
the state of the stats.  I am not sure if this is worth the cycles
spent on, TBH, so I would be happy with just the physical case checked
in TAP as it's simpler because streaming replication makes that easy
to work with.

One thing that I'm a bit unhappy about in the patch is the choice to
do the stats updates in WalSndLoop() for the logical WAL sender case,
because this forces an extra GetCurrentTimestamp() call for each loop,
and that's never a cheap system call in what can be a hot code path.
How about doing the calculations in WalSndWaitForWal() for the logical
part, relying on the existing GetCurrentTimestamp() done there?
That's also where the waits are handled for the logical part, so there
may be a good point in keeping this code more symmetric for now,
rather than split it.

Saying that, here is a version 7 with all that included, which is
simpler to read.
--
Michael


Attachments:

  [text/x-diff] v7-0001-Flush-the-IO-statistics-of-active-walsenders.patch (5.7K, ../../[email protected]/2-v7-0001-Flush-the-IO-statistics-of-active-walsenders.patch)
  download | inline diff:
From 9f6dadc679cdc0da7c005d005a06dad6e81020ad Mon Sep 17 00:00:00 2001
From: Bertrand Drouvot <[email protected]>
Date: Tue, 25 Feb 2025 10:18:05 +0000
Subject: [PATCH v7] Flush the IO statistics of active walsenders

The walsender does not flush its IO statistics until it exits.
The issue is there since pg_stat_io has been introduced in a9c70b46dbe.
This commits:

1. ensures it does not wait to exit to flush its IO statistics
2. flush its IO statistics periodically to not overload the walsender
3. adds a test for a physical walsender and a test for a logical walsender
---
 src/backend/replication/walsender.c   | 36 +++++++++++++++++++++++++--
 src/test/recovery/t/001_stream_rep.pl | 15 +++++++++++
 2 files changed, 49 insertions(+), 2 deletions(-)

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 1028919aecb1..216baeda5cd2 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -91,10 +91,14 @@
 #include "utils/guc.h"
 #include "utils/memutils.h"
 #include "utils/pg_lsn.h"
+#include "utils/pgstat_internal.h"
 #include "utils/ps_status.h"
 #include "utils/timeout.h"
 #include "utils/timestamp.h"
 
+/* Minimum interval used by walsender for stats flushes, in ms */
+#define WALSENDER_STATS_FLUSH_INTERVAL         1000
+
 /*
  * Maximum data payload in a WAL data message.  Must be >= XLOG_BLCKSZ.
  *
@@ -1797,6 +1801,7 @@ WalSndWaitForWal(XLogRecPtr loc)
 	int			wakeEvents;
 	uint32		wait_event = 0;
 	static XLogRecPtr RecentFlushPtr = InvalidXLogRecPtr;
+	TimestampTz last_flush = 0;
 
 	/*
 	 * Fast path to avoid acquiring the spinlock in case we already know we
@@ -1817,6 +1822,7 @@ WalSndWaitForWal(XLogRecPtr loc)
 	{
 		bool		wait_for_standby_at_stop = false;
 		long		sleeptime;
+		TimestampTz now;
 
 		/* Clear any already-pending wakeups */
 		ResetLatch(MyLatch);
@@ -1927,7 +1933,8 @@ WalSndWaitForWal(XLogRecPtr loc)
 		 * new WAL to be generated.  (But if we have nothing to send, we don't
 		 * want to wake on socket-writable.)
 		 */
-		sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
+		now = GetCurrentTimestamp();
+		sleeptime = WalSndComputeSleeptime(now);
 
 		wakeEvents = WL_SOCKET_READABLE;
 
@@ -1936,6 +1943,15 @@ WalSndWaitForWal(XLogRecPtr loc)
 
 		Assert(wait_event != 0);
 
+		/* Report IO statistics, if needed */
+		if (TimestampDifferenceExceeds(last_flush, now,
+									   WALSENDER_STATS_FLUSH_INTERVAL))
+		{
+			pgstat_flush_io(false);
+			(void) pgstat_flush_backend(false, PGSTAT_BACKEND_FLUSH_IO);
+			last_flush = now;
+		}
+
 		WalSndWait(wakeEvents, sleeptime, wait_event);
 	}
 
@@ -2742,6 +2758,8 @@ WalSndCheckTimeOut(void)
 static void
 WalSndLoop(WalSndSendDataCallback send_data)
 {
+	TimestampTz last_flush = 0;
+
 	/*
 	 * Initialize the last reply timestamp. That enables timeout processing
 	 * from hereon.
@@ -2836,6 +2854,9 @@ WalSndLoop(WalSndSendDataCallback send_data)
 		 * WalSndWaitForWal() handle any other blocking; idle receivers need
 		 * its additional actions.  For physical replication, also block if
 		 * caught up; its send_data does not block.
+		 *
+		 * The IO statistics are reported in WalSndWaitForWal() for the
+		 * logical WAL senders.
 		 */
 		if ((WalSndCaughtUp && send_data != XLogSendLogical &&
 			 !streamingDoneSending) ||
@@ -2843,6 +2864,7 @@ WalSndLoop(WalSndSendDataCallback send_data)
 		{
 			long		sleeptime;
 			int			wakeEvents;
+			TimestampTz now;
 
 			if (!streamingDoneReceiving)
 				wakeEvents = WL_SOCKET_READABLE;
@@ -2853,11 +2875,21 @@ WalSndLoop(WalSndSendDataCallback send_data)
 			 * Use fresh timestamp, not last_processing, to reduce the chance
 			 * of reaching wal_sender_timeout before sending a keepalive.
 			 */
-			sleeptime = WalSndComputeSleeptime(GetCurrentTimestamp());
+			now = GetCurrentTimestamp();
+			sleeptime = WalSndComputeSleeptime(now);
 
 			if (pq_is_send_pending())
 				wakeEvents |= WL_SOCKET_WRITEABLE;
 
+			/* Report IO statistics, if needed */
+			if (TimestampDifferenceExceeds(last_flush, now,
+										   WALSENDER_STATS_FLUSH_INTERVAL))
+			{
+				pgstat_flush_io(false);
+				(void) pgstat_flush_backend(false, PGSTAT_BACKEND_FLUSH_IO);
+				last_flush = now;
+			}
+
 			/* Sleep until something happens or we time out */
 			WalSndWait(wakeEvents, sleeptime, WAIT_EVENT_WAL_SENDER_MAIN);
 		}
diff --git a/src/test/recovery/t/001_stream_rep.pl b/src/test/recovery/t/001_stream_rep.pl
index ccd8417d449f..e55d8ec0ec17 100644
--- a/src/test/recovery/t/001_stream_rep.pl
+++ b/src/test/recovery/t/001_stream_rep.pl
@@ -42,6 +42,9 @@ $node_standby_2->init_from_backup($node_standby_1, $backup_name,
 	has_streaming => 1);
 $node_standby_2->start;
 
+# Reset IO statistics, for the WAL sender check with pg_stat_io.
+$node_primary->safe_psql('postgres', "SELECT pg_stat_reset_shared('io')");
+
 # Create some content on primary and check its presence in standby nodes
 $node_primary->safe_psql('postgres',
 	"CREATE TABLE tab_int AS SELECT generate_series(1,1002) AS a");
@@ -333,6 +336,18 @@ $node_primary->psql(
 
 note "switching to physical replication slot";
 
+# Wait for the walsender to update its IO statistics.  This is done before
+# the next restart and far enough from the reset done above.
+$node_primary->poll_query_until(
+	'postgres',
+	qq[SELECT sum(reads) > 0
+       FROM pg_catalog.pg_stat_io
+       WHERE backend_type = 'walsender'
+       AND object = 'wal']
+  )
+  or die
+  "Timed out while waiting for the walsender to update its IO statistics";
+
 # Switch to using a physical replication slot. We can do this without a new
 # backup since physical slots can go backwards if needed. Do so on both
 # standbys. Since we're going to be testing things that affect the slot state,
-- 
2.49.0



  [application/pgp-signature] signature.asc (833B, ../../[email protected]/3-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-07 07:13  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-04-07 07:13 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: vignesh C <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

Hi,

On Mon, Apr 07, 2025 at 03:31:14PM +0900, Michael Paquier wrote:
> On Fri, Apr 04, 2025 at 09:33:46PM +0530, vignesh C wrote:
> > The new test added currently passes even without the patch. It would
> > be ideal to have a test that fails without the patch and passes once
> > the patch is applied.
> 
> Right.  The subscription test and logical WAL senders passes without
> the patch, because we are able to catch some WAL activity through
> pgoutput.  The recovery test for physical WAL sender fails without the
> patch on timeout.
> 
> We could need something more advanced here for the logical case, where
> we could use pg_recvlogical started in the background with a hardcoded
> endpos, or just kill the pg_recvlogical command once we have checked
> the state of the stats.  I am not sure if this is worth the cycles
> spent on,

Another option for the logical walsender is to reset the stats once the
subscription is created like in the attached. With the attached in place the
test now fails without the patch in place (and passes with the patch).

> One thing that I'm a bit unhappy about in the patch is the choice to
> do the stats updates in WalSndLoop() for the logical WAL sender case,
> because this forces an extra GetCurrentTimestamp() call for each loop,
> and that's never a cheap system call in what can be a hot code path.
> How about doing the calculations in WalSndWaitForWal() for the logical
> part, relying on the existing GetCurrentTimestamp() done there?
> That's also where the waits are handled for the logical part, so there
> may be a good point in keeping this code more symmetric for now,
> rather than split it.

Well, while I was working on a reproducer case for the logical walsender (that
lead to the attached), I realized that the test was looping for relatively long
time before passing. Then I was changing the patch to do *exactly* what you did
propose in v7 and the logical walsender test now passes quickly enough...

So it looks like that the idea of using a "shared" code path was not that good
and that spliting physical/logical as done in v7 is a good choice.

But...

> TBH, so I would be happy with just the physical case checked
> in TAP as it's simpler because streaming replication makes that easy
> to work with.

As we now have 2 code paths I think we "really" need 2 tests. The attached
(to apply on top of v7) seems to do the job.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

commit e3d9337aa01539ce77553d95db47aa919d1f501c
Author: Bertrand Drouvot <[email protected]>
Date:   Mon Apr 7 06:56:08 2025 +0000

    logical walsender test

diff --git a/src/test/subscription/t/001_rep_changes.pl b/src/test/subscription/t/001_rep_changes.pl
index 8726fe04ad2..2253ee48312 100644
--- a/src/test/subscription/t/001_rep_changes.pl
+++ b/src/test/subscription/t/001_rep_changes.pl
@@ -113,6 +113,9 @@ $node_subscriber->safe_psql('postgres',
 # Wait for initial table sync to finish
 $node_subscriber->wait_for_subscription_sync($node_publisher, 'tap_sub');
 
+# To check that an active walsender updates its IO statistics below.
+$node_publisher->safe_psql('postgres', "SELECT pg_stat_reset_shared('io')");
+
 my $result =
   $node_subscriber->safe_psql('postgres', "SELECT count(*) FROM tab_notrep");
 is($result, qq(0), 'check non-replicated table is empty on subscriber');
@@ -184,6 +187,19 @@ $result =
   $node_subscriber->safe_psql('postgres', "SELECT count(*) FROM tab_no_col");
 is($result, qq(2), 'check replicated changes for table having no columns');
 
+# Wait for the walsender to update its IO statistics.
+# Has to be done before the next restart and far enough from the
+# pg_stat_reset_shared('io') to minimize the risk of polling for too long.
+$node_publisher->poll_query_until(
+	'postgres',
+	qq[SELECT sum(reads) > 0
+       FROM pg_catalog.pg_stat_io
+       WHERE backend_type = 'walsender'
+       AND object = 'wal']
+  )
+  or die
+  "Timed out while waiting for the walsender to update its IO statistics";
+
 # insert some duplicate rows
 $node_publisher->safe_psql('postgres',
 	"INSERT INTO tab_full SELECT generate_series(1,10)");


Attachments:

  [text/plain] add_logical_walsender_test.txt (1.6K, ../../Z%[email protected]/2-add_logical_walsender_test.txt)
  download | inline diff:
commit e3d9337aa01539ce77553d95db47aa919d1f501c
Author: Bertrand Drouvot <[email protected]>
Date:   Mon Apr 7 06:56:08 2025 +0000

    logical walsender test

diff --git a/src/test/subscription/t/001_rep_changes.pl b/src/test/subscription/t/001_rep_changes.pl
index 8726fe04ad2..2253ee48312 100644
--- a/src/test/subscription/t/001_rep_changes.pl
+++ b/src/test/subscription/t/001_rep_changes.pl
@@ -113,6 +113,9 @@ $node_subscriber->safe_psql('postgres',
 # Wait for initial table sync to finish
 $node_subscriber->wait_for_subscription_sync($node_publisher, 'tap_sub');
 
+# To check that an active walsender updates its IO statistics below.
+$node_publisher->safe_psql('postgres', "SELECT pg_stat_reset_shared('io')");
+
 my $result =
   $node_subscriber->safe_psql('postgres', "SELECT count(*) FROM tab_notrep");
 is($result, qq(0), 'check non-replicated table is empty on subscriber');
@@ -184,6 +187,19 @@ $result =
   $node_subscriber->safe_psql('postgres', "SELECT count(*) FROM tab_no_col");
 is($result, qq(2), 'check replicated changes for table having no columns');
 
+# Wait for the walsender to update its IO statistics.
+# Has to be done before the next restart and far enough from the
+# pg_stat_reset_shared('io') to minimize the risk of polling for too long.
+$node_publisher->poll_query_until(
+	'postgres',
+	qq[SELECT sum(reads) > 0
+       FROM pg_catalog.pg_stat_io
+       WHERE backend_type = 'walsender'
+       AND object = 'wal']
+  )
+  or die
+  "Timed out while waiting for the walsender to update its IO statistics";
+
 # insert some duplicate rows
 $node_publisher->safe_psql('postgres',
 	"INSERT INTO tab_full SELECT generate_series(1,10)");


^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-04-07 23:00  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 0 replies; 40+ messages in thread

From: Michael Paquier @ 2025-04-07 23:00 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: vignesh C <[email protected]>; Xuneng Zhou <[email protected]>; Andres Freund <[email protected]>; [email protected]

On Mon, Apr 07, 2025 at 07:13:20AM +0000, Bertrand Drouvot wrote:
> As we now have 2 code paths I think we "really" need 2 tests. The attached
> (to apply on top of v7) seems to do the job.

Confirmed.  I am sold on this extra location on HEAD, and it does not
impact the run time of the test as there is enough activity happening
between the resets and the poll check.  So, done down to v16.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-09-30 07:14  Bertrand Drouvot <[email protected]>
  2 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-09-30 07:14 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]

Hi,

On Thu, Feb 27, 2025 at 12:09:46PM +0900, Michael Paquier wrote:
> On Wed, Feb 26, 2025 at 05:08:17AM -0500, Andres Freund wrote:
> > I think it's also bad that we don't have a solution for 1), even just for
> > normal connections. If a backend causes a lot of IO we might want to know
> > about that long before the longrunning transaction commits.
> > 
> > I suspect the right design here would be to have a generalized form of the
> > timeout mechanism we have for 2).
> > 
> > For that we'd need to make sure that pgstat_report_stat() can be safely called
> > inside a transaction.  The second part would be to redesign the
> > IdleStatsUpdateTimeoutPending mechanism so it is triggered independent of
> > idleness, without introducing unacceptable overhead - I think that's doable.
> 
> Agreed that something in the lines of non-transaction update of the
> entries could be adapted in some cases, so +1 for the idea.  I suspect
> that there would be cases where a single stats kind should be able to
> handle both transactional and non-transactional flush cases.
> Splitting that across two stats kinds would lead to a lot of
> duplication.

One option could be to use 2 pending lists for the variables stats and 2 flush
callbacks for fixed stats. Thoughts?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-09-30 07:16  Bertrand Drouvot <[email protected]>
  2 siblings, 0 replies; 40+ messages in thread

From: Bertrand Drouvot @ 2025-09-30 07:16 UTC (permalink / raw)
  To: Andres Freund <[email protected]>; +Cc: Michael Paquier <[email protected]>; [email protected]

Hi,

On Wed, Feb 26, 2025 at 05:08:17AM -0500, Andres Freund wrote:
> Hi,
> 
> On 2025-02-26 15:37:10 +0900, Michael Paquier wrote:
> > That's bad, worse for a logical WAL sender, because it means that we
> > have no idea what kind of I/O happens in this process until it exits,
> > and logical WAL senders could loop forever, since v16 where we've
> > begun tracking I/O.
> 
> FWIW, I think medium term we need to work on splitting stats flushing into two
> separate kinds of flushes:
> 1) non-transactional stats, which should be flushed at a regular interval,
>    unless a process is completely idle
> 2) transaction stats, which can only be flushed at transaction boundaries,
>    because before the transaction boundary we don't know if e.g. newly
>    inserted rows should be counted as live or dead
> 
> So far we have some timer logic for 2), but we have basically no support for
> 1). Which means we have weird ad-hoc logic in various kinds of
> non-plain-connection processes. And that will often have holes, as Bertrand
> noticed here.
> 
> I think it's also bad that we don't have a solution for 1), even just for
> normal connections. If a backend causes a lot of IO we might want to know
> about that long before the longrunning transaction commits.
> 
> I suspect the right design here would be to have a generalized form of the
> timeout mechanism we have for 2).
> 
> For that we'd need to make sure that pgstat_report_stat() can be safely called
> inside a transaction.

I can see an issue with GetCurrentTransactionStopTimestamp(), any other issue
/concern you have in mind?

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-09-30 07:37  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-09-30 07:37 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]

On Tue, Sep 30, 2025 at 07:14:14AM +0000, Bertrand Drouvot wrote:
> On Thu, Feb 27, 2025 at 12:09:46PM +0900, Michael Paquier wrote:
>> Agreed that something in the lines of non-transaction update of the
>> entries could be adapted in some cases, so +1 for the idea.  I suspect
>> that there would be cases where a single stats kind should be able to
>> handle both transactional and non-transactional flush cases.
>> Splitting that across two stats kinds would lead to a lot of
>> duplication.
> 
> One option could be to use 2 pending lists for the variables stats and 2 flush
> callbacks for fixed stats. Thoughts?

Hmm.  I would have thought first about one pending area, and two
callbacks for the variable-sized stats, called with a different
timing because the stats to be flushed are the same aren't they?  For
example, if we are in a long analytical query, we would flush the IO
stats periodically, reset the pending data, repeat/rinse periodically, 
and do a last round when we are done with the query in postgres.c.

Do we really need a second callback by the way?  It could be as well
the same flush callback, with an option to mark stats kinds that allow
a periodic flush.  The trick is knowing where the new reports calls
should happen.  The executor is the primary target area.

Or perhaps you think that the pending data of a stats kind could be
different if a kind allows transactional and non-transactional
flushes? 
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-09-30 10:05  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Bertrand Drouvot @ 2025-09-30 10:05 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]

Hi,

On Tue, Sep 30, 2025 at 04:37:25PM +0900, Michael Paquier wrote:
> On Tue, Sep 30, 2025 at 07:14:14AM +0000, Bertrand Drouvot wrote:
> > On Thu, Feb 27, 2025 at 12:09:46PM +0900, Michael Paquier wrote:
> >> Agreed that something in the lines of non-transaction update of the
> >> entries could be adapted in some cases, so +1 for the idea.  I suspect
> >> that there would be cases where a single stats kind should be able to
> >> handle both transactional and non-transactional flush cases.
> >> Splitting that across two stats kinds would lead to a lot of
> >> duplication.
> > 
> > One option could be to use 2 pending lists for the variables stats and 2 flush
> > callbacks for fixed stats. Thoughts?
> 
> Hmm.  I would have thought first about one pending area, and two
> callbacks for the variable-sized stats, called with a different
> timing because the stats to be flushed are the same aren't they?  For
> example, if we are in a long analytical query, we would flush the IO
> stats periodically, reset the pending data, repeat/rinse periodically, 
> and do a last round when we are done with the query in postgres.c.
> 
> Do we really need a second callback by the way?  It could be as well
> the same flush callback, with an option to mark stats kinds that allow
> a periodic flush.  The trick is knowing where the new reports calls
> should happen.  The executor is the primary target area.
> 
> Or perhaps you think that the pending data of a stats kind could be
> different if a kind allows transactional and non-transactional
> flushes? 

Yeah that was my thought: one stats kind could have metrics that are transactional
and some metrics that are non-transactional. This could be possible for
both variable and fixed stats, that's why I was thinking about having
2 pending lists for the variables stats and 2 flush callbacks for fixed stats.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-09-30 22:43  Michael Paquier <[email protected]>
  parent: Bertrand Drouvot <[email protected]>
  0 siblings, 1 reply; 40+ messages in thread

From: Michael Paquier @ 2025-09-30 22:43 UTC (permalink / raw)
  To: Bertrand Drouvot <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]

On Tue, Sep 30, 2025 at 10:05:43AM +0000, Bertrand Drouvot wrote:
> On Tue, Sep 30, 2025 at 04:37:25PM +0900, Michael Paquier wrote:
>> Or perhaps you think that the pending data of a stats kind could be
>> different if a kind allows transactional and non-transactional
>> flushes? 
> 
> Yeah that was my thought: one stats kind could have metrics that are transactional
> and some metrics that are non-transactional. This could be possible for
> both variable and fixed stats, that's why I was thinking about having
> 2 pending lists for the variables stats and 2 flush callbacks for fixed stats.

Okay.  The first use case that comes into mind here is pgstat_io.c, to
offer periodic reports on analytics (please extend that to the backend
stats for WAL and I/O).  In this case, it seems that it would be good
to know about all the stats fields, meaning that a single pending list
is OK.  My feeling would be to reuse pgstat_report_stat() and plant a
new argument for the transactional state (or just a bits32 that works
along the force option) with the same threshold for reports, combined
with a new option to allow non-transactional reports (don't see a
point in forcing these and wait on locks, 1-min reports not happening
would not matter if an analytical query takes a few hours).

It would be better to determine a list of the stats we'd be
interesting in seeing updated without waiting for a query or a 
transaction to finish, then design the needs around these
requirements, with a new thread to discuss the matter.  The IO stats
are just the first case coming into mind.
--
Michael


Attachments:

  [application/pgp-signature] signature.asc (833B, ../../[email protected]/2-signature.asc)
  download

^ permalink  raw  reply  [nested|flat] 40+ messages in thread

* Re: [BUG]: the walsender does not update its IO statistics until it exits
@ 2025-10-01 14:21  Bertrand Drouvot <[email protected]>
  parent: Michael Paquier <[email protected]>
  0 siblings, 0 replies; 40+ messages in thread

From: Bertrand Drouvot @ 2025-10-01 14:21 UTC (permalink / raw)
  To: Michael Paquier <[email protected]>; +Cc: Andres Freund <[email protected]>; [email protected]

Hi,

On Wed, Oct 01, 2025 at 07:43:31AM +0900, Michael Paquier wrote:
> On Tue, Sep 30, 2025 at 10:05:43AM +0000, Bertrand Drouvot wrote:
> > On Tue, Sep 30, 2025 at 04:37:25PM +0900, Michael Paquier wrote:
> >> Or perhaps you think that the pending data of a stats kind could be
> >> different if a kind allows transactional and non-transactional
> >> flushes? 
> > 
> > Yeah that was my thought: one stats kind could have metrics that are transactional
> > and some metrics that are non-transactional. This could be possible for
> > both variable and fixed stats, that's why I was thinking about having
> > 2 pending lists for the variables stats and 2 flush callbacks for fixed stats.
> 
> Okay.  The first use case that comes into mind here is pgstat_io.c, to
> offer periodic reports on analytics (please extend that to the backend
> stats for WAL and I/O).  In this case, it seems that it would be good
> to know about all the stats fields, meaning that a single pending list
> is OK.  My feeling would be to reuse pgstat_report_stat() and plant a
> new argument for the transactional state (or just a bits32 that works
> along the force option) with the same threshold for reports, combined
> with a new option to allow non-transactional reports (don't see a
> point in forcing these and wait on locks, 1-min reports not happening
> would not matter if an analytical query takes a few hours).
> 
> It would be better to determine a list of the stats we'd be
> interesting in seeing updated without waiting for a query or a 
> transaction to finish, then design the needs around these
> requirements, with a new thread to discuss the matter.  The IO stats
> are just the first case coming into mind.

Yeah. Also for the relations stats we'd have a mix (for example there is no
need to wait for a transaction to finish to report it's related seq_scan if
any).

I'll work on a list and open a dedicated thread.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com





^ permalink  raw  reply  [nested|flat] 40+ messages in thread


end of thread, other threads:[~2025-10-01 14:21 UTC | newest]

Thread overview: 40+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-02-07 18:09 [PATCH v4 2/2] Do COPY FROM encoding conversion/verification in larger chunks. Heikki Linnakangas <[email protected]>
2025-02-28 05:41 ` Re: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-02-28 08:44   ` Re: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-02-28 10:39   ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-03 01:51     ` Re: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-03 11:54       ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-10 00:23         ` Re: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-10 14:52           ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-11 06:10             ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-13 09:31               ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-13 11:35                 ` Fwd: [BUG]: the walsender does not update its IO statistics until it exits Xuneng Zhou <[email protected]>
2025-03-13 13:19                   ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-18 11:14                     ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Xuneng Zhou <[email protected]>
2025-03-18 14:45                       ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-19 01:53                         ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Xuneng Zhou <[email protected]>
2025-03-19 05:26                           ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-19 05:50                             ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-19 08:00                               ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Xuneng Zhou <[email protected]>
2025-03-23 23:41                                 ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-31 13:05                                   ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-04-03 03:55                                     ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits vignesh C <[email protected]>
2025-04-03 07:24                                       ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-04-03 09:53                                         ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits vignesh C <[email protected]>
2025-04-04 05:01                                           ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-04-04 16:03                                             ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits vignesh C <[email protected]>
2025-04-07 06:31                                               ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-04-07 07:13                                                 ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-04-07 23:00                                                   ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-13 11:33         ` Fwd: [BUG]: the walsender does not update its IO statistics until it exits Xuneng Zhou <[email protected]>
2025-03-13 13:18           ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-18 08:11             ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-18 09:51               ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-03-18 23:19                 ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-03-19 05:26                   ` Re: Fwd: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-09-30 07:14 ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-09-30 07:37   ` Re: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-09-30 10:05     ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-09-30 22:43       ` Re: [BUG]: the walsender does not update its IO statistics until it exits Michael Paquier <[email protected]>
2025-10-01 14:21         ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[email protected]>
2025-09-30 07:16 ` Re: [BUG]: the walsender does not update its IO statistics until it exits Bertrand Drouvot <[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