Date: Fri, 16 Jul 2021 15:30:13 +0900
From: Yugo NAGATA <nagata@sraoss.co.jp>
To: pgsql-hackers@postgresql.org
Subject: pgbench: using prepared BEGIN statement in a pipeline could cause
 an error
Message-Id: <20210716153013.fc53b1c780b06fccc07a7f0d@sraoss.co.jp>
Mime-Version: 1.0
Content-Type: multipart/mixed;
 boundary="Multipart=_Fri__16_Jul_2021_15_30_13_+0900_4cKaGN5.YlWAWcqf"
Archived-At: 
 <https://www.postgresql.org/message-id/20210716153013.fc53b1c780b06fccc07a7f0d%40sraoss.co.jp>
Precedence: bulk

This is a multi-part message in MIME format.

--Multipart=_Fri__16_Jul_2021_15_30_13_+0900_4cKaGN5.YlWAWcqf
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit

Hello,

I found that using "BEGIN ISOLATINO LEVEL SERIALIZABLE" in a pipline with
prepared statement makes pgbench abort.

 $ cat pipeline.sql 
 \startpipeline
 begin isolation level repeatable read;
 select 1;
 end;
 \endpipeline

 $ pgbench -f pipeline.sql -M prepared -t 1
 pgbench (15devel)
 starting vacuum...end.
 pgbench: error: client 0 script 0 aborted in command 4 query 0: 
 transaction type: pipeline.sql
 scaling factor: 1
 query mode: prepared
 number of clients: 1
 number of threads: 1
 number of transactions per client: 1
 number of transactions actually processed: 0/1
 pgbench: fatal: Run was aborted; the above results are incomplete.

The error that occured in the backend was
"ERROR:  SET TRANSACTION ISOLATION LEVEL must be called before any query".

After investigating this, now I've got the cause as below. 

1. The commands in the script are executed in the order. First, pipeline
   mode starts at \startpipeline.
2. Parse messages for all SQL commands in the script are sent to the backend
   because it is first time to execute them.
3. An implicit transaction starts, and this is not committed yet because Sync
   message is not sent at that time in pipeline mode.
4. All prepared statements are sent to the backend.
5. After processing \endpipeline, Sync is issued and all sent commands are
   executed.
6. However, the BEGIN doesn't start new transaction because the implicit
   transaction has already started.  The error above occurs because the snapshot
   was already created before the BEGIN command.

We can also see the similar error when using "BEGIN DEFERRABLE". 

One way to avoid these errors is to send Parse messages before pipeline mode
starts. I attached a patch to fix to prepare commands at starting of a script
instead of at the first execution of the command. 

Or, we can also avoid these errors by placing \startpipeline after the BEGIN, 
so it might be enogh just to note in the documentation. 

Actually, we also get an error just when there is another SQL command before the
BEGIN in a pipelne, as below, regardless to using prepared statement or not,
because this command cause an implicit transaction.

 \startpipeline
 select 0;
 begin isolation level repeatable read;
 select 1;
 end;
 \endpipeline

I think it is hard to prevent this error from pgbench without analysing command
strings. Therefore, noting  in the documentation that the first command in a pipeline
starts an implicit transaction might be useful for users.


What do you think?


Regards,
Yugo Nagata

-- 
Yugo NAGATA <nagata@sraoss.co.jp>

--Multipart=_Fri__16_Jul_2021_15_30_13_+0900_4cKaGN5.YlWAWcqf
Content-Type: text/x-diff;
 name="pgbench-prepare.patch"
Content-Disposition: attachment;
 filename="pgbench-prepare.patch"
Content-Transfer-Encoding: 7bit

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 364b5a2e47..56e790fa33 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -2858,6 +2858,30 @@ chooseScript(TState *thread)
 	return i - 1;
 }
 
+/* Prepare SQL commands in the chosen script */
+static void
+prepareCommands(CState *st)
+{
+	int			j;
+	Command   **commands = sql_script[st->use_file].commands;
+
+	for (j = 0; commands[j] != NULL; j++)
+	{
+		PGresult   *res;
+		char		name[MAX_PREPARE_NAME];
+
+		if (commands[j]->type != SQL_COMMAND)
+			continue;
+		preparedStatementName(name, st->use_file, j);
+		res = PQprepare(st->con, name,
+						commands[j]->argv[0], commands[j]->argc - 1, NULL);
+		if (PQresultStatus(res) != PGRES_COMMAND_OK)
+			pg_log_error("%s", PQerrorMessage(st->con));
+		PQclear(res);
+	}
+	st->prepared[st->use_file] = true;
+}
+
 /* Send a SQL command, using the chosen querymode */
 static bool
 sendCommand(CState *st, Command *command)
@@ -2891,42 +2915,6 @@ sendCommand(CState *st, Command *command)
 		char		name[MAX_PREPARE_NAME];
 		const char *params[MAX_ARGS];
 
-		if (!st->prepared[st->use_file])
-		{
-			int			j;
-			Command   **commands = sql_script[st->use_file].commands;
-
-			for (j = 0; commands[j] != NULL; j++)
-			{
-				PGresult   *res;
-				char		name[MAX_PREPARE_NAME];
-
-				if (commands[j]->type != SQL_COMMAND)
-					continue;
-				preparedStatementName(name, st->use_file, j);
-				if (PQpipelineStatus(st->con) == PQ_PIPELINE_OFF)
-				{
-					res = PQprepare(st->con, name,
-									commands[j]->argv[0], commands[j]->argc - 1, NULL);
-					if (PQresultStatus(res) != PGRES_COMMAND_OK)
-						pg_log_error("%s", PQerrorMessage(st->con));
-					PQclear(res);
-				}
-				else
-				{
-					/*
-					 * In pipeline mode, we use asynchronous functions. If a
-					 * server-side error occurs, it will be processed later
-					 * among the other results.
-					 */
-					if (!PQsendPrepare(st->con, name,
-									   commands[j]->argv[0], commands[j]->argc - 1, NULL))
-						pg_log_error("%s", PQerrorMessage(st->con));
-				}
-			}
-			st->prepared[st->use_file] = true;
-		}
-
 		getQueryParams(st, command, params);
 		preparedStatementName(name, st->use_file, st->command);
 
@@ -3194,6 +3182,11 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
 					memset(st->prepared, 0, sizeof(st->prepared));
 				}
 
+
+				/* Prepare SQL commands if not yet */
+				if (querymode == QUERY_PREPARED && !st->prepared[st->use_file])
+					prepareCommands(st);
+
 				/* record transaction start time */
 				st->txn_begin = now;
 

--Multipart=_Fri__16_Jul_2021_15_30_13_+0900_4cKaGN5.YlWAWcqf--