Subject: Re: Add Pipelining support in psql

From: Michael Paquier <[email-masked]>
Date: Thu, 6 Mar 2025 13:20:37 +0900

On Wed, Mar 05, 2025 at 03:25:12PM +0100, Daniel Verite wrote:
> 	Anthonin Bonnefoy wrote:
>> I do see the idea to make it easier to convert existing scripts into
>> using pipelining. The main focus of the initial implementation was
>> more on protocol regression tests with psql, so that's not necessarily
>> something I had in mind.
> 
> Understood. Yet pipelining can accelerate considerably certain scripts
> when client-server latency is an issue. We should expect end users to
> benefit from it too.

That was not a test case we had in mind originally here, but if it is
possible to keep the implementation simple while supporting your
demand, well, let's do it.  If it's not that straight-forward, let's
use the new meta-command, forbidding \g and \gx based on your
arguments from upthread.
--
Michael

---

From: "a.kozhemyakin" <[email-masked]>
Date: Wed, 16 Apr 2025 21:31:59 +0700

Hello,

After commit 2cce0fe on master

When executing query:
psql postgres <<EOF
CREATE TABLE psql_pipeline();
\startpipeline
COPY psql_pipeline FROM STDIN;
SELECT 'val1';
\syncpipeline
\getresults
EOF

ERROR:  unexpected message type 0x50 during COPY from stdin
CONTEXT:  COPY psql_pipeline, line 1
Pipeline aborted, command did not run
psql: common.c:1510: discardAbortedPipelineResults: Assertion `res == 
((void *)0) || result_status == PGRES_PIPELINE_ABORTED' failed.
Aborted (core dumped)

The psql crashes with the stack trace:
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6, 
threadid=<optimized out>) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=<optimized out>) at 
./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) 
at ./nptl/pthread_kill.c:89
#3  0x0000760edd24527e in __GI_raise (sig=sig@entry=6) at 
../sysdeps/posix/raise.c:26
#4  0x0000760edd2288ff in __GI_abort () at ./stdlib/abort.c:79
#5  0x0000760edd22881b in __assert_fail_base (fmt=0x760edd3d01e8 
"%s%s%s:%u: %s%sAssertion `%s' failed.\n%n",
     assertion=assertion@entry=0x5ba46ab79850 "res == ((void *)0) || 
result_status == PGRES_PIPELINE_ABORTED", file=file@entry=0x5ba46ab6fcad 
"common.c",
     line=line@entry=1510, function=function@entry=0x5ba46ab9c780 
<__PRETTY_FUNCTION__.3> "discardAbortedPipelineResults") at 
./assert/assert.c:96
#6  0x0000760edd23b517 in __assert_fail 
(assertion=assertion@entry=0x5ba46ab79850 "res == ((void *)0) || 
result_status == PGRES_PIPELINE_ABORTED",
     file=file@entry=0x5ba46ab6fcad "common.c", line=line@entry=1510,
     function=function@entry=0x5ba46ab9c780 <__PRETTY_FUNCTION__.3> 
"discardAbortedPipelineResults") at ./assert/assert.c:105
#7  0x00005ba46ab2bd40 in discardAbortedPipelineResults () at common.c:1510
#8  ExecQueryAndProcessResults (query=query@entry=0x5ba4a2ec1e10 "SELECT 
'val1';", elapsed_msec=elapsed_msec@entry=0x7ffeb07262a8,
     svpt_gone_p=svpt_gone_p@entry=0x7ffeb07262a7, 
is_watch=is_watch@entry=false, min_rows=min_rows@entry=0, 
opt=opt@entry=0x0, printQueryFout=0x0)
     at common.c:1811
#9  0x00005ba46ab2983f in SendQuery (query=0x5ba4a2ec1e10 "SELECT 
'val1';") at common.c:1212
#10 0x00005ba46ab3f66a in MainLoop (source=source@entry=0x760edd4038e0 
<_IO_2_1_stdin_>) at mainloop.c:515
#11 0x00005ba46ab23f2a in process_file (filename=0x0, 
use_relative_path=use_relative_path@entry=false) at command.c:4870
#12 0x00005ba46ab1e9d9 in main (argc=<optimized out>, 
argv=0x7ffeb07269d8) at startup.c:420

---

From: Michael Paquier <[email-masked]>
Date: Wed, 16 Apr 2025 09:18:01 -0700

On Wed, Apr 16, 2025 at 09:31:59PM +0700, a.kozhemyakin wrote:
> psql: common.c:1510: discardAbortedPipelineResults: Assertion `res == ((void
> *)0) || result_status == PGRES_PIPELINE_ABORTED' failed.
> Aborted (core dumped)

Reproduced here, thanks for the report.  I'll look at that at the
beginning of next week, adding an open item for now.
--
Michael

---

From: Michael Paquier <[email-masked]>
Date: Mon, 21 Apr 2025 15:22:28 +0900

> beginning of next week, adding an open item for now.

The failure is not related to 2cce0fe.  The following sequence fails
as well, as long as we have one SELECT after the COPY to mess up with
the \getresults that causes a PGRES_FATAL_ERROR combined with a
"terminating connection because protocol synchronization was lost" on
the backend side, because the server expects some data while the
client does not send it but psql is not able to cope with this state:
\startpipeline
COPY psql_pipeline FROM STDIN \bind \sendpipeline
SELECT $1 \bind 'val1' \sendpipeline
\syncpipeline
\getresults
\endpipeline

It's actually nice that we are able to emulate such query patterns
with psql using all these meta-commands, I don't think we have
any coverage for the backend synchronization loss case yet like this
one?

2cce0fe makes that easier to reach by allowing more command patterns,
but it's the mix of COPY followed by a SELECT that causes psql to be
confused.  All the tests that we have don't check this kind of
scenarios, for COPY TO/FROM, with always use a flush or a sync
followed quickly by \getresults, but we don't have tests where we mix
things.

Anyway, I don't think that there is much we can do under a
PGRES_FATAL_ERROR in this code path when discarding the pipe results.
As far as I can tell, the server has failed the query suddenly and the
whole pipeline flow is borked.  The best thing that I can think of is
to discard all the results while decrementing the counters, then let
psql complain about that like in the attached.  I've added two tests
in TAP, as these trigger a FATAL in the backend so we cannot use the
normal SQL route, so as we have some coverage.

@Anthonin: Any thoughts or comments, perhaps?  A second opinion would
be welcome here.
--
Michael
From cec3613b43f536ec1f91a75a034264ed304cd628 Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Mon, 21 Apr 2025 15:17:43 +0900
Subject: [PATCH] psql: Fix assertion failure with pipeline mode

---
 src/bin/psql/common.c       | 20 ++++++++++++++++++++
 src/bin/psql/t/001_basic.pl | 35 +++++++++++++++++++++++++++++++----
 2 files changed, 51 insertions(+), 4 deletions(-)

diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 21d660a8961a..6eb56d7bb66e 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1478,6 +1478,26 @@ discardAbortedPipelineResults(void)
 			 */
 			return res;
 		}
+		else if (result_status == PGRES_FATAL_ERROR)
+		{
+			/*
+			 * Fatal error found from a query execution failure, there is not
+			 * much that can be done, so give up and clear all the results
+			 * available.  There may be more than one result stacked.
+			 */
+			PQclear(res);
+
+			if (pset.available_results > 0)
+				pset.available_results--;
+			if (pset.requested_results > 0)
+				pset.requested_results--;
+
+			/* leave if no more results */
+			if (pset.requested_results == 0)
+				return NULL;
+			else
+				continue;
+		}
 		else if (res == NULL)
 		{
 			/* A query was processed, decrement the counters */
diff --git a/src/bin/psql/t/001_basic.pl b/src/bin/psql/t/001_basic.pl
index 739cb4397087..91c56cd7c08c 100644
--- a/src/bin/psql/t/001_basic.pl
+++ b/src/bin/psql/t/001_basic.pl
@@ -34,11 +34,13 @@ sub psql_fails_like
 {
 	local $Test::Builder::Level = $Test::Builder::Level + 1;
 
-	my ($node, $sql, $expected_stderr, $test_name) = @_;
+	my ($node, $sql, $expected_stderr, $test_name, $replication) = @_;
+
+	# Use the context of a WAL sender, if requested by the caller.
+	$replication = '' unless defined($replication);
 
-	# Use the context of a WAL sender, some of the tests rely on that.
 	my ($ret, $stdout, $stderr) =
-	  $node->psql('postgres', $sql, replication => 'database');
+	  $node->psql('postgres', $sql, replication => $replication);
 
 	isnt($ret, 0, "$test_name: exit code not 0");
 	like($stderr, $expected_stderr, "$test_name: matches");
@@ -79,7 +81,8 @@ psql_fails_like(
 	$node,
 	'START_REPLICATION 0/0',
 	qr/unexpected PQresultStatus: 8$/,
-	'handling of unexpected PQresultStatus');
+	'handling of unexpected PQresultStatus',
+	'database');
 
 # test \timing
 psql_like(
@@ -481,4 +484,28 @@ psql_like($node, "copy (values ('foo'),('bar')) to stdout \\g | $pipe_cmd",
 my $c4 = slurp_file($g_file);
 like($c4, qr/foo.*bar/s);
 
+# Tests with pipelines.  These trigger FATAL failures in the backend,
+# so they cannot be tested through the SQL regression tests.
+$node->safe_psql('postgres', 'CREATE TABLE psql_pipeline()');
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN;
+SELECT 'val1';
+\\syncpipeline
+\\getresults
+\\endpipeline},
+	qr/unexpected message type 0x50 during COPY from stdin/,
+	'handling of protocol synchronization loss with pipelines');
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN \\bind \\sendpipeline
+SELECT 'val1' \\bind \\sendpipeline
+\\syncpipeline
+\\getresults
+\\endpipeline},
+	qr/unexpected message type 0x50 during COPY from stdin/,
+	'handling of protocol synchronization loss with pipelines');
+
 done_testing();
-- 
2.49.0

---

From: Michael Paquier <[email-masked]>
Date: Tue, 22 Apr 2025 09:06:20 +0900

> @Anthonin: Any thoughts or comments, perhaps?  A second opinion would

While considering more ways to test this patch, I've recalled that
injection points that issue a FATAL in the backend to emulate the
original failure with more query patterns can provide more coverage,
and the discard cleanup is showing stable enough as presented in the
patch.  I am wondering if we could not be smarter with the handling of
the counters, but I really doubt that there is much more we can do
under a PGRES_FATAL_ERROR.
--
Michael

---

From: Anthonin Bonnefoy <[email-masked]>
Date: Tue, 22 Apr 2025 14:37:19 +0200

On Tue, Apr 22, 2025 at 2:06 AM Michael Paquier <[email-masked]> wrote:
> I am wondering if we could not be smarter with the handling of

One thing that bothers me is that the reported error is silently
discarded within discardAbortedPipelineResults.

psql -f bug_assertion.sql
psql:bug_assertion.sql:7: ERROR:  unexpected message type 0x50 during
COPY from stdin
CONTEXT:  COPY psql_pipeline, line 1
psql:bug_assertion.sql:7: Pipeline aborted, command did not run

This should ideally report the "FATAL:  terminating connection because
protocol synchronization was lost" sent by the backend process.

Also, we still have a triggered assertion failure with the following:
CREATE TABLE psql_pipeline(a text);
\startpipeline
COPY psql_pipeline FROM STDIN;
SELECT 'val1';
\syncpipeline
\endpipeline
...
Assertion failed: (pset.piped_syncs == 0), function
ExecQueryAndProcessResults, file common.c, line 2153.

A possible alternative could be to abort discardAbortedPipelineResults
when we encounter a res != NULL + FATAL error and let the outer loop
handle it. As you said, the pipeline flow is borked so there's not
much to salvage. The outer loop would read and print all error
messages until the closed connection is detected. Then,
CheckConnection will reset the connection which will reset the
pipeline state.

While testing this change, I was initially looking for the "FATAL:
terminating connection because protocol synchronization was lost"
message in the tests. However, this was failing on Windows[1] as the
FATAL message wasn't reported on stderr. I'm not sure why yet.

[1]: https://cirrus-ci.com/task/5051031505076224?logs=check_world#L240-L246

---

From: Michael Paquier <[email-masked]>
Date: Wed, 23 Apr 2025 16:13:14 +0900

> ExecQueryAndProcessResults, file common.c, line 2153.

Right.  I didn't think about the case of a \endpipeline that fetches
all the results by itself.

> CheckConnection will reset the connection which will reset the

Sounds like a better idea seen from here, yes.

> FATAL message wasn't reported on stderr. I'm not sure why yet.

Hmm.  I vaguely recall that there could be some race condition here
with the attempt to catch up the FATAL message once the server tries
to shut down the connection..

Anyway, I agree that it would be nice to track that this specific
error message is generated in the server.  How about checking the
server logs instead, using a slurp_file() with an offset of the log
file before running each pipeline sequence?  We should use a few
wait_for_log() calls, I think, to be extra careful with the timings
where psql_fails_like() gives up, and I'm worried that this could be
unstable on slow machines.  Something like the attached seems stable
enough here.  What do you think?

The tweak for psql_fails_like() was kind of independent of the rest of
the fix, so I have applied that as a commit of its own.  I am not
convinced about the addition of a 4th test where we use the queries
with semicolons without a \getresults between the sync and the end.
--
Michael
From 2641356ffacc0c69779a6252a8072f41521c0f3f Mon Sep 17 00:00:00 2001
From: Michael Paquier <[email-masked]>
Date: Wed, 23 Apr 2025 15:52:24 +0900
Subject: [PATCH v3] psql: Fix assertion failure with pipeline mode

---
 src/bin/psql/common.c       | 17 +++++++++++++
 src/bin/psql/t/001_basic.pl | 49 +++++++++++++++++++++++++++++++++++++
 2 files changed, 66 insertions(+)

diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 21d660a8961a..0aab02ee32e6 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1478,6 +1478,23 @@ discardAbortedPipelineResults(void)
 			 */
 			return res;
 		}
+		else if (res != NULL && result_status == PGRES_FATAL_ERROR)
+		{
+			/*
+			 * We have a fatal error sent by the backend and we can't recover
+			 * from this state. Instead, return the last fatal error and let
+			 * the outer loop handle it.
+			 */
+			PGresult   *fatal_res PG_USED_FOR_ASSERTS_ONLY;
+
+			/*
+			 * Fetch result to consume the end of the current query being
+			 * processed.
+			 */
+			fatal_res = PQgetResult(pset.db);
+			Assert(fatal_res == NULL);
+			return res;
+		}
 		else if (res == NULL)
 		{
 			/* A query was processed, decrement the counters */
diff --git a/src/bin/psql/t/001_basic.pl b/src/bin/psql/t/001_basic.pl
index b0e4919d4d71..3cada3ba959b 100644
--- a/src/bin/psql/t/001_basic.pl
+++ b/src/bin/psql/t/001_basic.pl
@@ -483,4 +483,53 @@ psql_like($node, "copy (values ('foo'),('bar')) to stdout \\g | $pipe_cmd",
 my $c4 = slurp_file($g_file);
 like($c4, qr/foo.*bar/s);
 
+# Tests with pipelines.  These trigger FATAL failures in the backend,
+# so they cannot be tested through the SQL regression tests.
+$node->safe_psql('postgres', 'CREATE TABLE psql_pipeline()');
+my $log_location = -s $node->logfile;
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN;
+SELECT 'val1';
+\\syncpipeline
+\\getresults
+\\endpipeline},
+	qr/server closed the connection unexpectedly/,
+	'protocol sync loss in pipeline: direct COPY, SELECT, sync and getresult'
+);
+$node->wait_for_log(
+	qr/FATAL: .*terminating connection because protocol synchronization was lost/,
+	$log_location);
+
+$log_location = -s $node->logfile;
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN \\bind \\sendpipeline
+SELECT 'val1' \\bind \\sendpipeline
+\\syncpipeline
+\\getresults
+\\endpipeline},
+	qr/server closed the connection unexpectedly/,
+	'protocol sync loss in pipeline: bind COPY, SELECT, sync and getresult');
+$node->wait_for_log(
+	qr/FATAL: .*terminating connection because protocol synchronization was lost/,
+	$log_location);
+
+# This time, test without the \getresults.
+$log_location = -s $node->logfile;
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN;
+SELECT 'val1';
+\\syncpipeline
+\\endpipeline},
+	qr/server closed the connection unexpectedly/,
+	'protocol sync loss in pipeline: COPY, SELECT and sync');
+$node->wait_for_log(
+	qr/FATAL: .*terminating connection because protocol synchronization was lost/,
+	$log_location);
+
 done_testing();
-- 
2.49.0

---

From: Michael Paquier <[email-masked]>
Date: Thu, 24 Apr 2025 12:26:33 +0900

> with semicolons without a \getresults between the sync and the end.

I've had some room to look again at all that this morning as this is
an open item, and I have applied the fix.  One tweak was in the tests,
where I have added only one wait_for_log() which should offer enough
coverage.

If you notice anything else, please let me know.
--
Michael