From 7f5d15d564c3b35a2ed0e9b0f337ea5480b4be83 Mon Sep 17 00:00:00 2001 From: Marina Polyakova Date: Wed, 5 Sep 2018 18:23:07 +0300 Subject: [PATCH v11 3/4] Pgbench errors and serialization/deadlock retries Client's run is aborted only in case of a serious error, for example, the connection with the database server was lost or the end of script reached without completing the last transaction. Otherwise if the execution of SQL or meta command fails, the current transaction is always rolled back which also includes setting the client variables as they were before the run of this transaction (it is assumed that one transaction script contains only one transaction). Transactions with serialization or deadlock errors are rolled back and repeated until they complete successfully or reach the maximum number of tries (specified by the --max-tries option) / the maximum time of tries (specified by the --latency-limit option). These options can be combined together; more over, you cannot use an infinite number of tries (--max-tries=0) without the option --latency-limit. By default the option --max-tries is set to 1 and transactions with serialization/deadlock errors are not retried at all. If the last transaction run fails, this transaction will be reported as failed, and the client variables will be set as they were before the first run of this transaction. If there're retries and/or failures their statistics are printed in the progress, in the transaction / aggregation logs and in the end with other results (all and for each script). Also retries and failures are printed per-command with average latencies if you use the appropriate benchmarking option (--report-per-command, -r). If you want to group failures by basic types (serialization failures / deadlock failures / other SQL failures / failures in meta commands), use the option --failures-detailed. If you want to distinguish all errors and failures (errors without retrying) by type including which limit for retries was violated and how far it was exceeded for the serialization/deadlock failures, use the options --print-errors or --debug. The first option is recommended for this purpose because with the second option the output can be significantly increased due to debug messages of successful commands of all the transactions. --- doc/src/sgml/ref/pgbench.sgml | 420 +++++- src/bin/pgbench/pgbench.c | 1358 +++++++++++++++--- src/bin/pgbench/t/001_pgbench_with_server.pl | 408 +++++- src/bin/pgbench/t/002_pgbench_no_server.pl | 10 + src/fe_utils/conditional.c | 16 +- src/include/fe_utils/conditional.h | 2 + 6 files changed, 1962 insertions(+), 252 deletions(-) diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml index 88cf8b3933..4afc996825 100644 --- a/doc/src/sgml/ref/pgbench.sgml +++ b/doc/src/sgml/ref/pgbench.sgml @@ -55,16 +55,20 @@ number of clients: 10 number of threads: 1 number of transactions per client: 1000 number of transactions actually processed: 10000/10000 +maximum number of tries: 1 tps = 85.184871 (including connections establishing) tps = 85.296346 (excluding connections establishing) The first six lines report some of the most important parameter - settings. The next line reports the number of transactions completed + settings. The seventh 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 mode, only the actual - number of transactions is printed.) + failed before completion or some SQL/meta command(s) failed. (In + mode, only the actual number of transactions is printed.) + The next line reports the maximum number of tries for transactions with + serialization or deadlock errors (see for more information). The last two lines report the number of transactions per second, figured with and without counting the time to start database sessions. @@ -384,7 +388,8 @@ pgbench options d - Print debugging output. + Print debugging output. This option automatically turns on the option + . @@ -453,6 +458,17 @@ pgbench options d at all. They are counted and reported separately as skipped. + + When the option is used, the transaction + with serialization or deadlock error cannot be retried if the total time + of all its tries is greater than limit ms. To + limit only the time of tries and not their number, use + --max-tries=0. By default the option + is set to 1 and transactions with + serialization/deadlock errors are not retried at all. See + for more information about retrying such transactions. + @@ -513,22 +529,31 @@ pgbench options d Show progress report every 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 (), - 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. + deviation since the last report. If any transactions have received a + failure in the SQL or meta command since the last report, they are also + reported as failed. Under throttling (), 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. If any transactions have been rolled back and + retried after a serialization/deadlock error since the last report, the + report includes the number of such transactions and the sum of all + retries. Use the option to enable + transactions retries after serialization/deadlock errors. - + - 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. + Report the following statistics for each command after the benchmark + finishes: the average per-statement latency (execution time from the + perspective of the client), the number of failures and the number of + retries after serialization or deadlock errors in this command. The + report displays retry statistics only if the option + is not equal to 1. See below for details. @@ -656,6 +681,32 @@ pgbench options d + + + + + Report failures in per-transaction and aggregation logs, as well as in + the main and per-script reports, grouped by the following types: + + + serialization failures; + + + deadlock failures; + + + other SQL failures; + + + meta command failures. + + + See for more information. + + + + @@ -666,6 +717,39 @@ pgbench options d + + + + + Enable retries for transactions with serialization/deadlock errors and + set the maximum number of these tries. This option can be combined with + the option which limits the total time + of all transaction tries; more over, you cannot use an infinite number + of tries (--max-tries=0) without the option + . The default value is 1 and + transactions with serialization/deadlock errors are not retried at all. + See for more information about + retrying such transactions. + + + + + + + + + Print messages of all errors and failures (errors without retrying) + including which limit for retries was violated and how far it was + exceeded for the serialization/deadlock failures. (Note that in this + case the output can be significantly increased.). This option is + automatically enabled if the option is used. + See for more information. + + + + @@ -807,8 +891,8 @@ pgbench options d Notes - - What is the <quote>Transaction</quote> Actually Performed in <application>pgbench</application>? + + What is the <quote>Transaction</quote> Actually Performed in <application>pgbench</application>? pgbench executes test scripts chosen randomly @@ -881,6 +965,11 @@ pgbench options d both old and new versions of pgbench, be sure to write each SQL command on a single line ending with a semicolon. + + It is assumed that the scripts used do not contain incomplete blocks of SQL + transactions. If at runtime the client reaches the end of the script without + completing the last transaction block, he will be aborted. + @@ -1583,7 +1672,7 @@ END; The format of the log is: -client_id transaction_no time script_no time_epoch time_us schedule_lag +client_id transaction_no time script_no time_epoch time_us schedule_lag retries where @@ -1604,6 +1693,18 @@ END; When both and are used, the time for a skipped transaction will be reported as skipped. + retries is the sum of all the retries after the + serialization or deadlock errors during the current script execution. It is + present only if the option is not equal to 1. + If the transaction ended with a failure, its time + will be reported as failed. If you use the option + , the time of + the failed transaction will be reported as + serialization_failure / + deadlock_failure / other_sql_failure / + meta_command_failure depending on the type of failure (see + + for more information). @@ -1632,6 +1733,24 @@ END; were already late before they were even started. + + The following example shows a snippet of a log file with failures and + retries, with the maximum number of tries set to 10 (note the additional + retries column): + +3 0 47423 0 1499414498 34501 3 +3 1 8333 0 1499414498 42848 0 +3 2 8358 0 1499414498 51219 0 +4 0 72345 0 1499414498 59433 6 +1 3 41718 0 1499414498 67879 4 +1 4 8416 0 1499414498 76311 0 +3 3 33235 0 1499414498 84469 3 +0 0 failed 0 1499414498 84905 9 +2 0 failed 0 1499414498 86248 9 +3 4 8307 0 1499414498 92788 0 + + + When running a long test on hardware that can handle a lot of transactions, the log files can become very large. The option @@ -1647,7 +1766,7 @@ END; format is used for the log files: -interval_start num_transactions sum_latency sum_latency_2 min_latency max_latency sum_lag sum_lag_2 min_lag max_lag skipped +interval_start num_transactions sum_latency sum_latency_2 min_latency max_latency { failures | serialization_failures deadlock_failures other_sql_failures meta_command_failures } sum_lag sum_lag_2 min_lag max_lag skipped retried retries where @@ -1661,7 +1780,22 @@ END; transaction latencies within the interval, min_latency is the minimum latency within the interval, and - max_latency is the maximum latency within the interval. + max_latency is the maximum latency within the interval, + failures is the number of transactions that ended + with a failed SQL or meta command within the interval. If you use the option + , instead of the sum of all failed + transactions you will get more detailed statistics for the failed + transactions grouped by the following types: + serialization_failures is the number of + transactions that got a serialization error and were not retried after this, + deadlock_failures is the number of transactions + that got a deadlock error and were not retried after this, + other_sql_failures is the number of transactions + that got a different error in the SQL command (such errors are never + retried), + meta_command_failures is the number of + transactions that got an error in the meta command (such errors are never + retried). The next fields, sum_lag, sum_lag_2, min_lag, and max_lag, are only present if the @@ -1669,21 +1803,25 @@ END; They provide statistics about the time each transaction had to wait for the previous one to finish, i.e. the difference between each transaction's scheduled start time and the time it actually started. - The very last field, skipped, + The next field, skipped, is only present if the option is used, too. It counts the number of transactions skipped because they would have started too late. + The retried and retries + fields are present only if the option is not + equal to 1. They report the number of retried transactions and the sum of all + the retries after serialization or deadlock errors within the interval. Each transaction is counted in the interval when it was committed. Here is some example output: -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 1542744 483552416 61 2573 0 +1345828503 7884 1979812 565806736 60 1479 0 +1345828505 7208 1979422 567277552 59 1391 0 +1345828507 7685 1980268 569784714 60 1398 0 +1345828509 7073 1979779 573489941 236 1411 0 @@ -1695,13 +1833,44 @@ END; - Per-Statement Latencies + Per-Statement Report + + + With the option, pgbench + collects the following statistics for each statement: + + + + latency — elapsed transaction time for each + statement. pgbench reports an average value + of all successful runs of the statement. + + + + + The number of failures in this statement. See + for more information. + + + + + The number of retries after a serialization or a deadlock error in this + statement. See for more information. + + + + + + + The report displays retry statistics only if the option + is not equal to 1. + - With the option, 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. + All values are computed for each statement executed by every client and are + reported after the benchmark has finished. @@ -1715,27 +1884,64 @@ number of clients: 10 number of threads: 1 number of transactions per client: 1000 number of transactions actually processed: 10000/10000 +maximum number of tries: 1 latency average = 15.844 ms latency stddev = 2.715 ms tps = 618.764555 (including connections establishing) tps = 622.977698 (excluding connections establishing) -statement latencies in milliseconds: - 0.002 \set aid random(1, 100000 * :scale) - 0.005 \set bid random(1, 1 * :scale) - 0.002 \set tid random(1, 10 * :scale) - 0.001 \set delta random(-5000, 5000) - 0.326 BEGIN; - 0.603 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid; - 0.454 SELECT abalance FROM pgbench_accounts WHERE aid = :aid; - 5.528 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid; - 7.335 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid; - 0.371 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP); - 1.212 END; +statement latencies in milliseconds and failures: + 0.002 0 \set aid random(1, 100000 * :scale) + 0.005 0 \set bid random(1, 1 * :scale) + 0.002 0 \set tid random(1, 10 * :scale) + 0.001 0 \set delta random(-5000, 5000) + 0.326 0 BEGIN; + 0.603 0 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid; + 0.454 0 SELECT abalance FROM pgbench_accounts WHERE aid = :aid; + 5.528 0 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid; + 7.335 0 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid; + 0.371 0 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP); + 1.212 0 END; + + + Another example of output for the default script using serializable default + transaction isolation level (PGOPTIONS='-c + default_transaction_isolation=serializable' pgbench ...): + +starting vacuum...end. +transaction type: <builtin: TPC-B (sort of)> +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: 9676/10000 +number of failures: 324 (3.240%) +number of serialization failures: 324 (3.240%) +number of retried: 5629 (56.290%) +number of retries: 103299 +maximum number of tries: 100 +number of transactions above the 100.0 ms latency limit: 21/9676 (0.217 %) +latency average = 16.138 ms +latency stddev = 21.017 ms +tps = 413.650224 (including connections establishing) +tps = 413.686560 (excluding connections establishing) +statement latencies in milliseconds, failures and retries: + 0.002 0 0 \set aid random(1, 100000 * :scale) + 0.000 0 0 \set bid random(1, 1 * :scale) + 0.000 0 0 \set tid random(1, 10 * :scale) + 0.000 0 0 \set delta random(-5000, 5000) + 0.121 0 0 BEGIN; + 0.290 0 2 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid; + 0.221 0 0 SELECT abalance FROM pgbench_accounts WHERE aid = :aid; + 0.266 212 72127 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid; + 0.222 112 31170 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid; + 0.178 0 0 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP); + 1.210 0 0 END; - If multiple script files are specified, the averages are reported + If multiple script files are specified, all statistics are reported separately for each script file. @@ -1749,6 +1955,138 @@ statement latencies in milliseconds: + + Failures and Serialization/Deadlock Retries + + + When executing pgbench, there're three main types + of errors: + + + + Errors of the main program. They are the most serious and always result + in an immediate exit from the pgbench with + the corresponding error message. They include: + + + + errors at the beginning of the pgbench + (e.g. an invalid option value); + + + + + errors in the initialization mode (e.g. the query to create + tables for built-in scripts fails); + + + + + errors before starting threads (e.g. we could not connect to the + database server / the syntax error in the meta command / thread + creation failure); + + + + + internal pgbench errors (which are + supposed to never occur...). + + + + + + + + Errors when the thread manages its clients (e.g. the client could not + start a connection to the database server / the socket for connecting + the client to the database server has become invalid). In such cases + all clients of this thread stop while other threads continue to work. + + + + + Direct client errors. They lead to immediate exit from the + pgbench with the corresponding error message + only in the case of an internal pgbench + error (which are supposed to never occur...). Otherwise in the worst + case they only lead to the abortion of the failed client while other + clients continue their run (but most client errors are handled without + an abortion of the client and reported separately, see below). Later in + this section it is assumed that the discussed errors are only the + direct client errors and they are not internal + pgbench errors. + + + + + + + Client's run is aborted only in case of a serious error, for example, the + connection with the database server was lost or the end of script reached + without completing the last transaction. Otherwise if the execution of SQL or + meta command fails, the current transaction is always rolled back which also + includes setting the client variables as they were before the run of this + transaction (it is assumed that one transaction script contains only one + transaction; see for more information). + Transactions with serialization or deadlock errors are repeated after + rollbacks until they complete successfully or reach the maximum number of + tries (specified by the option) / the maximum + time of tries (specified by the option). If + the last transaction run fails, this transaction will be reported as failed. + + + + + Although without the option the transaction + will never be retried after an error, use an infinite number of tries + (--max-tries=0) and the option + to limit only the maximum time of tries. + + + Be careful when repeating scripts that contain multiple transactions: the + script is always retried completely, so the successful transactions can be + performed several times. + + + Be careful when repeating transactions with shell commands. Unlike the + results of SQL commands, the results of shell commands are not rolled back, + except for the variable value of the \setshell command. + + + + + The latency of a successful transaction includes the entire time of + transaction execution with rollbacks and retries. The latency for failed + transactions and commands is not computed separately. + + + + The main report contains the number of failed transactions if it is non-zero. + If the total number of retried transactions is non-zero, the main report also + contains the statistics related to retries: the total number of retried + transactions and total number of retries. The per-script report inherits all + these fields from the main report. The per-statement report displays retry + statistics only if the option is not equal to 1. + A retry is reported for the command if in this command an error is raised + which leads to a retry. + + + + If you want to group failures by basic types in per-transaction and + aggregation logs, as well as in the main and per-script reports, use the + option . If you also want to distinguish + all errors and failures (errors without retrying) by type including which + limit for retries was violated and how far it was exceeded for the + serialization/deadlock failures, use the options + or . The first + variant is recommended for this purpose because in the second case the output + can be significantly increased due to debug messages of successful commands + of all the transactions. + + + Good Practices diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c index 1b25487bfc..8da11209ad 100644 --- a/src/bin/pgbench/pgbench.c +++ b/src/bin/pgbench/pgbench.c @@ -59,6 +59,8 @@ #include "pgbench.h" +#define ERRCODE_T_R_SERIALIZATION_FAILURE "40001" +#define ERRCODE_T_R_DEADLOCK_DETECTED "40P01" #define ERRCODE_UNDEFINED_TABLE "42P01" /* @@ -187,9 +189,33 @@ bool progress_timestamp = false; /* progress report with Unix time */ int nclients = 1; /* number of clients */ int nthreads = 1; /* number of threads */ bool is_connect; /* establish connection for each transaction */ -bool is_latencies; /* report per-command latencies */ +bool report_per_command = false; /* report per-command latencies, retries + * after the errors and failures (errors + * without retrying) */ int main_pid; /* main process id used in log filename */ +/* + * There're different types of restrictions for deciding that the current + * transaction with a serialization/deadlock error can no longer be retried and + * should be reported as failed: + * - max_tries can be used to limit the number of tries; + * - latency_limit can be used to limit the total time of tries. + * + * They can be combined together, and you need to use at least one of them to + * retry the transactions with serialization/deadlock errors. If none of them is + * used, the default value of max_tries is set to 1 and such transactions will + * not be retried at all. + */ + +/* + * We cannot retry the transaction after the serialization/deadlock error if its + * number of tries reaches this maximum; if its value is zero, it is not used. + */ +uint32 max_tries = 0; + +bool failures_detailed = false; /* whether to group failures in reports + * or logs by basic types */ + char *pghost = ""; char *pgport = ""; char *login = NULL; @@ -267,9 +293,67 @@ typedef struct SimpleStats typedef struct StatsData { time_t start_time; /* interval start time, for aggregates */ - int64 cnt; /* number of transactions, including skipped */ + + /* + * Transactions are counted depending on their execution and outcome. First + * a transaction may have started or not: skipped transactions occur under + * --rate and --latency-limit when the client is too late to execute them. + * Secondly, a started transaction may ultimately succeed or get a failure, + * possibly after some retries when --max-tries is not one. Thus + * + * the number of all transactions = + * skipped (it was too late to execute them) + * cnt (the number of successful transactions) + + * failed (the number of failed transactions). + * + * A successful transaction can have several unsuccessful tries before a + * successful run. Thus + * + * cnt (the number of successful transactions) = + * successfully retried transactions (they got a serialization or a + * deadlock error(s), but were + * successfully retried from the very + * beginning) + + * directly successful transactions (they were successfully completed on + * the first try). + * + * A failed transaction can be one of several types: + * + * failed (the number of failed transactions) = + * serialization_failures (they got a serialization error and were not + * retried) + + * deadlock_failures (they got a deadlock error and were not retried) + + * other_sql_failures (they got a different error in the SQL command; such + * errors are never retried) + + * meta_command_failures (they got an error in the meta command; such + * errors are never retried). + * + * If the transaction was retried after a serialization or a deadlock error + * this does not guarantee that this retry was successful. Thus + * + * number of retries = + * number of retries in all retried transactions = + * number of retries in (successfully retried transactions + + * serialization failures + + * deadlock failures) transactions. + */ + int64 cnt; /* number of successful transactions */ int64 skipped; /* number of transactions skipped under --rate * and --latency-limit */ + int64 retries; /* number of retries after a serialization or a + * deadlock error in all the transactions */ + int64 retried; /* number of all transactions that were retried + * after a serialization or a deadlock error + * (perhaps the last try was unsuccessful) */ + int64 serialization_failures; /* number of transactions that were not + * retried after a serialization + * error */ + int64 deadlock_failures; /* number of transactions that were not + * retried after a deadlock error */ + int64 other_sql_failures; /* number of transactions with a different + * error in the SQL command */ + int64 meta_command_failures; /* number of transactions with an error + * in the meta command */ SimpleStats latency; SimpleStats lag; } StatsData; @@ -282,6 +366,30 @@ typedef struct unsigned short xseed[3]; } RandomState; +/* + * Data structure for repeating a transaction from the beginnning with the same + * parameters. + */ +typedef struct +{ + RandomState random_state; /* random seed */ + Variables variables; /* client variables */ +} RetryState; + +/* + * Error status for errors during script execution. + */ +typedef enum EStatus +{ + ESTATUS_NO_ERROR = 0, + ESTATUS_META_COMMAND_ERROR, + + /* SQL errors */ + ESTATUS_SERIALIZATION_ERROR, + ESTATUS_DEADLOCK_ERROR, + ESTATUS_OTHER_SQL_ERROR +} EStatus; + /* * Connection state machine states. */ @@ -336,6 +444,35 @@ typedef enum CSTATE_SLEEP, CSTATE_END_COMMAND, + /* + * States for failed commands. + * + * If the SQL/meta command fails, in CSTATE_ERROR clean up after an error: + * - clear the conditional stack; + * - if we have an unterminated (possibly failed) transaction block, send + * the rollback command to the server and wait for the result in + * CSTATE_WAIT_ROLLBACK_RESULT. If something goes wrong with rolling back, + * go to CSTATE_ABORTED. + * + * But if everything is ok we are ready for future transactions: if this is + * a serialization or deadlock error and we can re-execute the transaction + * from the very beginning, go to CSTATE_RETRY; otherwise go to + * CSTATE_FAILURE. + * + * In CSTATE_RETRY report an error, set the same parameters for the + * transaction execution as in the previous tries and process the first + * transaction command in CSTATE_START_COMMAND. + * + * In CSTATE_FAILURE report a failure, set the parameters for the + * transaction execution as they were before the first run of this + * transaction (except for a random state) and go to CSTATE_END_TX to + * complete this transaction. + */ + CSTATE_ERROR, + CSTATE_WAIT_ROLLBACK_RESULT, + CSTATE_RETRY, + CSTATE_FAILURE, + /* * CSTATE_END_TX performs end-of-transaction processing. Calculates * latency, and logs the transaction. In --connect mode, closes the @@ -382,10 +519,24 @@ typedef struct instr_time stmt_begin; /* used for measuring statement latencies */ bool prepared[MAX_SCRIPTS]; /* whether client prepared the script */ + bool rollback_prepared; /* whether client prepared a rollback + * command */ + + /* + * For processing failures and repeating transactions with serialization or + * deadlock errors: + */ + EStatus estatus; /* the error status of the current transaction + * execution; this is ESTATUS_NO_ERROR if there were + * no errors */ + RetryState retry_state; + uint32 retries; /* how many times have we already retried the + * current transaction after a serialization or + * a deadlock error? */ /* per client collected stats */ - int64 cnt; /* client transaction count, for -t */ - int ecnt; /* error count */ + int64 cnt; /* client transaction count, for -t; skipped and + * failed transactions are also counted here */ } CState; /* @@ -491,6 +642,10 @@ typedef struct char *argv[MAX_ARGS]; /* command word list */ PgBenchExpr *expr; /* parsed expression, if needed */ SimpleStats stats; /* time spent in this command */ + int64 retries; /* number of retries after a serialization or a + * deadlock error in the current command */ + int64 failures; /* number of errors in the current command that + * were not retried */ } Command; typedef struct ParsedScript @@ -506,7 +661,16 @@ static int num_scripts; /* number of scripts in sql_script[] */ static int num_commands = 0; /* total number of Command structs */ static int64 total_weight = 0; -static int debug = 0; /* debug flag */ +typedef enum DebugLevel +{ + NO_DEBUG = 0, /* no debugging output (except PGBENCH_DEBUG) */ + DEBUG_ERRORS, /* print only error messages, retries and + * failures */ + DEBUG_ALL /* print all debugging output (throttling, + * executed/sent/received commands etc.) */ +} DebugLevel; + +static DebugLevel debug_level = NO_DEBUG; /* debug flag */ /* Builtin test scripts */ typedef struct BuiltinScript @@ -618,15 +782,18 @@ usage(void) " protocol for submitting queries (default: simple)\n" " -n, --no-vacuum do not run VACUUM before tests\n" " -P, --progress=NUM show thread progress report every NUM seconds\n" - " -r, --report-latencies report average latency per command\n" + " -r, --report-per-command report latencies, failures and retries per command\n" " -R, --rate=NUM target rate in transactions per second\n" " -s, --scale=NUM report this scale factor in output\n" " -t, --transactions=NUM number of transactions each client runs (default: 10)\n" " -T, --time=NUM duration of benchmark test in seconds\n" " -v, --vacuum-all vacuum all four standard tables before tests\n" " --aggregate-interval=NUM aggregate data over NUM seconds\n" + " --failures-detailed report the failures grouped by basic types\n" " --log-prefix=PREFIX prefix for transaction time log file\n" " (default: \"pgbench_log\")\n" + " --max-tries=NUM max number of tries to run transaction (default: 1)\n" + " --print-errors print messages of all errors\n" " --progress-timestamp use Unix epoch timestamps for progress\n" " --random-seed=SEED set random seed (\"time\", \"rand\", integer)\n" " --sampling-rate=NUM fraction of transactions to log (e.g., 0.01 for 1%%)\n" @@ -1084,6 +1251,12 @@ initStats(StatsData *sd, time_t start_time) sd->start_time = start_time; sd->cnt = 0; sd->skipped = 0; + sd->retries = 0; + sd->retried = 0; + sd->serialization_failures = 0; + sd->deadlock_failures = 0; + sd->other_sql_failures = 0; + sd->meta_command_failures = 0; initSimpleStats(&sd->latency); initSimpleStats(&sd->lag); } @@ -1092,22 +1265,55 @@ 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, double lat, double lag, + EStatus estatus, int64 retries) { - stats->cnt++; - + /* Record the skipped transaction */ if (skipped) { /* no latency to record on skipped transactions */ stats->skipped++; + return; } - else + + /* + * Record the number of retries regardless of whether the transaction was + * successful or failed. + */ + stats->retries += retries; + if (retries > 0) + stats->retried++; + + switch (estatus) { - addToSimpleStats(&stats->latency, lat); + /* Record the successful transaction */ + case ESTATUS_NO_ERROR: + stats->cnt++; - /* and possibly the same for schedule lag */ - if (throttle_delay) - addToSimpleStats(&stats->lag, lag); + addToSimpleStats(&stats->latency, lat); + + /* and possibly the same for schedule lag */ + if (throttle_delay) + addToSimpleStats(&stats->lag, lag); + break; + + /* Record the failed transaction */ + case ESTATUS_META_COMMAND_ERROR: + stats->meta_command_failures++; + break; + case ESTATUS_SERIALIZATION_ERROR: + stats->serialization_failures++; + break; + case ESTATUS_DEADLOCK_ERROR: + stats->deadlock_failures++; + break; + case ESTATUS_OTHER_SQL_ERROR: + stats->other_sql_failures++; + break; + default: + /* internal error which should never occur */ + fprintf(stderr, "unexpected error status: %d\n", estatus); + exit(1); } } @@ -1340,9 +1546,10 @@ makeVariableValue(Variable *var) if (sscanf(var->svalue, "%lf%c", &dv, &xs) != 1) { - fprintf(stderr, - "malformed variable \"%s\" value: \"%s\"\n", - var->name, var->svalue); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "malformed variable \"%s\" value: \"%s\"\n", + var->name, var->svalue); return false; } setDoubleValue(&var->value, dv); @@ -1411,7 +1618,9 @@ enlargeVariables(Variables *variables, int needed) /* * Lookup a variable by name, creating it if need be. * Caller is expected to assign a value to the variable. - * Returns NULL on failure (bad name). + * Returns NULL on failure (bad name). Because this can be used by client + * commands, print an error message only in debug mode. The caller can print his + * own error message. */ static Variable * lookupCreateVariable(Variables *variables, const char *context, char *name) @@ -1427,8 +1636,9 @@ lookupCreateVariable(Variables *variables, const char *context, char *name) */ if (!valid_variable_name(name)) { - fprintf(stderr, "%s: invalid variable name: \"%s\"\n", - context, name); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: invalid variable name: \"%s\"\n", + context, name); return NULL; } @@ -1460,7 +1670,11 @@ putVariable(Variables *variables, const char *context, char *name, var = lookupCreateVariable(variables, context, name); if (!var) + { + fprintf(stderr, "%s: error while setting variable \"%s\"\n", + context, name); return false; + } /* dup then free, in case value is pointing at this variable */ val = pg_strdup(value); @@ -1473,8 +1687,12 @@ putVariable(Variables *variables, const char *context, char *name, return true; } -/* Assign a value to a variable, creating it if need be */ -/* Returns false on failure (bad name) */ +/* + * Assign a value to a variable, creating it if need be. + * Returns false on failure (bad name). Because this can be used by client + * commands, print an error message only in debug mode. The caller can print his + * own error message. + */ static bool putVariableValue(Variables *variables, const char *context, char *name, const PgBenchValue *value) @@ -1483,7 +1701,12 @@ putVariableValue(Variables *variables, const char *context, char *name, var = lookupCreateVariable(variables, context, name); if (!var) + { + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: error while setting variable \"%s\"\n", + context, name); return false; + } if (var->svalue) free(var->svalue); @@ -1493,8 +1716,12 @@ putVariableValue(Variables *variables, const char *context, char *name, return true; } -/* Assign an integer value to a variable, creating it if need be */ -/* Returns false on failure (bad name) */ +/* + * Assign an integer value to a variable, creating it if need be. + * Returns false on failure (bad name). Because this can be used by client + * commands, print an error message only in debug mode. The caller can print his + * own error message. + */ static bool putVariableInt(Variables *variables, const char *context, char *name, int64 value) @@ -1634,7 +1861,9 @@ coerceToBool(PgBenchValue *pval, bool *bval) } else /* NULL, INT or DOUBLE */ { - fprintf(stderr, "cannot coerce %s to boolean\n", valueTypeName(pval)); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "cannot coerce %s to boolean\n", + valueTypeName(pval)); *bval = false; /* suppress uninitialized-variable warnings */ return false; } @@ -1679,7 +1908,8 @@ coerceToInt(PgBenchValue *pval, int64 *ival) if (dval < PG_INT64_MIN || PG_INT64_MAX < dval) { - fprintf(stderr, "double to int overflow for %f\n", dval); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "double to int overflow for %f\n", dval); return false; } *ival = (int64) dval; @@ -1687,7 +1917,8 @@ coerceToInt(PgBenchValue *pval, int64 *ival) } else /* BOOLEAN or NULL */ { - fprintf(stderr, "cannot coerce %s to int\n", valueTypeName(pval)); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "cannot coerce %s to int\n", valueTypeName(pval)); return false; } } @@ -1708,7 +1939,9 @@ coerceToDouble(PgBenchValue *pval, double *dval) } else /* BOOLEAN or NULL */ { - fprintf(stderr, "cannot coerce %s to double\n", valueTypeName(pval)); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "cannot coerce %s to double\n", + valueTypeName(pval)); return false; } } @@ -1889,8 +2122,9 @@ evalStandardFunc(TState *thread, CState *st, if (l != NULL) { - fprintf(stderr, - "too many function arguments, maximum is %d\n", MAX_FARGS); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "too many function arguments, maximum is %d\n", MAX_FARGS); return false; } @@ -2013,7 +2247,8 @@ evalStandardFunc(TState *thread, CState *st, case PGBENCH_MOD: if (ri == 0) { - fprintf(stderr, "division by zero\n"); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "division by zero\n"); return false; } /* special handling of -1 divisor */ @@ -2024,7 +2259,9 @@ evalStandardFunc(TState *thread, CState *st, /* overflow check (needed for INT64_MIN) */ if (li == PG_INT64_MIN) { - fprintf(stderr, "bigint out of range\n"); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "bigint out of range\n"); return false; } else @@ -2264,13 +2501,15 @@ evalStandardFunc(TState *thread, CState *st, /* check random range */ if (imin > imax) { - fprintf(stderr, "empty range given to random\n"); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "empty range given to random\n"); return false; } else if (imax - imin < 0 || (imax - imin) + 1 < 0) { /* prevent int overflows in random functions */ - fprintf(stderr, "random range is too large\n"); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "random range is too large\n"); return false; } @@ -2292,9 +2531,10 @@ evalStandardFunc(TState *thread, CState *st, { if (param < MIN_GAUSSIAN_PARAM) { - fprintf(stderr, - "gaussian parameter must be at least %f " - "(not %f)\n", MIN_GAUSSIAN_PARAM, param); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "gaussian parameter must be at least %f (not %f)\n", + MIN_GAUSSIAN_PARAM, param); return false; } @@ -2306,9 +2546,10 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0 || param == 1.0 || param > MAX_ZIPFIAN_PARAM) { - fprintf(stderr, - "zipfian parameter must be in range (0, 1) U (1, %d]" - " (got %f)\n", MAX_ZIPFIAN_PARAM, param); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "zipfian parameter must be in range (0, 1) U (1, %d] (got %f)\n", + MAX_ZIPFIAN_PARAM, param); return false; } setIntValue(retval, @@ -2320,9 +2561,10 @@ evalStandardFunc(TState *thread, CState *st, { if (param <= 0.0) { - fprintf(stderr, - "exponential parameter must be greater than zero" - " (got %f)\n", param); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "exponential parameter must be greater than zero (got %f)\n", + param); return false; } @@ -2433,8 +2675,9 @@ evaluateExpr(TState *thread, CState *st, PgBenchExpr *expr, PgBenchValue *retval if ((var = lookupVariable(&st->variables, expr->u.variable.varname)) == NULL) { - fprintf(stderr, "undefined variable \"%s\"\n", - expr->u.variable.varname); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "undefined variable \"%s\"\n", + expr->u.variable.varname); return false; } @@ -2528,15 +2771,17 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) } else if ((arg = getVariable(variables, argv[i] + 1)) == NULL) { - fprintf(stderr, "%s: undefined variable \"%s\"\n", - argv[0], argv[i]); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: undefined variable \"%s\"\n", + argv[0], argv[i]); return false; } arglen = strlen(arg); if (len + arglen + (i > 0 ? 1 : 0) >= SHELL_COMMAND_SIZE - 1) { - fprintf(stderr, "%s: shell command is too long\n", argv[0]); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: shell command is too long\n", argv[0]); return false; } @@ -2553,7 +2798,7 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) { if (system(command)) { - if (!timer_exceeded) + if (!timer_exceeded && debug_level >= DEBUG_ERRORS) fprintf(stderr, "%s: could not launch shell command\n", argv[0]); return false; } @@ -2563,19 +2808,21 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) /* Execute the command with pipe and read the standard output. */ if ((fp = popen(command, "r")) == NULL) { - fprintf(stderr, "%s: could not launch shell command\n", argv[0]); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: could not launch shell command\n", argv[0]); return false; } if (fgets(res, sizeof(res), fp) == NULL) { - if (!timer_exceeded) + if (!timer_exceeded && debug_level >= DEBUG_ERRORS) fprintf(stderr, "%s: could not read result of shell command\n", argv[0]); (void) pclose(fp); return false; } if (pclose(fp) < 0) { - fprintf(stderr, "%s: could not close shell command\n", argv[0]); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: could not close shell command\n", argv[0]); return false; } @@ -2585,8 +2832,10 @@ runShellCommand(Variables *variables, char *variable, char **argv, int argc) endptr++; if (*res == '\0' || *endptr != '\0') { - fprintf(stderr, "%s: shell command must return an integer (not \"%s\")\n", - argv[0], res); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, + "%s: shell command must return an integer (not \"%s\")\n", + argv[0], res); return false; } if (!putVariableInt(variables, "setshell", variable, retval)) @@ -2605,14 +2854,31 @@ preparedStatementName(char *buffer, int file, int state) sprintf(buffer, "P%d_%d", file, state); } +/* + * Report the error in the command while the script is executing. + */ static void commandFailed(CState *st, const char *cmd, const char *message) { fprintf(stderr, - "client %d aborted in command %d (%s) of script %d; %s\n", + "client %d got an error in command %d (%s) of script %d; %s\n", st->id, st->command, cmd, st->use_file, message); } +/* + * Report the abortion of the client when processing SQL commands. + */ +static void +clientAborted(CState *st, const char *message) +{ + const Command *command = sql_script[st->use_file].commands[st->command]; + + Assert(command->type == SQL_COMMAND); + fprintf(stderr, + "client %d aborted in command %d (SQL) of script %d; %s\n", + st->id, st->command, st->use_file, message); +} + /* return a script number with a weighted choice. */ static int chooseScript(TState *thread) @@ -2645,7 +2911,7 @@ sendCommand(CState *st, Command *command) sql = pg_strdup(command->argv[0]); sql = assignVariables(&st->variables, sql); - if (debug) + if (debug_level >= DEBUG_ALL) fprintf(stderr, "client %d sending %s\n", st->id, sql); r = PQsendQuery(st->con, sql); free(sql); @@ -2657,7 +2923,7 @@ sendCommand(CState *st, Command *command) getQueryParams(&st->variables, command, params); - if (debug) + if (debug_level >= DEBUG_ALL) fprintf(stderr, "client %d sending %s\n", st->id, sql); r = PQsendQueryParams(st->con, sql, command->argc - 1, NULL, params, NULL, NULL, 0); @@ -2692,7 +2958,7 @@ sendCommand(CState *st, Command *command) getQueryParams(&st->variables, command, params); preparedStatementName(name, st->use_file, st->command); - if (debug) + if (debug_level >= DEBUG_ALL) fprintf(stderr, "client %d sending %s\n", st->id, name); r = PQsendQueryPrepared(st->con, name, command->argc - 1, params, NULL, NULL, 0); @@ -2702,10 +2968,62 @@ sendCommand(CState *st, Command *command) if (r == 0) { - if (debug) + if (debug_level >= DEBUG_ALL) fprintf(stderr, "client %d could not send %s\n", st->id, command->argv[0]); - st->ecnt++; + return false; + } + else + return true; +} + +/* Send a rollback command, using the chosen querymode */ +static bool +sendRollback(CState *st) +{ + static const char *rollback_cmd = "ROLLBACK;"; + static const char *prepared_name = "P_rollback"; /* for QUERY_PREPARED */ + int r; + + if (querymode == QUERY_SIMPLE) + { + if (debug_level >= DEBUG_ALL) + fprintf(stderr, "client %d sending %s\n", st->id, rollback_cmd); + r = PQsendQuery(st->con, rollback_cmd); + } + else if (querymode == QUERY_EXTENDED) + { + if (debug_level >= DEBUG_ALL) + fprintf(stderr, "client %d sending %s\n", st->id, rollback_cmd); + r = PQsendQueryParams(st->con, rollback_cmd, 0, + NULL, NULL, NULL, NULL, 0); + } + else if (querymode == QUERY_PREPARED) + { + if (!st->rollback_prepared) + { + PGresult *res; + + res = PQprepare(st->con, prepared_name, rollback_cmd, 0, NULL); + if (PQresultStatus(res) != PGRES_COMMAND_OK) + fprintf(stderr, "%s", PQerrorMessage(st->con)); + PQclear(res); + st->rollback_prepared = true; + } + + if (debug_level >= DEBUG_ALL) + fprintf(stderr, "client %d sending %s\n", st->id, prepared_name); + r = PQsendQueryPrepared(st->con, prepared_name, 0, + NULL, NULL, NULL, 0); + } + else /* unknown sql mode */ + r = 0; + + if (r == 0) + { + if (debug_level >= DEBUG_ALL) + fprintf(stderr, "client %d could not send %s\n", + st->id, rollback_cmd); return false; } else @@ -2726,8 +3044,9 @@ evaluateSleep(Variables *variables, int argc, char **argv, int *usecs) { if ((var = getVariable(variables, argv[1] + 1)) == NULL) { - fprintf(stderr, "%s: undefined variable \"%s\"\n", - argv[0], argv[1]); + if (debug_level >= DEBUG_ERRORS) + fprintf(stderr, "%s: undefined variable \"%s\"\n", + argv[0], argv[1]); return false; } usec = atoi(var); @@ -2749,6 +3068,192 @@ evaluateSleep(Variables *variables, int argc, char **argv, int *usecs) return true; } +/* + * Clear the variables in the array. The array itself is not freed. + */ +static void +clearVariables(Variables *variables) +{ + Variable *vars, + *var; + int nvars; + + if (!variables) + return; /* nothing to do here */ + + vars = variables->vars; + nvars = variables->nvars; + for (var = vars; var - vars < nvars; ++var) + { + pg_free(var->name); + pg_free(var->svalue); + } + + variables->nvars = 0; +} + +/* + * Make a deep copy of variables array. + * Before copying the function frees the string fields of the destination + * variables and if necessary enlarges their array. + */ +static void +copyVariables(Variables *dest, const Variables *source) +{ + Variable *dest_var; + const Variable *source_var; + + if (!dest || !source || dest == source) + return; /* nothing to do here */ + + /* + * Clear the original variables and make sure that we have enough space for + * the new variables. + */ + clearVariables(dest); + enlargeVariables(dest, source->nvars); + + /* Make a deep copy of variables array */ + for (source_var = source->vars, dest_var = dest->vars; + source_var - source->vars < source->nvars; + ++source_var, ++dest_var) + { + dest_var->name = pg_strdup(source_var->name); + if (source_var->svalue == NULL) + dest_var->svalue = NULL; + else + dest_var->svalue = pg_strdup(source_var->svalue); + dest_var->value = source_var->value; + } + dest->nvars = source->nvars; + dest->vars_sorted = source->vars_sorted; +} + +/* + * Get the error status from the error code. + */ +static EStatus +getSQLErrorStatus(const char *sqlState) +{ + if (sqlState) + { + if (strcmp(sqlState, ERRCODE_T_R_SERIALIZATION_FAILURE) == 0) + return ESTATUS_SERIALIZATION_ERROR; + else if (strcmp(sqlState, ERRCODE_T_R_DEADLOCK_DETECTED) == 0) + return ESTATUS_DEADLOCK_ERROR; + } + + return ESTATUS_OTHER_SQL_ERROR; +} + +/* + * Returns true if this type of error can be retried. + */ +static bool +canRetryError(EStatus estatus) +{ + return (estatus == ESTATUS_SERIALIZATION_ERROR || + estatus == ESTATUS_DEADLOCK_ERROR); +} + +/* + * Returns true if the error can be retried. + */ +static bool +doRetry(CState *st, instr_time *now) +{ + Assert(st->estatus != ESTATUS_NO_ERROR); + + /* We can only retry serialization or deadlock errors. */ + if (!canRetryError(st->estatus)) + return false; + + /* + * We must have at least one option to limit the retrying of transactions + * that got an error. + */ + Assert(max_tries || latency_limit); + + /* + * We cannot retry the error if we have reached the maximum number of tries. + */ + if (max_tries && st->retries + 1 >= max_tries) + return false; + + /* + * We cannot retry the error if we spent too much time on this transaction. + */ + if (latency_limit) + { + if (INSTR_TIME_IS_ZERO(*now)) + INSTR_TIME_SET_CURRENT(*now); + + if (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled > latency_limit) + return false; + } + + /* OK */ + return true; +} + +/* + * Set in_tx_block to true if we are in a (failed) transaction block and false + * otherwise. + * Returns false on failure (broken connection or internal error). + */ +static bool +getTransactionStatus(PGconn *con, bool *in_tx_block) +{ + PGTransactionStatusType tx_status; + + tx_status = PQtransactionStatus(con); + switch (tx_status) + { + case PQTRANS_IDLE: + *in_tx_block = false; + break; + case PQTRANS_INTRANS: + case PQTRANS_INERROR: + *in_tx_block = true; + break; + case PQTRANS_UNKNOWN: + /* PQTRANS_UNKNOWN is expected given a broken connection */ + if (PQstatus(con) == CONNECTION_BAD) + { /* there's something wrong */ + fprintf(stderr, "perhaps the backend died while processing\n"); + return false; + } + case PQTRANS_ACTIVE: + default: + /* + * We cannot find out whether we are in a transaction block or not. + * Internal error which should never occur. + */ + fprintf(stderr, "unexpected transaction status %d\n", tx_status); + return false; + } + + /* OK */ + return true; +} + +/* + * If the latency limit is used, return a percentage of the current transaction + * latency from the latency limit. Otherwise return zero. + */ +static double +getLatencyUsed(CState *st, instr_time *now) +{ + if (!latency_limit) + return 0.0; + + if (INSTR_TIME_IS_ZERO(*now)) + INSTR_TIME_SET_CURRENT(*now); + + return (100.0 * (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled) / + latency_limit); +} + /* * Advance the state machine of a connection, if possible. */ @@ -2790,9 +3295,9 @@ doCustom(TState *thread, CState *st, StatsData *agg) st->use_file = chooseScript(thread); - if (debug) - fprintf(stderr, "client %d executing script \"%s\"\n", st->id, - sql_script[st->use_file].desc); + if (debug_level >= DEBUG_ALL) + fprintf(stderr, "client %d executing script \"%s\"\n", + st->id, sql_script[st->use_file].desc); if (throttle_delay > 0) st->state = CSTATE_START_THROTTLE; @@ -2800,6 +3305,10 @@ doCustom(TState *thread, CState *st, StatsData *agg) st->state = CSTATE_START_TX; /* check consistency */ Assert(conditional_stack_empty(st->cstack)); + + /* reset transaction variables to default values */ + st->estatus = ESTATUS_NO_ERROR; + st->retries = 0; break; /* @@ -2865,7 +3374,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) } st->state = CSTATE_THROTTLE; - if (debug) + if (debug_level >= DEBUG_ALL) fprintf(stderr, "client %d throttling " INT64_FORMAT " us\n", st->id, wait); break; @@ -2909,8 +3418,17 @@ doCustom(TState *thread, CState *st, StatsData *agg) /* Reset session-local state */ memset(st->prepared, 0, sizeof(st->prepared)); + st->rollback_prepared = false; } + /* + * It is the first try to run this transaction. Remember its + * parameters: maybe it will get an error and we will need to + * run it again. + */ + st->retry_state.random_state = st->random_state; + copyVariables(&st->retry_state.variables, &st->variables); + /* * Record transaction start time under logging, progress or * throttling. @@ -2955,7 +3473,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) * Record statement start time if per-command latencies are * requested */ - if (is_latencies) + if (report_per_command) { if (INSTR_TIME_IS_ZERO(now)) INSTR_TIME_SET_CURRENT(now); @@ -2966,7 +3484,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) { if (!sendCommand(st, command)) { - commandFailed(st, "SQL", "SQL command send failed"); + clientAborted(st, "SQL command send failed"); st->state = CSTATE_ABORTED; } else @@ -2978,7 +3496,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) i; char **argv = command->argv; - if (debug) + if (debug_level >= DEBUG_ALL) { fprintf(stderr, "client %d executing \\%s", st->id, argv[0]); for (i = 1; i < argc; i++) @@ -2999,8 +3517,11 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (!evaluateSleep(&st->variables, argc, argv, &usec)) { - commandFailed(st, "sleep", "execution of meta-command failed"); - st->state = CSTATE_ABORTED; + if (debug_level >= DEBUG_ERRORS) + commandFailed(st, "sleep", + "execution of meta-command failed"); + st->estatus = ESTATUS_META_COMMAND_ERROR; + st->state = CSTATE_ERROR; break; } @@ -3031,8 +3552,11 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (!evaluateExpr(thread, st, expr, &result)) { - commandFailed(st, argv[0], "evaluation of meta-command failed"); - st->state = CSTATE_ABORTED; + if (debug_level >= DEBUG_ERRORS) + commandFailed(st, argv[0], + "evaluation of meta-command failed"); + st->estatus = ESTATUS_META_COMMAND_ERROR; + st->state = CSTATE_ERROR; break; } @@ -3041,8 +3565,11 @@ doCustom(TState *thread, CState *st, StatsData *agg) if (!putVariableValue(&st->variables, argv[0], argv[1], &result)) { - commandFailed(st, "set", "assignment of meta-command failed"); - st->state = CSTATE_ABORTED; + if (debug_level >= DEBUG_ERRORS) + commandFailed(st, "set", + "assignment of meta-command failed"); + st->estatus = ESTATUS_META_COMMAND_ERROR; + st->state = CSTATE_ERROR; break; } } @@ -3103,8 +3630,11 @@ doCustom(TState *thread, CState *st, StatsData *agg) } else if (!ret) /* on error */ { - commandFailed(st, "setshell", "execution of meta-command failed"); - st->state = CSTATE_ABORTED; + if (debug_level >= DEBUG_ERRORS) + commandFailed(st, "setshell", + "execution of meta-command failed"); + st->estatus = ESTATUS_META_COMMAND_ERROR; + st->state = CSTATE_ERROR; break; } else @@ -3124,8 +3654,11 @@ doCustom(TState *thread, CState *st, StatsData *agg) } else if (!ret) /* on error */ { - commandFailed(st, "shell", "execution of meta-command failed"); - st->state = CSTATE_ABORTED; + if (debug_level >= DEBUG_ERRORS) + commandFailed(st, "shell", + "execution of meta-command failed"); + st->estatus = ESTATUS_META_COMMAND_ERROR; + st->state = CSTATE_ERROR; break; } else @@ -3242,11 +3775,12 @@ doCustom(TState *thread, CState *st, StatsData *agg) */ case CSTATE_WAIT_RESULT: command = sql_script[st->use_file].commands[st->command]; - if (debug) + if (debug_level >= DEBUG_ALL) fprintf(stderr, "client %d receiving\n", st->id); if (!PQconsumeInput(st->con)) { /* there's something wrong */ - commandFailed(st, "SQL", "perhaps the backend died while processing"); + clientAborted(st, + "perhaps the backend died while processing"); st->state = CSTATE_ABORTED; break; } @@ -3263,12 +3797,66 @@ doCustom(TState *thread, CState *st, StatsData *agg) case PGRES_TUPLES_OK: case PGRES_EMPTY_QUERY: /* OK */ + st->estatus = ESTATUS_NO_ERROR; PQclear(res); discard_response(st); st->state = CSTATE_END_COMMAND; break; + case PGRES_NONFATAL_ERROR: + case PGRES_FATAL_ERROR: + st->estatus = getSQLErrorStatus( + PQresultErrorField(res, PG_DIAG_SQLSTATE)); + if (debug_level >= DEBUG_ERRORS) + commandFailed(st, "SQL", PQerrorMessage(st->con)); + PQclear(res); + discard_response(st); + st->state = CSTATE_ERROR; + break; default: - commandFailed(st, "SQL", PQerrorMessage(st->con)); + clientAborted(st, PQerrorMessage(st->con)); + PQclear(res); + st->state = CSTATE_ABORTED; + break; + } + break; + + /* + * Wait for the rollback command to complete + */ + case CSTATE_WAIT_ROLLBACK_RESULT: + if (debug_level >= DEBUG_ALL) + fprintf(stderr, "client %d receiving\n", st->id); + if (!PQconsumeInput(st->con)) + { + fprintf(stderr, + "client %d aborted while rolling back the transaction after an error; perhaps the backend died while processing\n", + st->id); + st->state = CSTATE_ABORTED; + break; + } + if (PQisBusy(st->con)) + return; /* don't have the whole result yet */ + + /* + * Read and discard the query result; + */ + res = PQgetResult(st->con); + switch (PQresultStatus(res)) + { + case PGRES_COMMAND_OK: + /* OK */ + PQclear(res); + discard_response(st); + /* Check if we can retry the error. */ + if (doRetry(st, &now)) + st->state = CSTATE_RETRY; + else + st->state = CSTATE_FAILURE; + break; + default: + fprintf(stderr, + "client %d aborted while rolling back the transaction after an error; %s\n", + st->id, PQerrorMessage(st->con)); PQclear(res); st->state = CSTATE_ABORTED; break; @@ -3300,7 +3888,7 @@ doCustom(TState *thread, CState *st, StatsData *agg) * in thread-local data structure, if per-command latencies * are requested. */ - if (is_latencies) + if (report_per_command) { if (INSTR_TIME_IS_ZERO(now)) INSTR_TIME_SET_CURRENT(now); @@ -3319,52 +3907,215 @@ doCustom(TState *thread, CState *st, StatsData *agg) break; /* - * End of transaction. + * Clean up after an error. */ - case CSTATE_END_TX: + case CSTATE_ERROR: + { + bool in_tx_block; - /* transaction finished: calculate latency and do log */ - processXactStats(thread, st, &now, false, agg); + Assert(st->estatus != ESTATUS_NO_ERROR); - /* conditional stack must be empty */ - if (!conditional_stack_empty(st->cstack)) - { - fprintf(stderr, "end of script reached within a conditional, missing \\endif\n"); - exit(1); + /* Clear the conditional stack */ + conditional_stack_reset(st->cstack); + + /* + * Check if we have a (failed) transaction block or not, and + * roll it back if any. + */ + + if (!getTransactionStatus(st->con, &in_tx_block)) + { + /* + * There's something wrong... + * It is assumed that the function getTransactionStatus + * has already printed a more detailed error message. + */ + fprintf(stderr, + "client %d aborted while receiving the transaction status\n", + st->id); + st->state = CSTATE_ABORTED; + break; + } + + if (in_tx_block) + { + /* Try to rollback a (failed) transaction block. */ + if (!sendRollback(st)) + { + fprintf(stderr, + "client %d aborted: failed to send sql command for rolling back the failed transaction\n", + st->id); + st->state = CSTATE_ABORTED; + } + else + st->state = CSTATE_WAIT_ROLLBACK_RESULT; + } + else + { + /* Check if we can retry the error. */ + if (doRetry(st, &now)) + st->state = CSTATE_RETRY; + else + st->state = CSTATE_FAILURE; + } } + break; + + /* + * Retry the transaction after an error. + */ + case CSTATE_RETRY: + command = sql_script[st->use_file].commands[st->command]; + + /* Accumulate the retry. */ + st->retries++; + if (report_per_command) + command->retries++; - if (is_connect) + /* + * Inform that the transaction will be retried after the error. + */ + if (debug_level >= DEBUG_ERRORS) { - finishCon(st); - INSTR_TIME_SET_ZERO(now); + fprintf(stderr, + "client %d repeats the transaction after the error (try %d", + st->id, st->retries + 1); + if (max_tries) + fprintf(stderr, "/%d", max_tries); + if (latency_limit) + fprintf(stderr, + ", %.3f%% of the maximum time of tries was used", + getLatencyUsed(st, &now)); + fprintf(stderr, ")\n"); } - if ((st->cnt >= nxacts && duration <= 0) || timer_exceeded) + /* + * Reset the execution parameters as they were at the beginning + * of the transaction. + */ + st->random_state = st->retry_state.random_state; + copyVariables(&st->variables, &st->retry_state.variables); + + /* Process the first transaction command. */ + st->command = 0; + st->estatus = ESTATUS_NO_ERROR; + st->state = CSTATE_START_COMMAND; + break; + + /* + * Complete the failed transaction. + */ + case CSTATE_FAILURE: + command = sql_script[st->use_file].commands[st->command]; + + /* Accumulate the failure. */ + if (report_per_command) + command->failures++; + + /* + * If this is a serialization or deadlock failure, inform that + * the failed transaction will not be retried. + */ + if (debug_level >= DEBUG_ERRORS && canRetryError(st->estatus)) { - /* exit success */ - st->state = CSTATE_FINISHED; - break; + fprintf(stderr, + "client %d ends the failed transaction (try %d", + st->id, st->retries + 1); + if (max_tries) + fprintf(stderr, "/%d", max_tries); + if (latency_limit) + fprintf(stderr, + ", %.3f%% of the maximum time of tries was used", + getLatencyUsed(st, &now)); + fprintf(stderr, ")\n"); } /* - * No transaction is underway anymore. + * Reset the execution parameters as they were at the beginning + * of the transaction except for a random state. */ - st->state = CSTATE_CHOOSE_SCRIPT; + copyVariables(&st->variables, &st->retry_state.variables); + + /* End the failed transaction. */ + st->state = CSTATE_END_TX; + break; /* - * If we paced through all commands in the script in this - * loop, without returning to the caller even once, do it now. - * This gives the thread a chance to process other - * connections, and to do progress reporting. This can - * currently only happen if the script consists entirely of - * meta-commands. + * End of transaction. */ - if (end_tx_processed) - return; - else + case CSTATE_END_TX: { - end_tx_processed = true; - break; + bool in_tx_block; + + /* transaction finished: calculate latency and do log */ + processXactStats(thread, st, &now, false, agg); + + /* conditional stack must be empty */ + if (!conditional_stack_empty(st->cstack)) + { + fprintf(stderr, "end of script reached within a conditional, missing \\endif\n"); + exit(1); + } + + /* + * We must complete all the transaction blocks that were + * started in this script. + */ + if (!getTransactionStatus(st->con, &in_tx_block)) + { + /* + * There's something wrong... + * It is assumed that the function getTransactionStatus + * has already printed a more detailed error message. + */ + fprintf(stderr, + "client %d aborted while receiving the transaction status\n", + st->id); + st->state = CSTATE_ABORTED; + break; + } + if (in_tx_block) + { + fprintf(stderr, + "client %d aborted: end of script reached without completing the last transaction\n", + st->id); + st->state = CSTATE_ABORTED; + break; + } + + if (is_connect) + { + finishCon(st); + INSTR_TIME_SET_ZERO(now); + } + + if ((st->cnt >= nxacts && duration <= 0) || timer_exceeded) + { + /* exit success */ + st->state = CSTATE_FINISHED; + break; + } + + /* + * No transaction is underway anymore. + */ + st->state = CSTATE_CHOOSE_SCRIPT; + + /* + * If we paced through all commands in the script in this + * loop, without returning to the caller even once, do it now. + * This gives the thread a chance to process other + * connections, and to do progress reporting. This can + * currently only happen if the script consists entirely of + * meta-commands. + */ + if (end_tx_processed) + return; + else + { + end_tx_processed = true; + break; + } } /* @@ -3378,6 +4129,15 @@ doCustom(TState *thread, CState *st, StatsData *agg) } } +static int64 +getFailures(const StatsData *stats) +{ + return (stats->serialization_failures + + stats->deadlock_failures + + stats->other_sql_failures + + stats->meta_command_failures); +} + /* * Print log entry after completing one transaction. * @@ -3422,6 +4182,16 @@ doLog(TState *thread, CState *st, agg->latency.sum2, agg->latency.min, agg->latency.max); + + if (failures_detailed) + fprintf(logfile, " " INT64_FORMAT " " INT64_FORMAT " " INT64_FORMAT " " INT64_FORMAT, + agg->serialization_failures, + agg->deadlock_failures, + agg->other_sql_failures, + agg->meta_command_failures); + else + fprintf(logfile, " " INT64_FORMAT, getFailures(agg)); + if (throttle_delay) { fprintf(logfile, " %.0f %.0f %.0f %.0f", @@ -3432,6 +4202,10 @@ doLog(TState *thread, CState *st, if (latency_limit) fprintf(logfile, " " INT64_FORMAT, agg->skipped); } + if (max_tries != 1) + fprintf(logfile, " " INT64_FORMAT " " INT64_FORMAT, + agg->retried, + agg->retries); fputc('\n', logfile); /* reset data and move to next interval */ @@ -3439,7 +4213,7 @@ doLog(TState *thread, CState *st, } /* accumulate the current transaction */ - accumStats(agg, skipped, latency, lag); + accumStats(agg, skipped, latency, lag, st->estatus, st->retries); } else { @@ -3451,12 +4225,50 @@ doLog(TState *thread, CState *st, fprintf(logfile, "%d " INT64_FORMAT " skipped %d %ld %ld", st->id, st->cnt, st->use_file, (long) tv.tv_sec, (long) tv.tv_usec); - else + else if (st->estatus == ESTATUS_NO_ERROR) fprintf(logfile, "%d " INT64_FORMAT " %.0f %d %ld %ld", st->id, st->cnt, latency, st->use_file, (long) tv.tv_sec, (long) tv.tv_usec); + else if (failures_detailed) + { + switch (st->estatus) + { + case ESTATUS_META_COMMAND_ERROR: + fprintf(logfile, "%d " INT64_FORMAT " meta_command_failure %d %ld %ld", + st->id, st->cnt, st->use_file, + (long) tv.tv_sec, (long) tv.tv_usec); + break; + case ESTATUS_SERIALIZATION_ERROR: + fprintf(logfile, "%d " INT64_FORMAT " serialization_failure %d %ld %ld", + st->id, st->cnt, st->use_file, + (long) tv.tv_sec, (long) tv.tv_usec); + break; + case ESTATUS_DEADLOCK_ERROR: + fprintf(logfile, "%d " INT64_FORMAT " deadlock_failure %d %ld %ld", + st->id, st->cnt, st->use_file, + (long) tv.tv_sec, (long) tv.tv_usec); + break; + case ESTATUS_OTHER_SQL_ERROR: + fprintf(logfile, "%d " INT64_FORMAT " other_sql_failure %d %ld %ld", + st->id, st->cnt, st->use_file, + (long) tv.tv_sec, (long) tv.tv_usec); + break; + default: + /* internal error which should never occur */ + fprintf(stderr, "unexpected error status: %d\n", + st->estatus); + exit(1); + } + } + else + fprintf(logfile, "%d " INT64_FORMAT " failed %d %ld %ld", + st->id, st->cnt, st->use_file, + (long) tv.tv_sec, (long) tv.tv_usec); + if (throttle_delay) fprintf(logfile, " %.0f", lag); + if (max_tries != 1) + fprintf(logfile, " %d", st->retries); fputc('\n', logfile); } } @@ -3465,7 +4277,8 @@ doLog(TState *thread, CState *st, * Accumulate and report statistics at end of a transaction. * * (This is also called when a transaction is late and thus skipped. - * Note that even skipped transactions are counted in the "cnt" fields.) + * Note that even skipped and failed transactions are counted in the CState + * "cnt" field.) */ static void processXactStats(TState *thread, CState *st, instr_time *now, @@ -3473,10 +4286,10 @@ processXactStats(TState *thread, CState *st, instr_time *now, { double latency = 0.0, lag = 0.0; - bool thread_details = progress || throttle_delay || latency_limit, - detailed = thread_details || use_log || per_script_stats; + bool detailed = progress || throttle_delay || latency_limit || + use_log || per_script_stats; - if (detailed && !skipped) + if (detailed && !skipped && st->estatus == ESTATUS_NO_ERROR) { if (INSTR_TIME_IS_ZERO(*now)) INSTR_TIME_SET_CURRENT(*now); @@ -3486,20 +4299,12 @@ processXactStats(TState *thread, CState *st, instr_time *now, lag = INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled; } - if (thread_details) - { - /* keep detailed thread stats */ - accumStats(&thread->stats, skipped, latency, lag); + /* keep detailed thread stats */ + accumStats(&thread->stats, skipped, latency, lag, st->estatus, st->retries); - /* count transactions over the latency limit, if needed */ - if (latency_limit && latency > latency_limit) - thread->latency_late++; - } - else - { - /* no detailed stats, just count */ - thread->stats.cnt++; - } + /* count transactions over the latency limit, if needed */ + if (latency_limit && latency > latency_limit) + thread->latency_late++; /* client stat is just counting */ st->cnt++; @@ -3509,7 +4314,8 @@ processXactStats(TState *thread, CState *st, instr_time *now, /* 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, latency, lag, + st->estatus, st->retries); } @@ -4644,15 +5450,16 @@ printResults(TState *threads, StatsData *total, instr_time total_time, double time_include, tps_include, tps_exclude; - int64 ntx = total->cnt - total->skipped; + int64 failures = getFailures(total); + int64 total_cnt = total->cnt + total->skipped + failures; int i, totalCacheOverflows = 0; time_include = INSTR_TIME_GET_DOUBLE(total_time); /* tps is about actually executed transactions */ - tps_include = ntx / time_include; - tps_exclude = ntx / + tps_include = total->cnt / time_include; + tps_exclude = total->cnt / (time_include - (INSTR_TIME_GET_DOUBLE(conn_total_time) / nclients)); /* Report test parameters. */ @@ -4666,14 +5473,55 @@ printResults(TState *threads, StatsData *total, instr_time total_time, { printf("number of transactions per client: %d\n", nxacts); printf("number of transactions actually processed: " INT64_FORMAT "/%d\n", - ntx, nxacts * nclients); + total->cnt, nxacts * nclients); } else { printf("duration: %d s\n", duration); printf("number of transactions actually processed: " INT64_FORMAT "\n", - ntx); + total->cnt); + } + + if (failures > 0) + { + printf("number of failures: " INT64_FORMAT " (%.3f%%)\n", + failures, 100.0 * failures / total_cnt); + + if (failures_detailed) + { + /* SQL failures */ + if (total->serialization_failures || total->other_sql_failures) + printf("number of serialization failures: " INT64_FORMAT " (%.3f%%)\n", + total->serialization_failures, + 100.0 * total->serialization_failures / total_cnt); + if (total->deadlock_failures || total->other_sql_failures) + printf("number of deadlock failures: " INT64_FORMAT " (%.3f%%)\n", + total->deadlock_failures, + 100.0 * total->deadlock_failures / total_cnt); + if (total->other_sql_failures) + printf("number of other SQL failures: " INT64_FORMAT " (%.3f%%)\n", + total->other_sql_failures, + 100.0 * total->other_sql_failures / total_cnt); + + /* meta command failures */ + if (total->meta_command_failures > 0) + printf("number of meta-command failures: " INT64_FORMAT " (%.3f%%)\n", + total->meta_command_failures, + 100.0 * total->meta_command_failures / total_cnt); + } + } + + /* it can be non-zero only if max_tries is not equal to one */ + if (total->retried > 0) + { + printf("number of retried: " INT64_FORMAT " (%.3f%%)\n", + total->retried, 100.0 * total->retried / total_cnt); + printf("number of retries: " INT64_FORMAT "\n", total->retries); } + + if (max_tries) + printf("maximum number of tries: %d\n", max_tries); + /* Report zipfian cache overflow */ for (i = 0; i < nthreads; i++) { @@ -4685,26 +5533,27 @@ printResults(TState *threads, StatsData *total, instr_time total_time, } /* Remaining stats are nonsensical if we failed to execute any xacts */ - if (total->cnt <= 0) + if (total->cnt + total->skipped <= 0) return; if (throttle_delay && latency_limit) printf("number of transactions skipped: " INT64_FORMAT " (%.3f %%)\n", total->skipped, - 100.0 * total->skipped / total->cnt); + 100.0 * total->skipped / total_cnt); if (latency_limit) printf("number of transactions above the %.1f ms latency limit: " INT64_FORMAT "/" INT64_FORMAT " (%.3f %%)\n", - latency_limit / 1000.0, latency_late, ntx, - (ntx > 0) ? 100.0 * latency_late / ntx : 0.0); + latency_limit / 1000.0, latency_late, total->cnt, + (total->cnt > 0) ? 100.0 * latency_late / total->cnt : 0.0); if (throttle_delay || progress || latency_limit) printSimpleStats("latency", &total->latency); else { /* no measurement, show average latency computed from run time */ - printf("latency average = %.3f ms\n", - 1000.0 * time_include * nclients / total->cnt); + printf("latency average = %.3f ms%s\n", + 1000.0 * time_include * nclients / total_cnt, + failures > 0 ? " (including failures)" : ""); } if (throttle_delay) @@ -4723,7 +5572,7 @@ printResults(TState *threads, StatsData *total, instr_time total_time, printf("tps = %f (excluding connections establishing)\n", tps_exclude); /* Report per-script/command statistics */ - if (per_script_stats || is_latencies) + if (per_script_stats || report_per_command) { int i; @@ -4732,6 +5581,9 @@ printResults(TState *threads, StatsData *total, instr_time total_time, if (per_script_stats) { StatsData *sstats = &sql_script[i].stats; + int64 script_failures = getFailures(sstats); + int64 script_total_cnt = + sstats->cnt + sstats->skipped + script_failures; printf("SQL script %d: %s\n" " - weight: %d (targets %.1f%% of total)\n" @@ -4741,25 +5593,75 @@ printResults(TState *threads, StatsData *total, instr_time total_time, 100.0 * sql_script[i].weight / total_weight, sstats->cnt, 100.0 * sstats->cnt / total->cnt, - (sstats->cnt - sstats->skipped) / time_include); + sstats->cnt / time_include); + + if (failures > 0) + { + printf(" - number of failures: " INT64_FORMAT " (%.3f%%)\n", + script_failures, + 100.0 * script_failures / script_total_cnt); + + if (failures_detailed) + { + /* SQL failures */ + if (total->serialization_failures || + total->other_sql_failures) + printf(" - number of serialization failures: " INT64_FORMAT " (%.3f%%)\n", + sstats->serialization_failures, + (100.0 * sstats->serialization_failures / + script_total_cnt)); + if (total->deadlock_failures || + total->other_sql_failures) + printf(" - number of deadlock failures: " INT64_FORMAT " (%.3f%%)\n", + sstats->deadlock_failures, + (100.0 * sstats->deadlock_failures / + script_total_cnt)); + if (total->other_sql_failures) + printf(" - number of other SQL failures: " INT64_FORMAT " (%.3f%%)\n", + sstats->other_sql_failures, + (100.0 * sstats->other_sql_failures / + script_total_cnt)); + + /* meta command failures */ + if (total->meta_command_failures > 0) + printf(" - number of meta-command failures: " INT64_FORMAT " (%.3f%%)\n", + sstats->meta_command_failures, + (100.0 * sstats->meta_command_failures / + script_total_cnt)); + } + } + + /* it can be non-zero only if max_tries is not equal to one */ + if (total->retried > 0) + { + printf(" - number of retried: " INT64_FORMAT " (%.3f%%)\n", + sstats->retried, + 100.0 * sstats->retried / script_total_cnt); + printf(" - number of retries: " INT64_FORMAT "\n", + sstats->retries); + } - if (throttle_delay && latency_limit && sstats->cnt > 0) + if (throttle_delay && latency_limit && script_total_cnt > 0) printf(" - number of transactions skipped: " INT64_FORMAT " (%.3f%%)\n", sstats->skipped, - 100.0 * sstats->skipped / sstats->cnt); + 100.0 * sstats->skipped / script_total_cnt); printSimpleStats(" - latency", &sstats->latency); } - /* Report per-command latencies */ - if (is_latencies) + /* + * Report per-command statistics: latencies, retries after errors, + * failures (errors without retrying). + */ + if (report_per_command) { Command **commands; - if (per_script_stats) - printf(" - statement latencies in milliseconds:\n"); - else - printf("statement latencies in milliseconds:\n"); + printf("%sstatement latencies in milliseconds%s:\n", + per_script_stats ? " - " : "", + (max_tries == 1 ? + " and failures" : + ", failures and retries")); for (commands = sql_script[i].commands; *commands != NULL; @@ -4767,10 +5669,19 @@ printResults(TState *threads, StatsData *total, instr_time total_time, { SimpleStats *cstats = &(*commands)->stats; - printf(" %11.3f %s\n", - (cstats->count > 0) ? - 1000.0 * cstats->sum / cstats->count : 0.0, - (*commands)->line); + if (max_tries == 1) + printf(" %11.3f %10" INT64_MODIFIER "d %s\n", + (cstats->count > 0) ? + 1000.0 * cstats->sum / cstats->count : 0.0, + (*commands)->failures, + (*commands)->line); + else + printf(" %11.3f %10" INT64_MODIFIER "d %10" INT64_MODIFIER "d %s\n", + (cstats->count > 0) ? + 1000.0 * cstats->sum / cstats->count : 0.0, + (*commands)->failures, + (*commands)->retries, + (*commands)->line); } } } @@ -4862,7 +5773,7 @@ main(int argc, char **argv) {"progress", required_argument, NULL, 'P'}, {"protocol", required_argument, NULL, 'M'}, {"quiet", no_argument, NULL, 'q'}, - {"report-latencies", no_argument, NULL, 'r'}, + {"report-per-command", no_argument, NULL, 'r'}, {"rate", required_argument, NULL, 'R'}, {"scale", required_argument, NULL, 's'}, {"select-only", no_argument, NULL, 'S'}, @@ -4881,6 +5792,9 @@ main(int argc, char **argv) {"log-prefix", required_argument, NULL, 7}, {"foreign-keys", no_argument, NULL, 8}, {"random-seed", required_argument, NULL, 9}, + {"failures-detailed", no_argument, NULL, 10}, + {"max-tries", required_argument, NULL, 11}, + {"print-errors", no_argument, NULL, 12}, {NULL, 0, NULL, 0} }; @@ -4917,6 +5831,7 @@ main(int argc, char **argv) PGconn *con; PGresult *res; char *env; + bool retry = false; /* retry transactions with errors or not */ progname = get_progname(argv[0]); @@ -4986,7 +5901,7 @@ main(int argc, char **argv) pgport = pg_strdup(optarg); break; case 'd': - debug++; + debug_level = DEBUG_ALL; break; case 'c': benchmarking_option_set = true; @@ -5039,7 +5954,7 @@ main(int argc, char **argv) break; case 'r': benchmarking_option_set = true; - is_latencies = true; + report_per_command = true; break; case 's': scale_given = true; @@ -5236,6 +6151,40 @@ main(int argc, char **argv) exit(1); } break; + case 10: /* failures-detailed */ + benchmarking_option_set = true; + failures_detailed = true; + break; + case 11: /* max-tries */ + { + int32 max_tries_arg = atoi(optarg); + + if (max_tries_arg < 0) + { + fprintf(stderr, + "invalid number of maximum tries: \"%s\"\n", + optarg); + exit(1); + } + + benchmarking_option_set = true; + + /* + * Always retry transactions with errors if this option is + * used. But if its value is 0, use the option + * --latency-limit to limit the number of tries. + */ + retry = true; + + max_tries = (uint32) max_tries_arg; + } + break; + case 12: /* print-errors */ + benchmarking_option_set = true; + /* do not conflict with the option --debug */ + if (debug_level < DEBUG_ERRORS) + debug_level = DEBUG_ERRORS; + break; default: fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname); exit(1); @@ -5405,6 +6354,20 @@ main(int argc, char **argv) exit(1); } + if (!max_tries) + { + if (retry && !latency_limit) + { + fprintf(stderr, "an infinite number of transaction tries can only be used with the option --latency-limit\n"); + exit(1); + } + else if (!retry) + { + /* By default transactions with errors are not retried */ + max_tries = 1; + } + } + /* * save main process id in the global variable because process id will be * changed after fork. @@ -5430,7 +6393,12 @@ main(int argc, char **argv) { if (!putVariableValue(&state[i].variables, "startup", var->name, &var->value)) + { + fprintf(stderr, + "error when setting the startup variable \"%s\" for client %d\n", + var->name, i); exit(1); + } } else { @@ -5449,7 +6417,7 @@ main(int argc, char **argv) initRandomState(&state[i].random_state); } - if (debug) + if (debug_level >= DEBUG_ALL) { if (duration <= 0) printf("pghost: %s pgport: %s nclients: %d nxacts: %d dbName: %s\n", @@ -5515,7 +6483,12 @@ main(int argc, char **argv) for (i = 0; i < nclients; i++) { if (!putVariableInt(&state[i].variables, "startup", "scale", scale)) + { + fprintf(stderr, + "error when setting the startup variable \"scale\" for client %d\n", + i); exit(1); + } } } @@ -5527,7 +6500,12 @@ main(int argc, char **argv) { for (i = 0; i < nclients; i++) if (!putVariableInt(&state[i].variables, "startup", "client_id", i)) + { + fprintf(stderr, + "error when setting the startup variable \"client_id\" for client %d\n", + i); exit(1); + } } /* set default seed for hash functions */ @@ -5541,7 +6519,12 @@ main(int argc, char **argv) for (i = 0; i < nclients; i++) if (!putVariableInt(&state[i].variables, "startup", "default_seed", (int64) seed)) + { + fprintf(stderr, + "error when setting the startup variable \"default_seed\" for client %d\n", + i); exit(1); + } } /* set random seed unless overwritten */ @@ -5550,7 +6533,12 @@ main(int argc, char **argv) for (i = 0; i < nclients; i++) if (!putVariableInt(&state[i].variables, "startup", "random_seed", random_seed)) + { + fprintf(stderr, + "error when setting the startup variable \"random_seed\" for client %d\n", + i); exit(1); + } } if (!is_no_vacuum) @@ -5666,6 +6654,12 @@ main(int argc, char **argv) mergeSimpleStats(&stats.lag, &thread->stats.lag); stats.cnt += thread->stats.cnt; stats.skipped += thread->stats.skipped; + stats.retries += thread->stats.retries; + stats.retried += thread->stats.retried; + stats.serialization_failures += thread->stats.serialization_failures; + stats.deadlock_failures += thread->stats.deadlock_failures; + stats.other_sql_failures += thread->stats.other_sql_failures; + stats.meta_command_failures += thread->stats.meta_command_failures; latency_late += thread->latency_late; INSTR_TIME_ADD(conn_total_time, thread->conn_time); } @@ -5804,7 +6798,8 @@ threadRun(void *arg) if (min_usec > this_usec) min_usec = this_usec; } - else if (st->state == CSTATE_WAIT_RESULT) + else if (st->state == CSTATE_WAIT_RESULT || + st->state == CSTATE_WAIT_ROLLBACK_RESULT) { /* * waiting for result from server - nothing to do unless the @@ -5908,7 +6903,8 @@ threadRun(void *arg) { CState *st = &state[i]; - if (st->state == CSTATE_WAIT_RESULT) + if (st->state == CSTATE_WAIT_RESULT || + st->state == CSTATE_WAIT_ROLLBACK_RESULT) { /* don't call doCustom unless data is available */ int sock = PQsocket(st->con); @@ -5950,7 +6946,9 @@ threadRun(void *arg) /* generate and show report */ StatsData cur; int64 run = now - last_report, - ntx; + cnt, + failures, + retried; double tps, total_run, latency, @@ -5977,23 +6975,34 @@ threadRun(void *arg) mergeSimpleStats(&cur.lag, &thread[i].stats.lag); cur.cnt += thread[i].stats.cnt; cur.skipped += thread[i].stats.skipped; + cur.retries += thread[i].stats.retries; + cur.retried += thread[i].stats.retried; + cur.serialization_failures += + thread[i].stats.serialization_failures; + cur.deadlock_failures += thread[i].stats.deadlock_failures; + cur.other_sql_failures += + thread[i].stats.other_sql_failures; + cur.meta_command_failures += + thread[i].stats.meta_command_failures; } /* we count only actually executed transactions */ - ntx = (cur.cnt - cur.skipped) - (last.cnt - last.skipped); + cnt = cur.cnt - last.cnt; total_run = (now - thread_start) / 1000000.0; - tps = 1000000.0 * ntx / run; - if (ntx > 0) + tps = 1000000.0 * cnt / run; + if (cnt > 0) { - latency = 0.001 * (cur.latency.sum - last.latency.sum) / ntx; - sqlat = 1.0 * (cur.latency.sum2 - last.latency.sum2) / ntx; + latency = 0.001 * (cur.latency.sum - last.latency.sum) / cnt; + sqlat = 1.0 * (cur.latency.sum2 - last.latency.sum2) / cnt; stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency); - lag = 0.001 * (cur.lag.sum - last.lag.sum) / ntx; + lag = 0.001 * (cur.lag.sum - last.lag.sum) / cnt; } else { latency = sqlat = stdev = lag = 0; } + failures = getFailures(&cur) - getFailures(&last); + retried = cur.retried - last.retried; if (progress_timestamp) { @@ -6019,6 +7028,9 @@ threadRun(void *arg) "progress: %s, %.1f tps, lat %.3f ms stddev %.3f", tbuf, tps, latency, stdev); + if (failures > 0) + fprintf(stderr, ", " INT64_FORMAT " failed", failures); + if (throttle_delay) { fprintf(stderr, ", lag %.3f ms", lag); @@ -6026,6 +7038,12 @@ threadRun(void *arg) fprintf(stderr, ", " INT64_FORMAT " skipped", cur.skipped - last.skipped); } + + /* it can be non-zero only if max_tries is not equal to one */ + if (retried > 0) + fprintf(stderr, + ", " INT64_FORMAT " retried, " INT64_FORMAT " retries", + retried, cur.retries - last.retries); fprintf(stderr, "\n"); last = cur; diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl index 2fc021dde7..033e66996e 100644 --- a/src/bin/pgbench/t/001_pgbench_with_server.pl +++ b/src/bin/pgbench/t/001_pgbench_with_server.pl @@ -5,9 +5,20 @@ use PostgresNode; use TestLib; use Test::More; +use constant +{ + SQL_ERROR => 0, + META_COMMAND_ERROR => 1, + SYNTAX_ERROR => 2, +}; + # start a pgbench specific server my $node = get_new_node('main'); -$node->init; + +# Set to untranslated messages, to be able to compare program output with +# expected strings. +$node->init(extra => [ '--locale', 'C' ]); + $node->start; # invoke pgbench @@ -136,7 +147,8 @@ pgbench( qr{builtin: TPC-B}, qr{clients: 2\b}, qr{processed: 10/10}, - qr{mode: simple} + qr{mode: simple}, + qr{maximum number of tries: 1} ], [qr{^$}], 'pgbench tpcb-like'); @@ -530,11 +542,12 @@ pgbench( # trigger many expression errors my @errors = ( - # [ test name, expected status, expected stderr, script ] + # [ test name, expected status, error type, expected stderr, script ] # SQL [ 'sql syntax error', 0, + SQL_ERROR, [ qr{ERROR: syntax error}, qr{prepared statement .* does not exist} @@ -544,28 +557,36 @@ my @errors = ( } ], [ - 'sql too many args', 1, [qr{statement has too many arguments.*\b9\b}], + 'sql too many args', 1, SYNTAX_ERROR, + [qr{statement has too many arguments.*\b9\b}], q{-- MAX_ARGS=10 for prepared \set i 0 SELECT LEAST(:i, :i, :i, :i, :i, :i, :i, :i, :i, :i, :i); +} + ], + [ 'sql division by zero', 0, SQL_ERROR, [qr{ERROR: division by zero}], + q{-- SQL division by zero +SELECT 1 / 0; } ], # SHELL [ - 'shell bad command', 0, + 'shell bad command', 0, META_COMMAND_ERROR, [qr{\(shell\) .* meta-command failed}], q{\shell no-such-command} ], [ - 'shell undefined variable', 0, + 'shell undefined variable', 0, META_COMMAND_ERROR, [qr{undefined variable ":nosuchvariable"}], q{-- undefined variable in shell \shell echo ::foo :nosuchvariable } ], - [ 'shell missing command', 1, [qr{missing command }], q{\shell} ], + [ 'shell missing command', 1, SYNTAX_ERROR, [qr{missing command }], + q{\shell} ], [ - 'shell too many args', 1, [qr{too many arguments in command "shell"}], + 'shell too many args', 1, SYNTAX_ERROR, + [qr{too many arguments in command "shell"}], q{-- 257 arguments to \shell \shell echo \ 0 1 2 3 4 5 6 7 8 9 A B C D E F \ @@ -589,162 +610,232 @@ SELECT LEAST(:i, :i, :i, :i, :i, :i, :i, :i, :i, :i, :i); # SET [ - 'set syntax error', 1, + 'set syntax error', 1, SYNTAX_ERROR, [qr{syntax error in command "set"}], q{\set i 1 +} ], [ - 'set no such function', 1, + 'set no such function', 1, SYNTAX_ERROR, [qr{unexpected function name}], q{\set i noSuchFunction()} ], [ - 'set invalid variable name', 0, + 'set invalid variable name', 0, META_COMMAND_ERROR, [qr{invalid variable name}], q{\set . 1} ], [ - 'set int overflow', 0, + 'set int overflow', 0, META_COMMAND_ERROR, [qr{double to int overflow for 100}], q{\set i int(1E32)} ], - [ 'set division by zero', 0, [qr{division by zero}], q{\set i 1/0} ], [ - 'set bigint out of range', 0, + 'set division by zero', 0, META_COMMAND_ERROR, + [qr{division by zero}], q{\set i 1/0} + ], + [ + 'set bigint out of range', 0, META_COMMAND_ERROR, [qr{bigint out of range}], q{\set i 9223372036854775808 / -1} ], [ 'set undefined variable', 0, + META_COMMAND_ERROR, [qr{undefined variable "nosuchvariable"}], q{\set i :nosuchvariable} ], - [ 'set unexpected char', 1, [qr{unexpected character .;.}], q{\set i ;} ], + [ + 'set unexpected char', 1, SYNTAX_ERROR, + [qr{unexpected character .;.}], q{\set i ;} + ], [ 'set too many args', 0, + META_COMMAND_ERROR, [qr{too many function arguments}], q{\set i least(0,1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16)} ], [ - 'set empty random range', 0, + 'set empty random range', 0, META_COMMAND_ERROR, [qr{empty range given to random}], q{\set i random(5,3)} ], [ 'set random range too large', 0, + META_COMMAND_ERROR, [qr{random range is too large}], q{\set i random(-9223372036854775808, 9223372036854775807)} ], [ 'set gaussian param too small', 0, + META_COMMAND_ERROR, [qr{gaussian param.* at least 2}], q{\set i random_gaussian(0, 10, 1.0)} ], [ 'set exponential param greater 0', 0, + META_COMMAND_ERROR, [qr{exponential parameter must be greater }], q{\set i random_exponential(0, 10, 0.0)} ], [ 'set zipfian param to 1', 0, + META_COMMAND_ERROR, [qr{zipfian parameter must be in range \(0, 1\) U \(1, \d+\]}], q{\set i random_zipfian(0, 10, 1)} ], [ 'set zipfian param too large', 0, + META_COMMAND_ERROR, [qr{zipfian parameter must be in range \(0, 1\) U \(1, \d+\]}], q{\set i random_zipfian(0, 10, 1000000)} ], [ - 'set non numeric value', 0, + 'set non numeric value', 0, META_COMMAND_ERROR, [qr{malformed variable "foo" value: "bla"}], q{\set i :foo + 1} ], - [ 'set no expression', 1, [qr{syntax error}], q{\set i} ], - [ 'set missing argument', 1, [qr{missing argument}i], q{\set} ], + [ 'set no expression', 1, SYNTAX_ERROR, [qr{syntax error}], q{\set i} ], + [ + 'set missing argument', 1, SYNTAX_ERROR, + [qr{missing argument}i], q{\set} + ], [ - 'set not a bool', 0, + 'set not a bool', 0, META_COMMAND_ERROR, [qr{cannot coerce double to boolean}], q{\set b NOT 0.0} ], [ - 'set not an int', 0, + 'set not an int', 0, META_COMMAND_ERROR, [qr{cannot coerce boolean to int}], q{\set i TRUE + 2} ], [ - 'set not a double', 0, + 'set not a double', 0, META_COMMAND_ERROR, [qr{cannot coerce boolean to double}], q{\set d ln(TRUE)} ], [ 'set case error', 1, + SYNTAX_ERROR, [qr{syntax error in command "set"}], q{\set i CASE TRUE THEN 1 ELSE 0 END} ], [ - 'set random error', 0, + 'set random error', 0, META_COMMAND_ERROR, [qr{cannot coerce boolean to int}], q{\set b random(FALSE, TRUE)} ], [ - 'set number of args mismatch', 1, + 'set number of args mismatch', 1, SYNTAX_ERROR, [qr{unexpected number of arguments}], q{\set d ln(1.0, 2.0))} ], [ - 'set at least one arg', 1, + 'set at least one arg', 1, SYNTAX_ERROR, [qr{at least one argument expected}], q{\set i greatest())} ], # SETSHELL [ - 'setshell not an int', 0, + 'setshell not an int', 0, META_COMMAND_ERROR, [qr{command must return an integer}], q{\setshell i echo -n one} ], - [ 'setshell missing arg', 1, [qr{missing argument }], q{\setshell var} ], [ - 'setshell no such command', 0, + 'setshell missing arg', 1, SYNTAX_ERROR, + [qr{missing argument }], q{\setshell var} + ], + [ + 'setshell no such command', 0, META_COMMAND_ERROR, [qr{could not read result }], q{\setshell var no-such-command} ], # SLEEP [ - 'sleep undefined variable', 0, + 'sleep undefined variable', 0, META_COMMAND_ERROR, [qr{sleep: undefined variable}], q{\sleep :nosuchvariable} ], [ - 'sleep too many args', 1, + 'sleep too many args', 1, SYNTAX_ERROR, [qr{too many arguments}], q{\sleep too many args} ], [ - 'sleep missing arg', 1, + 'sleep missing arg', 1, SYNTAX_ERROR, [ qr{missing argument}, qr{\\sleep} ], q{\sleep} ], [ - 'sleep unknown unit', 1, + 'sleep unknown unit', 1, SYNTAX_ERROR, [qr{unrecognized time unit}], q{\sleep 1 week} ], + # CONDITIONAL BLOCKS + [ 'error inside a conditional block', 0, SQL_ERROR, + [qr{ERROR: division by zero}], + q{-- error inside a conditional block +\if true +SELECT 1 / 0; +\endif +} + ], + # MISC [ - 'misc invalid backslash command', 1, + 'misc invalid backslash command', 1, SYNTAX_ERROR, [qr{invalid command .* "nosuchcommand"}], q{\nosuchcommand} ], - [ 'misc empty script', 1, [qr{empty command list for script}], q{} ], [ - 'bad boolean', 0, + 'misc empty script', 1, SYNTAX_ERROR, + [qr{empty command list for script}], q{} + ], + [ + 'bad boolean', 0, META_COMMAND_ERROR, [qr{malformed variable.*trueXXX}], q{\set b :badtrue or true} ],); for my $e (@errors) { - my ($name, $status, $re, $script) = @$e; + my ($name, $status, $error_type, $re, $script) = @$e; my $n = '001_pgbench_error_' . $name; $n =~ s/ /_/g; + my $test_name = 'pgbench script error: ' . $name; + my $stdout_re; + + if ($status) + { + # only syntax errors get non-zero exit status + # internal error which should never occur + die $test_name . ": unexpected error type: " . $error_type . "\n" + if ($error_type != SYNTAX_ERROR); + + $stdout_re = [ qr{^$} ]; + } + else + { + $stdout_re = + [ qr{processed: 0/1}, qr{number of failures: 1 \(100.000%\)}, + qr{^((?!number of retried)(.|\n))*$} ]; + + if ($error_type == SQL_ERROR) + { + push @$stdout_re, + qr{number of serialization failures: 0 \(0.000%\)}, + qr{number of deadlock failures: 0 \(0.000%\)}, + qr{number of other SQL failures: 1 \(100.000%\)}; + } + elsif ($error_type == META_COMMAND_ERROR) + { + push @$stdout_re, + qr{number of meta-command failures: 1 \(100.000%\)}; + } + else + { + # internal error which should never occur + die $test_name . ": unexpected error type: " . $error_type . "\n"; + } + } + pgbench( - '-n -t 1 -Dfoo=bla -Dnull=null -Dtrue=true -Done=1 -Dzero=0.0 -Dbadtrue=trueXXX -M prepared', + '-n -t 1 -Dfoo=bla -Dnull=null -Dtrue=true -Done=1 -Dzero=0.0 -Dbadtrue=trueXXX -M prepared --failures-detailed --print-errors', $status, - [ $status ? qr{^$} : qr{processed: 0/1} ], + $stdout_re, $re, - 'pgbench script error: ' . $name, + $test_name, { $n => $script }); } @@ -848,6 +939,245 @@ pgbench( check_pgbench_logs("$bdir/001_pgbench_log_3", 1, 10, 10, qr{^\d \d{1,2} \d+ \d \d+ \d+$}); +# abortion of the client if the script contains an incomplete transaction block +pgbench( + '--no-vacuum', 0, [ qr{processed: 1/10} ], + [ qr{client 0 aborted: end of script reached without completing the last transaction} ], + 'incomplete transaction block', + { '001_pgbench_incomplete_transaction_block' => q{BEGIN;SELECT 1;} }); + +# Rollback of transaction block in case of meta command failure. +# +# If the rollback is not performed, we either continue the current transaction +# block or we terminate it successfully. In the first case we get an abortion of +# the client (we reached the end of the script with an incomplete transaction +# block). In the second case we run the second transaction and get a failure in +# the SQL command (the previous transaction was successful and inserting the +# same value will get a unique violation error). + +$node->safe_psql('postgres', + 'CREATE UNLOGGED TABLE x_unique (x integer UNIQUE);'); + +pgbench( + '--no-vacuum -t 2 --failures-detailed', 0, + [ + qr{processed: 0/2}, + qr{number of meta-command failures: 2 \(100.000%\)} + ], + [qr{^$}], + 'rollback of transaction block in case of meta command failure', + { '001_pgbench_rollback_of_transaction_block_in_case_of_meta_command_failure' => q{ +BEGIN; +INSERT INTO x_unique VALUES (1); +\set i 1/0 +END; +} + }); + +# clean up +$node->safe_psql('postgres', 'DROP TABLE x_unique'); + +# Test the concurrent update in the table row and deadlocks. + +$node->safe_psql('postgres', + 'CREATE UNLOGGED TABLE first_client_table (value integer); ' + . 'CREATE UNLOGGED TABLE xy (x integer, y integer); ' + . 'INSERT INTO xy VALUES (1, 2);'); + +# Serialization error and retry + +local $ENV{PGOPTIONS} = "-c default_transaction_isolation=repeatable\\ read"; + +# Check that we have a serialization error and the same random value of the +# delta variable in the next try +my $err_pattern = + "(client (0|1) sending UPDATE xy SET y = y \\+ -?\\d+\\b).*" + . "client \\g2 got an error in command 3 \\(SQL\\) of script 0; " + . "ERROR: could not serialize access due to concurrent update\\b.*" + . "\\g1"; + +pgbench( + "-n -c 2 -t 1 -d --max-tries 2", + 0, + [ qr{processed: 2/2\b}, qr{^((?!number of failures)(.|\n))*$}, + qr{number of retried: 1\b}, qr{number of retries: 1\b} ], + [ qr/$err_pattern/s ], + 'concurrent update with retrying', + { + '001_pgbench_serialization' => q{ +-- What's happening: +-- The first client starts the transaction with the isolation level Repeatable +-- Read: +-- +-- BEGIN; +-- UPDATE xy SET y = ... WHERE x = 1; +-- +-- The second client starts a similar transaction with the same isolation level: +-- +-- BEGIN; +-- UPDATE xy SET y = ... WHERE x = 1; +-- +-- +-- The first client commits its transaction, and the second client gets a +-- serialization error. + +\set delta random(-5000, 5000) + +-- The second client will stop here +SELECT pg_advisory_lock(0); + +-- Start transaction with concurrent update +BEGIN; +UPDATE xy SET y = y + :delta WHERE x = 1 AND pg_advisory_lock(1) IS NOT NULL; + +-- Wait for the second client +DO $$ +DECLARE + exists boolean; + waiters integer; +BEGIN + -- The second client always comes in second, and the number of rows in the + -- table first_client_table reflect this. Here the first client inserts a row, + -- so the second client will see a non-empty table when repeating the + -- transaction after the serialization error. + SELECT EXISTS (SELECT * FROM first_client_table) INTO STRICT exists; + IF NOT exists THEN + -- Let the second client begin + PERFORM pg_advisory_unlock(0); + -- And wait until the second client tries to get the same lock + LOOP + SELECT COUNT(*) INTO STRICT waiters FROM pg_locks WHERE + locktype = 'advisory' AND objsubid = 1 AND + ((classid::bigint << 32) | objid::bigint = 1::bigint) AND NOT granted; + IF waiters = 1 THEN + INSERT INTO first_client_table VALUES (1); + + -- Exit loop + EXIT; + END IF; + END LOOP; + END IF; +END$$; + +COMMIT; +SELECT pg_advisory_unlock_all(); +} + }); + +# Clean up + +$node->safe_psql('postgres', 'DELETE FROM first_client_table;'); + +local $ENV{PGOPTIONS} = "-c default_transaction_isolation=read\\ committed"; + +# Deadlock error and retry + +# Check that we have a deadlock error +$err_pattern = + "client (0|1) got an error in command (3|5) \\(SQL\\) of script 0; " + . "ERROR: deadlock detected\\b"; + +pgbench( + "-n -c 2 -t 1 --max-tries 2 --print-errors", + 0, + [ qr{processed: 2/2\b}, qr{^((?!number of failures)(.|\n))*$}, + qr{number of retried: 1\b}, qr{number of retries: 1\b} ], + [ qr{$err_pattern} ], + 'deadlock with retrying', + { + '001_pgbench_deadlock' => q{ +-- What's happening: +-- The first client gets the lock 2. +-- The second client gets the lock 3 and tries to get the lock 2. +-- The first client tries to get the lock 3 and one of them gets a deadlock +-- error. +-- +-- A client that does not get a deadlock error must hold a lock at the +-- transaction start. Thus in the end it releases all of its locks before the +-- client with the deadlock error starts a retry (we do not want any errors +-- again). + +-- Since the client with the deadlock error has not released the blocking locks, +-- let's do this here. +SELECT pg_advisory_unlock_all(); + +-- The second client and the client with the deadlock error stop here +SELECT pg_advisory_lock(0); +SELECT pg_advisory_lock(1); + +-- The second client and the client with the deadlock error always come after +-- the first and the number of rows in the table first_client_table reflects +-- this. Here the first client inserts a row, so in the future the table is +-- always non-empty. +DO $$ +DECLARE + exists boolean; +BEGIN + SELECT EXISTS (SELECT * FROM first_client_table) INTO STRICT exists; + IF exists THEN + -- We are the second client or the client with the deadlock error + + -- The first client will take care by itself of this lock (see below) + PERFORM pg_advisory_unlock(0); + + PERFORM pg_advisory_lock(3); + + -- The second client can get a deadlock here + PERFORM pg_advisory_lock(2); + ELSE + -- We are the first client + + -- This code should not be used in a new transaction after an error + INSERT INTO first_client_table VALUES (1); + + PERFORM pg_advisory_lock(2); + END IF; +END$$; + +DO $$ +DECLARE + num_rows integer; + waiters integer; +BEGIN + -- Check if we are the first client + SELECT COUNT(*) FROM first_client_table INTO STRICT num_rows; + IF num_rows = 1 THEN + -- This code should not be used in a new transaction after an error + INSERT INTO first_client_table VALUES (2); + + -- Let the second client begin + PERFORM pg_advisory_unlock(0); + PERFORM pg_advisory_unlock(1); + + -- Make sure the second client is ready for deadlock + LOOP + SELECT COUNT(*) INTO STRICT waiters FROM pg_locks WHERE + locktype = 'advisory' AND + objsubid = 1 AND + ((classid::bigint << 32) | objid::bigint = 2::bigint) AND + NOT granted; + + IF waiters = 1 THEN + -- Exit loop + EXIT; + END IF; + END LOOP; + + PERFORM pg_advisory_lock(0); + -- And the second client took care by itself of the lock 1 + END IF; +END$$; + +-- The first client can get a deadlock here +SELECT pg_advisory_lock(3); + +SELECT pg_advisory_unlock_all(); +} + }); + +# Clean up +$node->safe_psql('postgres', 'DROP TABLE first_client_table, xy;'); + # done $node->stop; done_testing(); diff --git a/src/bin/pgbench/t/002_pgbench_no_server.pl b/src/bin/pgbench/t/002_pgbench_no_server.pl index c1c2c1e3d4..7cca6df57d 100644 --- a/src/bin/pgbench/t/002_pgbench_no_server.pl +++ b/src/bin/pgbench/t/002_pgbench_no_server.pl @@ -157,6 +157,16 @@ my @options = ( qr{error while setting random seed from --random-seed option} ] ], + [ + 'bad maximum number of tries', + '--max-tries -10', + [qr{invalid number of maximum tries: "-10"}] + ], + [ + 'an infinite number of tries', + '--max-tries 0', + [qr{an infinite number of transaction tries can only be used with the option --latency-limit}] + ], # loging sub-options [ diff --git a/src/fe_utils/conditional.c b/src/fe_utils/conditional.c index db2a0a53b3..4d14066024 100644 --- a/src/fe_utils/conditional.c +++ b/src/fe_utils/conditional.c @@ -24,13 +24,25 @@ conditional_stack_create(void) } /* - * destroy stack + * Destroy all the elements from the stack. The stack itself is not freed. */ void -conditional_stack_destroy(ConditionalStack cstack) +conditional_stack_reset(ConditionalStack cstack) { + if (!cstack) + return; /* nothing to do here */ + while (conditional_stack_pop(cstack)) continue; +} + +/* + * destroy stack + */ +void +conditional_stack_destroy(ConditionalStack cstack) +{ + conditional_stack_reset(cstack); free(cstack); } diff --git a/src/include/fe_utils/conditional.h b/src/include/fe_utils/conditional.h index 9b91de5a3d..59c8d8a8e5 100644 --- a/src/include/fe_utils/conditional.h +++ b/src/include/fe_utils/conditional.h @@ -73,6 +73,8 @@ typedef struct ConditionalStackData *ConditionalStack; extern ConditionalStack conditional_stack_create(void); +extern void conditional_stack_reset(ConditionalStack cstack); + extern void conditional_stack_destroy(ConditionalStack cstack); extern int conditional_stack_depth(ConditionalStack cstack); -- 2.17.1