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