[Marina Polyakova <m.polyakova@postgrespro.ru>]

Hello, hackers!

Now in pgbench we can test only transactions with Read Committed 
isolation level because client sessions are disconnected forever on 
serialization failures. There were some proposals and discussions about 
it (see message here [1] and thread here [2]).

I suggest a patch where pgbench client sessions are not disconnected 
because of serialization or deadlock failures and these failures are 
mentioned in reports. In details:
- transaction with one of these failures continue run normally, but its 
result is rolled back;
- if there were these failures during script execution this 
"transaction" is marked
appropriately in logs;
- numbers of "transactions" with these failures are printed in progress, 
in aggregation logs and in the end with other results (all and for each 
script);

Advanced options:
- mostly for testing built-in scripts: you can set the default 
transaction isolation level by the appropriate benchmarking option (-I);
- for more detailed reports: to know per-statement serialization and 
deadlock failures you can use the appropriate benchmarking option 
(--report-failures).

Also: TAP tests for new functionality and changed documentation with new 
examples.

Patches are attached. Any suggestions are welcome!

P.S. Does this use case (do not retry transaction with serialization or 
deadlock failure) is most interesting or failed transactions should be 
retried (and how much times if there seems to be no hope of success...)?

[1] 
https://www.postgresql.org/message-id/4EC65830020000250004323F%40gw.wicourts.gov
[2] 
https://www.postgresql.org/message-id/flat/alpine.DEB.2.02.1305182259550.1473%40localhost6.localdoma...

-- 
Marina Polyakova
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Attachments:

v1-0001-Pgbench-Serialization-and-deadlock-errors.patch (text/x-diff, 19.5K) download
From c393e68c8da0c691fdccdfd4a584d035b18f982e Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Fri, 9 Jun 2017 14:42:30 +0300
Subject: [PATCH v1 1/4] Pgbench Serialization and deadlock errors

Now session is not disconnected because of serialization or deadlock errors.
If there were such errors during script execution this "transaction" is marked
appropriately in logs. Numbers of "transactions" with such errors are printed in
progress, in aggregation logs and in the end with other results (all and for
each script).
---
 src/bin/pgbench/pgbench.c                     | 169 +++++++++++++++++++++-----
 src/bin/pgbench/t/002_serialization_errors.pl |  75 ++++++++++++
 src/bin/pgbench/t/003_deadlock_errors.pl      |  93 ++++++++++++++
 3 files changed, 308 insertions(+), 29 deletions(-)
 create mode 100644 src/bin/pgbench/t/002_serialization_errors.pl
 create mode 100644 src/bin/pgbench/t/003_deadlock_errors.pl

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index ae36247..bbf444b 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -58,6 +58,9 @@
 
 #include "pgbench.h"
 
+#define ERRCODE_IN_FAILED_SQL_TRANSACTION  "25P02"
+#define ERRCODE_T_R_SERIALIZATION_FAILURE  "40001"
+#define ERRCODE_T_R_DEADLOCK_DETECTED  "40P01"
 #define ERRCODE_UNDEFINED_TABLE  "42P01"
 
 /*
@@ -232,6 +235,10 @@ typedef struct StatsData
 	int64		cnt;			/* number of transactions */
 	int64		skipped;		/* number of transactions skipped under --rate
 								 * and --latency-limit */
+	int64		serialization_failures;	/* number of transactions with
+										 * serialization failures */
+	int64		deadlock_failures; /* number of transactions with deadlock
+									* failures */
 	SimpleStats latency;
 	SimpleStats lag;
 } StatsData;
@@ -330,6 +337,10 @@ typedef struct
 
 	/* per client collected stats */
 	int64		cnt;			/* transaction count */
+	bool		serialization_failure;	/* if there was serialization failure
+										 * during script execution */
+	bool		deadlock_failure;	/* if there was deadlock failure during
+									 * script execution */
 	int			ecnt;			/* error count */
 } CState;
 
@@ -786,6 +797,8 @@ initStats(StatsData *sd, time_t start_time)
 	sd->start_time = start_time;
 	sd->cnt = 0;
 	sd->skipped = 0;
+	sd->serialization_failures = 0;
+	sd->deadlock_failures = 0;
 	initSimpleStats(&sd->latency);
 	initSimpleStats(&sd->lag);
 }
@@ -794,14 +807,20 @@ initStats(StatsData *sd, time_t start_time)
  * Accumulate one additional item into the given stats object.
  */
 static void
-accumStats(StatsData *stats, bool skipped, double lat, double lag)
+accumStats(StatsData *stats, bool skipped, bool serialization_failure,
+		   bool deadlock_failure, double lat, double lag)
 {
 	stats->cnt++;
 
-	if (skipped)
+	if (skipped || serialization_failure || deadlock_failure)
 	{
-		/* no latency to record on skipped transactions */
-		stats->skipped++;
+		/* no latency to record on such transactions */
+		if (skipped)
+			stats->skipped++;
+		if (serialization_failure)
+			stats->serialization_failures++;
+		if (deadlock_failure)
+			stats->deadlock_failures++;
 	}
 	else
 	{
@@ -1962,6 +1981,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 	instr_time	now;
 	bool		end_tx_processed = false;
 	int64		wait;
+	bool		serialization_failure = false;
+	bool		deadlock_failure = false;
+	bool		in_failed_transaction = false;
+	ExecStatusType result_status;
+	char	   *sqlState;
 
 	/*
 	 * gettimeofday() isn't free, so we get the current timestamp lazily the
@@ -2121,6 +2145,10 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 						st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);
 				}
 
+				/* reset transaction variables to default values */
+				st->serialization_failure = false;
+				st->deadlock_failure = false;
+
 				/* Begin with the first command */
 				st->command = 0;
 				st->state = CSTATE_START_COMMAND;
@@ -2142,6 +2170,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 					break;
 				}
 
+				/* reset command result variables to default values */
+				serialization_failure = false;
+				deadlock_failure = false;
+				in_failed_transaction = false;
+
 				/*
 				 * Record statement start time if per-command latencies are
 				 * requested
@@ -2299,21 +2332,34 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * Read and discard the query result;
 				 */
 				res = PQgetResult(st->con);
-				switch (PQresultStatus(res))
+				result_status = PQresultStatus(res);
+				sqlState = PQresultErrorField(res, PG_DIAG_SQLSTATE);
+				if (sqlState) {
+					serialization_failure =
+						strcmp(sqlState, ERRCODE_T_R_SERIALIZATION_FAILURE) == 0;
+					deadlock_failure =
+						strcmp(sqlState, ERRCODE_T_R_DEADLOCK_DETECTED) == 0;
+					in_failed_transaction =
+						strcmp(sqlState, ERRCODE_IN_FAILED_SQL_TRANSACTION) == 0;
+				}
+
+				if (result_status == PGRES_COMMAND_OK ||
+					result_status == PGRES_TUPLES_OK ||
+					result_status == PGRES_EMPTY_QUERY ||
+					serialization_failure ||
+					deadlock_failure ||
+					in_failed_transaction)
 				{
-					case PGRES_COMMAND_OK:
-					case PGRES_TUPLES_OK:
-					case PGRES_EMPTY_QUERY:
-						/* OK */
-						PQclear(res);
-						discard_response(st);
-						st->state = CSTATE_END_COMMAND;
-						break;
-					default:
-						commandFailed(st, PQerrorMessage(st->con));
-						PQclear(res);
-						st->state = CSTATE_ABORTED;
-						break;
+					/* OK */
+					PQclear(res);
+					discard_response(st);
+					st->state = CSTATE_END_COMMAND;
+				}
+				else
+				{
+					commandFailed(st, PQerrorMessage(st->con));
+					PQclear(res);
+					st->state = CSTATE_ABORTED;
 				}
 				break;
 
@@ -2342,7 +2388,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
-				if (is_latencies)
+				if (is_latencies && !serialization_failure && !deadlock_failure)
 				{
 					if (INSTR_TIME_IS_ZERO(now))
 						INSTR_TIME_SET_CURRENT(now);
@@ -2354,6 +2400,12 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 				}
 
+				/* remember for transaction if there were failures */
+				if (serialization_failure)
+					st->serialization_failure = true;
+				if (deadlock_failure)
+					st->deadlock_failure = true;
+
 				/* Go ahead with next command */
 				st->command++;
 				st->state = CSTATE_START_COMMAND;
@@ -2370,9 +2422,17 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 */
 				if (progress || throttle_delay || latency_limit ||
 					per_script_stats || use_log)
+				{
 					processXactStats(thread, st, &now, false, agg);
+				}
 				else
+				{
 					thread->stats.cnt++;
+					if (st->serialization_failure)
+						thread->stats.serialization_failures++;
+					if (st->deadlock_failure)
+						thread->stats.deadlock_failures++;
+				}
 
 				if (is_connect)
 				{
@@ -2462,9 +2522,11 @@ doLog(TState *thread, CState *st,
 		while (agg->start_time + agg_interval <= now)
 		{
 			/* print aggregated report to logfile */
-			fprintf(logfile, "%ld " INT64_FORMAT " %.0f %.0f %.0f %.0f",
+			fprintf(logfile, "%ld " INT64_FORMAT " " INT64_FORMAT " " INT64_FORMAT " %.0f %.0f %.0f %.0f",
 					(long) agg->start_time,
 					agg->cnt,
+					agg->serialization_failures,
+					agg->deadlock_failures,
 					agg->latency.sum,
 					agg->latency.sum2,
 					agg->latency.min,
@@ -2486,17 +2548,28 @@ doLog(TState *thread, CState *st,
 		}
 
 		/* accumulate the current transaction */
-		accumStats(agg, skipped, latency, lag);
+		accumStats(agg, skipped, st->serialization_failure,
+				   st->deadlock_failure, latency, lag);
 	}
 	else
 	{
 		/* no, print raw transactions */
 		struct timeval tv;
+		char		transaction_label[256];
 
-		gettimeofday(&tv, NULL);
 		if (skipped)
-			fprintf(logfile, "%d " INT64_FORMAT " skipped %d %ld %ld",
-					st->id, st->cnt, st->use_file,
+			snprintf(transaction_label, sizeof(transaction_label), "skipped");
+		else if (st->serialization_failure && st->deadlock_failure)
+			snprintf(transaction_label, sizeof(transaction_label),
+					 "serialization and deadlock failures");
+		else if (st->serialization_failure || st->deadlock_failure)
+			snprintf(transaction_label, sizeof(transaction_label), "%s failure",
+					 st->serialization_failure ? "serialization" : "deadlock");
+
+		gettimeofday(&tv, NULL);
+		if (skipped || st->serialization_failure || st->deadlock_failure)
+			fprintf(logfile, "%d " INT64_FORMAT " %s %d %ld %ld",
+					st->id, st->cnt, transaction_label, st->use_file,
 					(long) tv.tv_sec, (long) tv.tv_usec);
 		else
 			fprintf(logfile, "%d " INT64_FORMAT " %.0f %d %ld %ld",
@@ -2523,7 +2596,7 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 	if ((!skipped) && INSTR_TIME_IS_ZERO(*now))
 		INSTR_TIME_SET_CURRENT(*now);
 
-	if (!skipped)
+	if (!skipped && !st->serialization_failure && !st->deadlock_failure)
 	{
 		/* compute latency & lag */
 		latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
@@ -2532,21 +2605,30 @@ processXactStats(TState *thread, CState *st, instr_time *now,
 
 	if (progress || throttle_delay || latency_limit)
 	{
-		accumStats(&thread->stats, skipped, latency, lag);
+		accumStats(&thread->stats, skipped, st->serialization_failure,
+				   st->deadlock_failure, latency, lag);
 
 		/* count transactions over the latency limit, if needed */
 		if (latency_limit && latency > latency_limit)
 			thread->latency_late++;
 	}
 	else
+	{
 		thread->stats.cnt++;
+		if (st->serialization_failure)
+			thread->stats.serialization_failures++;
+		if (st->deadlock_failure)
+			thread->stats.deadlock_failures++;
+	}
 
 	if (use_log)
 		doLog(thread, st, agg, skipped, latency, lag);
 
 	/* XXX could use a mutex here, but we choose not to */
 	if (per_script_stats)
-		accumStats(&sql_script[st->use_file].stats, skipped, latency, lag);
+		accumStats(&sql_script[st->use_file].stats, skipped,
+				   st->serialization_failure, st->deadlock_failure, latency,
+				   lag);
 }
 
 
@@ -3522,6 +3604,14 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
 	if (total->cnt <= 0)
 		return;
 
+	printf("number of transactions with serialization failures: " INT64_FORMAT " (%.3f %%)\n",
+		   total->serialization_failures,
+		   (100.0 * total->serialization_failures / total->cnt));
+
+	printf("number of transactions with deadlock failures: " INT64_FORMAT " (%.3f %%)\n",
+		   total->deadlock_failures,
+		   (100.0 * total->deadlock_failures / total->cnt));
+
 	if (throttle_delay && latency_limit)
 		printf("number of transactions skipped: " INT64_FORMAT " (%.3f %%)\n",
 			   total->skipped,
@@ -3576,6 +3666,16 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
 			else
 				printf("script statistics:\n");
 
+			printf(" - number of transactions with serialization failures: " INT64_FORMAT " (%.3f%%)\n",
+				   sql_script[i].stats.serialization_failures,
+				   (100.0 * sql_script[i].stats.serialization_failures /
+					sql_script[i].stats.cnt));
+
+			printf(" - number of transactions with deadlock failures: " INT64_FORMAT " (%.3f%%)\n",
+				   sql_script[i].stats.deadlock_failures,
+				   (100.0 * sql_script[i].stats.deadlock_failures /
+					sql_script[i].stats.cnt));
+
 			if (latency_limit)
 				printf(" - number of transactions skipped: " INT64_FORMAT " (%.3f%%)\n",
 					   sql_script[i].stats.skipped,
@@ -4340,6 +4440,8 @@ main(int argc, char **argv)
 		mergeSimpleStats(&stats.lag, &thread->stats.lag);
 		stats.cnt += thread->stats.cnt;
 		stats.skipped += thread->stats.skipped;
+		stats.serialization_failures += thread->stats.serialization_failures;
+		stats.deadlock_failures += thread->stats.deadlock_failures;
 		latency_late += thread->latency_late;
 		INSTR_TIME_ADD(conn_total_time, thread->conn_time);
 	}
@@ -4639,6 +4741,9 @@ threadRun(void *arg)
 					mergeSimpleStats(&cur.lag, &thread[i].stats.lag);
 					cur.cnt += thread[i].stats.cnt;
 					cur.skipped += thread[i].stats.skipped;
+					cur.serialization_failures +=
+						thread[i].stats.serialization_failures;
+					cur.deadlock_failures += thread[i].stats.deadlock_failures;
 				}
 
 				total_run = (now - thread_start) / 1000000.0;
@@ -4669,8 +4774,14 @@ threadRun(void *arg)
 					snprintf(tbuf, sizeof(tbuf), "%.1f s", total_run);
 
 				fprintf(stderr,
-						"progress: %s, %.1f tps, lat %.3f ms stddev %.3f",
-						tbuf, tps, latency, stdev);
+						"progress: %s, %.1f tps, " INT64_FORMAT " serialization failures transactions, " INT64_FORMAT " deadlock failures transactions, lat %.3f ms stddev %.3f",
+						tbuf,
+						tps,
+						(cur.serialization_failures -
+						 last.serialization_failures),
+						(cur.deadlock_failures - last.deadlock_failures),
+						latency,
+						stdev);
 
 				if (throttle_delay)
 				{
diff --git a/src/bin/pgbench/t/002_serialization_errors.pl b/src/bin/pgbench/t/002_serialization_errors.pl
new file mode 100644
index 0000000..8d0d99f
--- /dev/null
+++ b/src/bin/pgbench/t/002_serialization_errors.pl
@@ -0,0 +1,75 @@
+use strict;
+use warnings;
+
+use PostgresNode;
+use TestLib;
+use Test::More tests => 18;
+
+# Test concurrent update in table row with different transaction isolation
+# levels.
+my $node = get_new_node('main');
+$node->init;
+$node->start;
+$node->safe_psql('postgres',
+	    'CREATE UNLOGGED TABLE xy (x integer, y integer); '
+	  . 'INSERT INTO xy VALUES (1, 2);');
+
+# Test serialization errors on transactions with Read committed isolation level
+my $script_read_committed = $node->basedir . '/pgbench_script_read_committed';
+append_to_file($script_read_committed,
+		"\\set delta random(-5000, 5000)\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED;\n"
+	  . "UPDATE xy SET y = y + :delta WHERE x = 1;\n"
+	  . "END;\n");
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_read_committed ],
+	qr{processed: 50/50},
+	'concurrent update: Read Committed: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_read_committed ],
+	qr{serialization failures: 0 \(0\.000 %\)},
+	'concurrent update: Read Committed: check serialization failures');
+
+# Test serialization errors on transactions with Repeatable read isolation level
+my $script_repeatable_read = $node->basedir . '/pgbench_script_repeatable_read';
+append_to_file($script_repeatable_read,
+		"\\set delta random(-5000, 5000)\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ;\n"
+	  . "UPDATE xy SET y = y + :delta WHERE x = 1;\n"
+	  . "END;\n");
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_repeatable_read ],
+	qr{processed: 50/50},
+	'concurrent update: Repeatable Read: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_repeatable_read ],
+	qr{serialization failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent update: Repeatable Read: check serialization failures');
+
+# Test serialization errors on transactions with Serializable isolation level
+my $script_serializable = $node->basedir . '/pgbench_script_serializable';
+append_to_file($script_serializable,
+		"\\set delta random(-5000, 5000)\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE;\n"
+	  . "UPDATE xy SET y = y + :delta WHERE x = 1;\n"
+	  . "END;\n");
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_serializable ],
+	qr{processed: 50/50},
+	'concurrent update: Serializable: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_serializable ],
+	qr{serialization failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent update: Serializable: check serialization failures');
diff --git a/src/bin/pgbench/t/003_deadlock_errors.pl b/src/bin/pgbench/t/003_deadlock_errors.pl
new file mode 100644
index 0000000..791d456
--- /dev/null
+++ b/src/bin/pgbench/t/003_deadlock_errors.pl
@@ -0,0 +1,93 @@
+use strict;
+use warnings;
+
+use PostgresNode;
+use TestLib;
+use Test::More tests => 18;
+
+# Test concurrent deadlock updates in table with different transaction isolation
+# levels.
+my $node = get_new_node('main');
+$node->init;
+$node->start;
+$node->safe_psql('postgres',
+	    'CREATE UNLOGGED TABLE xy (x integer, y integer); '
+	  . 'INSERT INTO xy VALUES (1, 2), (2, 3);');
+
+# Test deadlock errors on transactions with Read committed isolation level
+my $script_read_committed = $node->basedir . '/pgbench_script_read_committed';
+append_to_file($script_read_committed,
+		"\\set delta1 random(-5000, 5000)\n"
+	  . "\\set delta2 random(-5000, 5000)\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED;\n"
+	  . "UPDATE xy SET y = y + :delta1 WHERE x = 1;\n"
+	  . "UPDATE xy SET y = y + :delta2 WHERE x = 2;\n"
+	  . "END;\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL READ COMMITTED;\n"
+	  . "UPDATE xy SET y = y + :delta2 WHERE x = 2;\n"
+	  . "UPDATE xy SET y = y + :delta1 WHERE x = 1;\n"
+	  . "END;\n");
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_read_committed ],
+	qr{processed: 50/50},
+	'concurrent deadlock update: Read Committed: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_read_committed ],
+	qr{deadlock failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent deadlock update: Read Committed: check deadlock failures');
+
+# Test deadlock errors on transactions with Repeatable read isolation level
+my $script_repeatable_read = $node->basedir . '/pgbench_script_repeatable_read';
+append_to_file($script_repeatable_read,
+		"\\set delta1 random(-5000, 5000)\n"
+	  . "\\set delta2 random(-5000, 5000)\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ;\n"
+	  . "UPDATE xy SET y = y + :delta1 WHERE x = 1;\n"
+	  . "UPDATE xy SET y = y + :delta2 WHERE x = 2;\n"
+	  . "END;\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL REPEATABLE READ;\n"
+	  . "UPDATE xy SET y = y + :delta2 WHERE x = 2;\n"
+	  . "UPDATE xy SET y = y + :delta1 WHERE x = 1;\n"
+	  . "END;\n");
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_repeatable_read ],
+	qr{processed: 50/50},
+	'concurrent deadlock update: Repeatable Read: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_repeatable_read ],
+	qr{deadlock failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent deadlock update: Repeatable Read: check deadlock failures');
+
+# Test deadlock errors on transactions with Serializable isolation level
+my $script_serializable = $node->basedir . '/pgbench_script_serializable';
+append_to_file($script_serializable,
+		"\\set delta1 random(-5000, 5000)\n"
+	  . "\\set delta2 random(-5000, 5000)\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE;\n"
+	  . "UPDATE xy SET y = y + :delta1 WHERE x = 1;\n"
+	  . "UPDATE xy SET y = y + :delta2 WHERE x = 2;\n"
+	  . "END;\n"
+	  . "BEGIN TRANSACTION ISOLATION LEVEL SERIALIZABLE;\n"
+	  . "UPDATE xy SET y = y + :delta2 WHERE x = 2;\n"
+	  . "UPDATE xy SET y = y + :delta1 WHERE x = 1;\n"
+	  . "END;\n");
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_serializable ],
+	qr{processed: 50/50},
+	'concurrent update: Serializable: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10 --file),
+		$script_serializable ],
+	qr{deadlock failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent update: Serializable: check deadlock failures');
\ No newline at end of file
-- 
1.9.1



v1-0002-Pgbench-Set-default-transaction-isolation-level.patch (text/x-diff, 8.5K) download
From d27bdbb4e360b30ec0960634c13a6ba21c7a618d Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Fri, 9 Jun 2017 16:34:08 +0300
Subject: [PATCH v1 2/4] Pgbench Set default transaction isolation level

You can set the default transaction isolation level by the appropriate
benchmarking option (-I).
---
 src/bin/pgbench/pgbench.c                          | 66 ++++++++++++++++++-
 .../004_set_default_transaction_isolation_level.pl | 76 ++++++++++++++++++++++
 2 files changed, 141 insertions(+), 1 deletion(-)
 create mode 100644 src/bin/pgbench/t/004_set_default_transaction_isolation_level.pl

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index bbf444b..8c48793 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -456,6 +456,24 @@ static const BuiltinScript builtin_script[] =
 	}
 };
 
+/* Default transaction isolation level */
+typedef enum DefaultIsolationLevel
+{
+	READ_COMMITTED,
+	REPEATABLE_READ,
+	SERIALIZABLE,
+	NUM_DEFAULT_ISOLATION_LEVEL
+} DefaultIsolationLevel;
+
+DefaultIsolationLevel default_isolation_level = READ_COMMITTED;
+
+static const char *DEFAULT_ISOLATION_LEVEL_ABBREVIATION[] = {"RC", "RR", "S"};
+static const char *DEFAULT_ISOLATION_LEVEL_SQL[] = {
+	"read committed",
+	"repeatable read",
+	"serializable"
+};
+
 
 /* Function prototypes */
 static void setIntValue(PgBenchValue *pv, int64 ival);
@@ -508,6 +526,8 @@ usage(void)
 		   "  -C, --connect            establish new connection for each transaction\n"
 		   "  -D, --define=VARNAME=VALUE\n"
 	  "                           define variable for use by custom script\n"
+		   "  -I, --default-isolation-level=RC|RR|S\n"
+	  "                           default transaction isolation level (default: RC)\n"
 		   "  -j, --jobs=NUM           number of threads (default: 1)\n"
 		   "  -l, --log                write transaction times to log file\n"
 		   "  -L, --latency-limit=NUM  count transactions lasting more than NUM ms as late\n"
@@ -2108,6 +2128,7 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				if (st->con == NULL)
 				{
 					instr_time	start;
+					char		buffer[256];
 
 					if (INSTR_TIME_IS_ZERO(now))
 						INSTR_TIME_SET_CURRENT(now);
@@ -2124,6 +2145,16 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 
 					/* Reset session-local state */
 					memset(st->prepared, 0, sizeof(st->prepared));
+
+					/* set default isolation level */
+					snprintf(buffer, sizeof(buffer),
+							 "set session characteristics as transaction isolation level %s",
+							 DEFAULT_ISOLATION_LEVEL_SQL[
+								default_isolation_level]);
+					executeStatement(st->con, buffer);
+					if (debug)
+						fprintf(stderr, "client %d execute command: %s\n",
+								st->id, buffer);
 				}
 
 				/*
@@ -3583,6 +3614,8 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
 	/* Report test parameters. */
 	printf("transaction type: %s\n",
 		   num_scripts == 1 ? sql_script[0].desc : "multiple scripts");
+	printf("default transaction isolation level: %s\n",
+		   DEFAULT_ISOLATION_LEVEL_SQL[default_isolation_level]);
 	printf("scaling factor: %d\n", scale);
 	printf("query mode: %s\n", QUERYMODE[querymode]);
 	printf("number of clients: %d\n", nclients);
@@ -3719,6 +3752,7 @@ main(int argc, char **argv)
 		{"fillfactor", required_argument, NULL, 'F'},
 		{"host", required_argument, NULL, 'h'},
 		{"initialize", no_argument, NULL, 'i'},
+		{"default-isolation-level", required_argument, NULL, 'I'},
 		{"jobs", required_argument, NULL, 'j'},
 		{"log", no_argument, NULL, 'l'},
 		{"latency-limit", required_argument, NULL, 'L'},
@@ -3811,7 +3845,7 @@ main(int argc, char **argv)
 	state = (CState *) pg_malloc(sizeof(CState));
 	memset(state, 0, sizeof(CState));
 
-	while ((c = getopt_long(argc, argv, "ih:nvp:dqb:SNc:j:Crs:t:T:U:lf:D:F:M:P:R:L:", long_options, &optindex)) != -1)
+	while ((c = getopt_long(argc, argv, "ih:nvp:dqb:SNc:j:Crs:t:T:U:lf:D:F:M:P:R:L:I:", long_options, &optindex)) != -1)
 	{
 		char	   *script;
 
@@ -4051,6 +4085,25 @@ main(int argc, char **argv)
 					latency_limit = (int64) (limit_ms * 1000);
 				}
 				break;
+			case 'I':
+				{
+					benchmarking_option_set = true;
+
+					for (default_isolation_level = 0;
+						 default_isolation_level < NUM_DEFAULT_ISOLATION_LEVEL;
+						 default_isolation_level++)
+						if (strcmp(optarg,
+								DEFAULT_ISOLATION_LEVEL_ABBREVIATION[
+									default_isolation_level]) == 0)
+							break;
+					if (default_isolation_level >= NUM_DEFAULT_ISOLATION_LEVEL)
+					{
+						fprintf(stderr, "invalid default isolation level (-I): \"%s\"\n",
+								optarg);
+						exit(1);
+					}
+				}
+				break;
 			case 0:
 				/* This covers long options which take no argument. */
 				if (foreign_keys || unlogged_tables)
@@ -4522,8 +4575,19 @@ threadRun(void *arg)
 		/* make connections to the database */
 		for (i = 0; i < nstate; i++)
 		{
+			char		buffer[256];
+
 			if ((state[i].con = doConnect()) == NULL)
 				goto done;
+
+			/* set default isolation level */
+			snprintf(buffer, sizeof(buffer),
+					 "set session characteristics as transaction isolation level %s",
+					 DEFAULT_ISOLATION_LEVEL_SQL[default_isolation_level]);
+			executeStatement(state[i].con, buffer);
+			if (debug)
+				fprintf(stderr, "client %d execute command: %s\n",
+						state[i].id, buffer);
 		}
 	}
 
diff --git a/src/bin/pgbench/t/004_set_default_transaction_isolation_level.pl b/src/bin/pgbench/t/004_set_default_transaction_isolation_level.pl
new file mode 100644
index 0000000..cb9f03b
--- /dev/null
+++ b/src/bin/pgbench/t/004_set_default_transaction_isolation_level.pl
@@ -0,0 +1,76 @@
+use strict;
+use warnings;
+
+use PostgresNode;
+use TestLib;
+use Test::More tests => 27;
+
+# Test concurrent update in table row with different default transaction
+# isolation levels.
+my $node = get_new_node('main');
+$node->init;
+$node->start;
+$node->safe_psql('postgres',
+	    'CREATE UNLOGGED TABLE xy (x integer, y integer); '
+	  . 'INSERT INTO xy VALUES (1, 2);');
+
+my $script = $node->basedir . '/pgbench_script';
+append_to_file($script, "\\set delta random(-5000, 5000)\n");
+append_to_file($script, "UPDATE xy SET y = y + :delta WHERE x = 1;");
+
+# Test Read committed default transaction isolation level
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=RC --file), $script ],
+	qr{default transaction isolation level: read committed},
+	'concurrent update: Read Committed: check default isolation level');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=RC --file), $script ],
+	qr{processed: 50/50},
+	'concurrent update: Read Committed: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=RC --file), $script ],
+	qr{serialization failures: 0 \(0\.000 %\)},
+	'concurrent update: Read Committed: check serialization failures');
+
+# Test Repeatable read default transaction isolation level
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=RR --file), $script ],
+	qr{default transaction isolation level: repeatable read},
+	'concurrent update: Repeatable Read: check default isolation level');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=RR --file), $script ],
+	qr{processed: 50/50},
+	'concurrent update: Repeatable Read: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=RR --file), $script ],
+	qr{serialization failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent update: Repeatable Read: check serialization failures');
+
+# Test Serializable default transaction isolation level
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=S --file), $script ],
+	qr{default transaction isolation level: serializable},
+	'concurrent update: Serializable: check default isolation level');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=S --file), $script ],
+	qr{processed: 50/50},
+	'concurrent update: Serializable: check processed transactions');
+
+$node->command_like(
+	[   qw(pgbench --no-vacuum --client=5 --transactions=10
+		  --default-isolation-level=S --file), $script ],
+	qr{serialization failures: [1-9]\d* \([1-9]\d*\.\d* %\)},
+	'concurrent update: Serializable: check serialization failures');
-- 
1.9.1



v1-0003-Pgbench-Report-per-statement-serialization-and-de.patch (text/x-diff, 6.3K) download
From fd2727472745929e50ebf564ab77d27588483f7c Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Fri, 9 Jun 2017 17:41:11 +0300
Subject: [PATCH v1 3/4] Pgbench Report per-statement serialization and
 deadlock failures

They are reported if you use the appropriate benchmarking option
(--report-failures). It can be combined with the average per-statement latencies
option (-r).
---
 src/bin/pgbench/pgbench.c | 69 ++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 60 insertions(+), 9 deletions(-)

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 8c48793..ec27ace 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -179,6 +179,8 @@ int			nthreads = 1;		/* number of threads */
 bool		is_connect;			/* establish connection for each transaction */
 bool		is_latencies;		/* report per-command latencies */
 int			main_pid;			/* main process id used in log filename */
+bool		report_failures = false;	/* whether to report serialization and
+										 * deadlock failures per command */
 
 char	   *pghost = "";
 char	   *pgport = "";
@@ -393,6 +395,10 @@ typedef struct
 	char	   *argv[MAX_ARGS]; /* command word list */
 	PgBenchExpr *expr;			/* parsed expression, if needed */
 	SimpleStats stats;			/* time spent in this command */
+	int64		serialization_failures;	/* number of serialization failures in
+										 * this command */
+	int64		deadlock_failures;	/* number of deadlock failures in this
+									 * command */
 } Command;
 
 typedef struct ParsedScript
@@ -543,6 +549,7 @@ usage(void)
 		   "  -v, --vacuum-all         vacuum all four standard tables before tests\n"
 		   "  --aggregate-interval=NUM aggregate data over NUM seconds\n"
 		"  --progress-timestamp     use Unix epoch timestamps for progress\n"
+		"  --report-failures        report serialization and deadlock failures per command\n"
 		   "  --sampling-rate=NUM      fraction of transactions to log (e.g., 0.01 for 1%%)\n"
 		   "  --log-prefix=PREFIX      prefix for transaction time log file\n"
 		   "                           (default: \"pgbench_log\")\n"
@@ -2419,23 +2426,34 @@ doCustom(TState *thread, CState *st, StatsData *agg)
 				 * in thread-local data structure, if per-command latencies
 				 * are requested.
 				 */
+				command = sql_script[st->use_file].commands[st->command];
+
 				if (is_latencies && !serialization_failure && !deadlock_failure)
 				{
 					if (INSTR_TIME_IS_ZERO(now))
 						INSTR_TIME_SET_CURRENT(now);
 
 					/* XXX could use a mutex here, but we choose not to */
-					command = sql_script[st->use_file].commands[st->command];
 					addToSimpleStats(&command->stats,
 									 INSTR_TIME_GET_DOUBLE(now) -
 									 INSTR_TIME_GET_DOUBLE(st->stmt_begin));
 				}
 
-				/* remember for transaction if there were failures */
+				/*
+				 * Accumulate per-command serialization / deadlock failures
+				 * count in thread-local data structure and remember for
+				 * transaction if there were failures.
+				 */
 				if (serialization_failure)
+				{
+					command->serialization_failures++;
 					st->serialization_failure = true;
+				}
 				if (deadlock_failure)
+				{
+					command->deadlock_failures++;
 					st->deadlock_failure = true;
+				}
 
 				/* Go ahead with next command */
 				st->command++;
@@ -3098,6 +3116,8 @@ process_sql_command(PQExpBuffer buf, const char *source)
 	my_command->type = SQL_COMMAND;
 	my_command->argc = 0;
 	initSimpleStats(&my_command->stats);
+	my_command->serialization_failures = 0;
+	my_command->deadlock_failures = 0;
 
 	/*
 	 * If SQL command is multi-line, we only want to save the first line as
@@ -3167,6 +3187,8 @@ process_backslash_command(PsqlScanState sstate, const char *source)
 	my_command->type = META_COMMAND;
 	my_command->argc = 0;
 	initSimpleStats(&my_command->stats);
+	my_command->serialization_failures = 0;
+	my_command->deadlock_failures = 0;
 
 	/* Save first word (command name) */
 	j = 0;
@@ -3718,20 +3740,43 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
 			if (num_scripts > 1)
 				printSimpleStats(" - latency", &sql_script[i].stats.latency);
 
-			/* Report per-command latencies */
-			if (is_latencies)
+			/*
+			 * Report per-command serialization / deadlock failures and
+			 * latencies
+			 */
+			if (report_failures || is_latencies)
 			{
 				Command   **commands;
 
-				printf(" - statement latencies in milliseconds:\n");
+				if (report_failures && is_latencies)
+					printf(" - statement serialization, deadlock failures and latencies in milliseconds:\n");
+				else if (report_failures)
+					printf(" - statement serialization and deadlock failures:\n");
+				else
+					printf(" - statement latencies in milliseconds:\n");
 
 				for (commands = sql_script[i].commands;
 					 *commands != NULL;
 					 commands++)
-					printf("   %11.3f  %s\n",
-						   1000.0 * (*commands)->stats.sum /
-						   (*commands)->stats.count,
-						   (*commands)->line);
+				{
+					if (report_failures && is_latencies)
+						printf("   %25" INT64_MODIFIER "d  %25" INT64_MODIFIER "d  %11.3f  %s\n",
+							   (*commands)->serialization_failures,
+							   (*commands)->deadlock_failures,
+							   1000.0 * (*commands)->stats.sum /
+							   (*commands)->stats.count,
+							   (*commands)->line);
+					else if (report_failures)
+						printf("   %25" INT64_MODIFIER "d  %25" INT64_MODIFIER "d  %s\n",
+							   (*commands)->serialization_failures,
+							   (*commands)->deadlock_failures,
+							   (*commands)->line);
+					else
+						printf("   %11.3f  %s\n",
+							   1000.0 * (*commands)->stats.sum /
+							   (*commands)->stats.count,
+							   (*commands)->line);
+				}
 			}
 		}
 	}
@@ -3779,6 +3824,7 @@ main(int argc, char **argv)
 		{"aggregate-interval", required_argument, NULL, 5},
 		{"progress-timestamp", no_argument, NULL, 6},
 		{"log-prefix", required_argument, NULL, 7},
+		{"report-failures", no_argument, NULL, 8},
 		{NULL, 0, NULL, 0}
 	};
 
@@ -4144,6 +4190,11 @@ main(int argc, char **argv)
 				benchmarking_option_set = true;
 				logfile_prefix = pg_strdup(optarg);
 				break;
+			case 8:
+				benchmarking_option_set = true;
+				per_script_stats = true;
+				report_failures = true;
+				break;
 			default:
 				fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
 				exit(1);
-- 
1.9.1



v1-0004-Pgbench-Fix-documentation.patch (text/x-diff, 15.5K) download
From ce28b9433d596adcfa3ddd860faaeb8de3315971 Mon Sep 17 00:00:00 2001
From: Marina Polyakova <m.polyakova@postgrespro.ru>
Date: Tue, 13 Jun 2017 10:34:23 +0300
Subject: [PATCH v1 4/4] Pgbench Fix documentation

New:
- no fails on serialization and deadlock errors; report about them in logs, in
progress, in aggregation logs and in the end with other results (all and for
each script)
- benchmarking option to set default transaction isolation level (-I)
- benchmarking option to report per-statement serialization and deadlock
failures (--report-failures)
---
 doc/src/sgml/ref/pgbench.sgml | 177 ++++++++++++++++++++++++++++++++++++------
 1 file changed, 152 insertions(+), 25 deletions(-)

diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml
index 5735c48..158d300 100644
--- a/doc/src/sgml/ref/pgbench.sgml
+++ b/doc/src/sgml/ref/pgbench.sgml
@@ -49,23 +49,30 @@
 
 <screen>
 transaction type: &lt;builtin: TPC-B (sort of)&gt;
+default transaction isolation level: read committed
 scaling factor: 10
 query mode: simple
 number of clients: 10
 number of threads: 1
 number of transactions per client: 1000
 number of transactions actually processed: 10000/10000
+number of transactions with serialization failures: 0 (0.000 %)
+number of transactions with deadlock failures: 0 (0.000 %)
 tps = 85.184871 (including connections establishing)
 tps = 85.296346 (excluding connections establishing)
 </screen>
 
-  The first six lines report some of the most important parameter
+  The first seven lines report some of the most important parameter
   settings.  The next line reports the number of transactions completed
   and intended (the latter being just the product of number of clients
   and number of transactions per client); these will be equal unless the run
   failed before completion.  (In <option>-T</> mode, only the actual
   number of transactions is printed.)
-  The last two lines report the number of transactions per second,
+  The next two lines report the number of
+  transactions with serialization and deadlock failures; unlike other errors
+  transactions with these ones don't fail and continue run normally, but
+  transaction result is rolled back.
+  And the last two lines report the number of transactions per second,
   figured with and without counting the time to start database sessions.
  </para>
 
@@ -338,6 +345,30 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
      </varlistentry>
 
      <varlistentry>
+      <term><option>-I</option> <replaceable>isolationlevel</></term>
+      <term><option>--default-isolation-level=</option><replaceable>isolationlevel</></term>
+      <listitem>
+       <para>
+         Set default transaction isolation level.  Use next abbreviations for
+         <replaceable>isolationlevel</>:
+          <itemizedlist>
+           <listitem>
+            <para><literal>RC</>: set default transaction isolation level as Read Committed.</para>
+           </listitem>
+           <listitem>
+            <para><literal>RR</>: set default transaction isolation level as Repeatable Read.</para>
+           </listitem>
+           <listitem>
+            <para><literal>S</>: set default transaction isolation level as Serializable.</para>
+           </listitem>
+          </itemizedlist>
+          The default is Read Committed isolation level.  (See
+          <xref linkend="transaction-iso"> for more information.)
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
       <term><option>-j</option> <replaceable>threads</></term>
       <term><option>--jobs=</option><replaceable>threads</></term>
       <listitem>
@@ -434,12 +465,13 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
       <listitem>
        <para>
         Show progress report every <replaceable>sec</> seconds.  The report
-        includes the time since the beginning of the run, the tps since the
-        last report, and the transaction latency average and standard
-        deviation since the last report.  Under throttling (<option>-R</>),
-        the latency is computed with respect to the transaction scheduled
-        start time, not the actual transaction beginning time, thus it also
-        includes the average schedule lag time.
+        includes the time since the beginning of the run and next
+        characteristics since the last report: the tps, the number of
+        transactions with serialization and deadlock failures, and the
+        transaction latency average and standard deviation.  Under throttling
+        (<option>-R</>), the latency is computed with respect to the transaction
+        scheduled start time, not the actual transaction beginning time, thus it
+        also includes the average schedule lag time.
        </para>
       </listitem>
      </varlistentry>
@@ -451,7 +483,9 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
        <para>
         Report the average per-statement latency (execution time from the
         perspective of the client) of each command after the benchmark
-        finishes.  See below for details.
+        finishes (with the number of serialization and deadlock failures for
+        each command if it is used with <option>--report-failures</> option).
+        See below for details.
        </para>
       </listitem>
      </varlistentry>
@@ -496,6 +530,15 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
        </para>
 
        <para>
+        Transactions with serialization or deadlock failures (or with both
+        of them if used script contains several transactions; see
+        <xref linkend="transactions-and-scripts"
+        endterm="transactions-and-scripts-title"> for more information) are
+        marked separately and their time is not reported as for skipped
+        transactions.
+       </para>
+
+       <para>
         A high schedule lag time is an indication that the system cannot
         process transactions at the specified rate, with the chosen number of
         clients and threads. When the average transaction execution time is
@@ -593,6 +636,18 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
      </varlistentry>
 
      <varlistentry>
+      <term><option>--report-failures</option></term>
+      <listitem>
+       <para>
+        Report the number of serialization and deadlock failures for each
+        command after the benchmark finishes (with the average per-statement
+        latencies of each command if it is used with <option>-r</> option).  See
+        below for details.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
       <term><option>--sampling-rate=<replaceable>rate</></option></term>
       <listitem>
        <para>
@@ -693,8 +748,8 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
  <refsect1>
   <title>Notes</title>
 
- <refsect2>
-  <title>What is the <quote>Transaction</> Actually Performed in <application>pgbench</application>?</title>
+ <refsect2 id="transactions-and-scripts">
+  <title id="transactions-and-scripts-title">What is the <quote>Transaction</> Actually Performed in <application>pgbench</application>?</title>
 
   <para>
    <application>pgbench</> executes test scripts chosen randomly
@@ -1169,6 +1224,13 @@ END;
    When both <option>--rate</> and <option>--latency-limit</> are used,
    the <replaceable>time</> for a skipped transaction will be reported as
    <literal>skipped</>.
+   If transaction has serialization / deadlock failure or them both (last thing
+   is possible if used script contains several transactions; see
+   <xref linkend="transactions-and-scripts"
+   endterm="transactions-and-scripts-title"> for more information), its
+   <replaceable>time</> will be reported as <literal>serialization failure</> /
+   <literal>deadlock failure</> /
+   <literal>serialization and deadlock failures</> appropriately.
   </para>
 
   <para>
@@ -1198,6 +1260,20 @@ END;
   </para>
 
   <para>
+   Example with serialization, deadlock and both these failures:
+<screen>
+1 128 24968 0 1496759158 426984
+0 129 serialization failure 0 1496759158 427023
+3 129 serialization failure 0 1496759158 432662
+2 128 serialization failure 0 1496759158 432765
+0 130 deadlock failure 0 1496759159 460070
+1 129 serialization failure 0 1496759160 485188
+2 129 serialization and deadlock failures 0 1496759160 485339
+4 130 serialization failure 0 1496759160 485465
+</screen>
+  </para>
+
+  <para>
    When running a long test on hardware that can handle a lot of transactions,
    the log files can become very large.  The <option>--sampling-rate</> option
    can be used to log only a random sample of transactions.
@@ -1212,7 +1288,7 @@ END;
    format is used for the log files:
 
 <synopsis>
-<replaceable>interval_start</> <replaceable>num_transactions</> <replaceable>sum_latency</> <replaceable>sum_latency_2</> <replaceable>min_latency</> <replaceable>max_latency</> <optional> <replaceable>sum_lag</> <replaceable>sum_lag_2</> <replaceable>min_lag</> <replaceable>max_lag</> <optional> <replaceable>skipped</> </optional> </optional>
+<replaceable>interval_start</> <replaceable>num_transactions</> <replaceable>num_serialization_failures_transactions</> <replaceable>num_deadlock_failures_transactions</> <replaceable>sum_latency</> <replaceable>sum_latency_2</> <replaceable>min_latency</> <replaceable>max_latency</> <optional> <replaceable>sum_lag</> <replaceable>sum_lag_2</> <replaceable>min_lag</> <replaceable>max_lag</> <optional> <replaceable>skipped</> </optional> </optional>
 </synopsis>
 
    where
@@ -1220,6 +1296,9 @@ END;
    epoch time stamp),
    <replaceable>num_transactions</> is the number of transactions
    within the interval,
+   <replaceable>num_serialization_failures_transactions</> and
+   <replaceable>num_deadlock_failures_transactions</> are the numbers of
+   transactions with appropriate failures within the interval,
    <replaceable>sum_latency</replaceable> is the sum of the transaction
    latencies within the interval,
    <replaceable>sum_latency_2</replaceable> is the sum of squares of the
@@ -1244,11 +1323,11 @@ END;
   <para>
    Here is some example output:
 <screen>
-1345828501 5601 1542744 483552416 61 2573
-1345828503 7884 1979812 565806736 60 1479
-1345828505 7208 1979422 567277552 59 1391
-1345828507 7685 1980268 569784714 60 1398
-1345828509 7073 1979779 573489941 236 1411
+1345828501 5601 0 0 1542744 483552416 61 2573
+1345828503 7884 0 0 1979812 565806736 60 1479
+1345828505 7208 0 0 1979422 567277552 59 1391
+1345828507 7685 0 0 1980268 569784714 60 1398
+1345828509 7073 0 0 1979779 573489941 236 1411
 </screen></para>
 
   <para>
@@ -1260,31 +1339,45 @@ END;
  </refsect2>
 
  <refsect2>
-  <title>Per-Statement Latencies</title>
+  <title>Per-Statement Latencies and Failures</title>
 
   <para>
-   With the <option>-r</> option, <application>pgbench</> collects
-   the elapsed transaction time of each statement executed by every
-   client.  It then reports an average of those values, referred to
-   as the latency for each statement, after the benchmark has finished.
+   There're two options to get some per-statement characteristics: <option>-r</> and
+   <option>--report-failures</> (they can be combined together).  All values
+   are computed for each statement executed by every client and are reported
+   after the benchmark has finished.  With the <option>-r</> option,
+   <application>pgbench</> collects the elapsed transaction time of each
+   statement.  It then reports an average of those values, referred to as the
+   latency for each statement.  With the <option>--report-failures</> option,
+   <application>pgbench</> collects the number of serialization and deadlock
+   failures for each statement (notice that the total sum of per-command
+   failures of each type can be greater than the number of "transactions" with
+   these failures; see <xref linkend="transactions-and-scripts"
+   endterm="transactions-and-scripts-title"> for more information).
   </para>
 
   <para>
-   For the default script, the output will look similar to this:
+   For the default script if you use <option>-r</> option, the output will look
+   similar to this:
 <screen>
 starting vacuum...end.
 transaction type: &lt;builtin: TPC-B (sort of)&gt;
+default transaction isolation level: read committed
 scaling factor: 1
 query mode: simple
 number of clients: 10
 number of threads: 1
 number of transactions per client: 1000
 number of transactions actually processed: 10000/10000
+number of transactions with serialization failures: 0 (0.000 %)
+number of transactions with deadlock failures: 0 (0.000 %)
 latency average = 15.844 ms
 latency stddev = 2.715 ms
 tps = 618.764555 (including connections establishing)
 tps = 622.977698 (excluding connections establishing)
 script statistics:
+ - number of transactions with serialization failures: 0 (0.000%)
+ - number of transactions with deadlock failures: 0 (0.000%)
  - statement latencies in milliseconds:
         0.002  \set aid random(1, 100000 * :scale)
         0.005  \set bid random(1, 1 * :scale)
@@ -1298,11 +1391,45 @@ script statistics:
         0.371  INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
         1.212  END;
 </screen>
+
+   Another example of output for the default script using serializable default
+   transaction isolation level (-I S) and <option>--report-failures</> option:
+<screen>
+starting vacuum...end.
+transaction type: &lt;builtin: TPC-B (sort of)&gt;
+default transaction isolation level: serializable
+scaling factor: 1
+query mode: simple
+number of clients: 10
+number of threads: 1
+number of transactions per client: 1000
+number of transactions actually processed: 10000/10000
+number of transactions with serialization failures: 9284 (92.840 %)
+number of transactions with deadlock failures: 0 (0.000 %)
+latency average = 10.817 ms
+tps = 924.477920 (including connections establishing)
+tps = 928.159352 (excluding connections establishing)
+script statistics:
+ - number of transactions with serialization failures: 9284 (92.840%)
+ - number of transactions with deadlock failures: 0 (0.000%)
+ - statement serialization and deadlock failures:
+                           0                          0  \set aid random(1, 100000 * :scale)
+                           0                          0  \set bid random(1, 1 * :scale)
+                           0                          0  \set tid random(1, 10 * :scale)
+                           0                          0  \set delta random(-5000, 5000)
+                           0                          0  BEGIN;
+                           0                          0  UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
+                           0                          0  SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
+                        7975                          0  UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
+                        1305                          0  UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
+                           0                          0  INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
+                           4                          0  END;
+</screen>
   </para>
 
   <para>
-   If multiple script files are specified, the averages are reported
-   separately for each script file.
+   If multiple script files are specified, the averages and the failures are
+   reported separately for each script file.
   </para>
 
   <para>
-- 
1.9.1