From 16827d442448d1935ed644e944a4cb8213345351 Mon Sep 17 00:00:00 2001
From: Tom Lane <tgl@sss.pgh.pa.us>
Date: Tue, 21 Nov 2017 17:30:48 -0500
Subject: [PATCH] pgbench: fix stats reporting when some transactions are
skipped.
pgbench can skip some transactions when both -R and -L options are used.
Previously, this resulted in slightly silly statistics both in progress
reports and final output, because the skipped transactions were counted
as executed for TPS and related stats. Discount skipped xacts in TPS
numbers, and also when figuring the percentage of xacts exceeding the
latency limit.
Also, don't print per-script skipped-transaction counts when there is
only one script. That's redundant with the overall count, and it's
inconsistent with the fact that we don't print other per-script stats
when there's only one script. Clean up some unnecessary interactions
between what should be independent options that were due to that
decision.
While at it, avoid division-by-zero in cases where no transactions were
executed. While on modern platforms this would generally result in
printing "NaN" rather than a crash, that isn't spelled consistently
across platforms and it would confuse many people. Skip the relevant
output entirely when practical, else print zeroes.
Fabien Coelho, reviewed by Steve Singer, additional hacking by me
Discussion: https://postgr.es/m/26654.1505232433@sss.pgh.pa.us
---
doc/src/sgml/ref/pgbench.sgml | 3 +-
src/bin/pgbench/pgbench.c | 104 +++++++++++--------
src/bin/pgbench/t/001_pgbench_with_server.pl | 2 +-
3 files changed, 65 insertions(+), 44 deletions(-)
diff --git a/doc/src/sgml/ref/pgbench.sgml b/doc/src/sgml/ref/pgbench.sgml
index c48a69713ab..f6e93c3ade6 100644
--- a/doc/src/sgml/ref/pgbench.sgml
+++ b/doc/src/sgml/ref/pgbench.sgml
@@ -1363,8 +1363,7 @@ latency average = 15.844 ms
latency stddev = 2.715 ms
tps = 618.764555 (including connections establishing)
tps = 622.977698 (excluding connections establishing)
-script statistics:
- - statement latencies in milliseconds:
+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)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index ceb2fcc3ad6..bd96eae5e6b 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3664,27 +3664,32 @@ addScript(ParsedScript script)
static void
printSimpleStats(const char *prefix, SimpleStats *ss)
{
- /* print NaN if no transactions where executed */
- double latency = ss->sum / ss->count;
- double stddev = sqrt(ss->sum2 / ss->count - latency * latency);
+ if (ss->count > 0)
+ {
+ double latency = ss->sum / ss->count;
+ double stddev = sqrt(ss->sum2 / ss->count - latency * latency);
- printf("%s average = %.3f ms\n", prefix, 0.001 * latency);
- printf("%s stddev = %.3f ms\n", prefix, 0.001 * stddev);
+ printf("%s average = %.3f ms\n", prefix, 0.001 * latency);
+ printf("%s stddev = %.3f ms\n", prefix, 0.001 * stddev);
+ }
}
/* print out results */
static void
printResults(TState *threads, StatsData *total, instr_time total_time,
- instr_time conn_total_time, int latency_late)
+ instr_time conn_total_time, int64 latency_late)
{
double time_include,
tps_include,
tps_exclude;
+ int64 ntx = total->cnt - total->skipped;
time_include = INSTR_TIME_GET_DOUBLE(total_time);
- tps_include = total->cnt / time_include;
- tps_exclude = total->cnt / (time_include -
- (INSTR_TIME_GET_DOUBLE(conn_total_time) / nclients));
+
+ /* tps is about actually executed transactions */
+ tps_include = ntx / time_include;
+ tps_exclude = ntx /
+ (time_include - (INSTR_TIME_GET_DOUBLE(conn_total_time) / nclients));
/* Report test parameters. */
printf("transaction type: %s\n",
@@ -3697,13 +3702,13 @@ 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",
- total->cnt - total->skipped, nxacts * nclients);
+ ntx, nxacts * nclients);
}
else
{
printf("duration: %d s\n", duration);
printf("number of transactions actually processed: " INT64_FORMAT "\n",
- total->cnt);
+ ntx);
}
/* Remaining stats are nonsensical if we failed to execute any xacts */
@@ -3716,9 +3721,9 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
100.0 * total->skipped / total->cnt);
if (latency_limit)
- printf("number of transactions above the %.1f ms latency limit: %d (%.3f %%)\n",
- latency_limit / 1000.0, latency_late,
- 100.0 * latency_late / total->cnt);
+ 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);
if (throttle_delay || progress || latency_limit)
printSimpleStats("latency", &total->latency);
@@ -3745,47 +3750,55 @@ 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 || latency_limit || is_latencies)
+ if (per_script_stats || is_latencies)
{
int i;
for (i = 0; i < num_scripts; i++)
{
- if (num_scripts > 1)
+ if (per_script_stats)
+ {
+ StatsData *sstats = &sql_script[i].stats;
+
printf("SQL script %d: %s\n"
" - weight: %d (targets %.1f%% of total)\n"
" - " INT64_FORMAT " transactions (%.1f%% of total, tps = %f)\n",
i + 1, sql_script[i].desc,
sql_script[i].weight,
100.0 * sql_script[i].weight / total_weight,
- sql_script[i].stats.cnt,
- 100.0 * sql_script[i].stats.cnt / total->cnt,
- sql_script[i].stats.cnt / time_include);
- else
- printf("script statistics:\n");
+ sstats->cnt,
+ 100.0 * sstats->cnt / total->cnt,
+ (sstats->cnt - sstats->skipped) / time_include);
- if (latency_limit)
- printf(" - number of transactions skipped: " INT64_FORMAT " (%.3f%%)\n",
- sql_script[i].stats.skipped,
- 100.0 * sql_script[i].stats.skipped / sql_script[i].stats.cnt);
+ if (throttle_delay && latency_limit && sstats->cnt > 0)
+ printf(" - number of transactions skipped: " INT64_FORMAT " (%.3f%%)\n",
+ sstats->skipped,
+ 100.0 * sstats->skipped / sstats->cnt);
- if (num_scripts > 1)
- printSimpleStats(" - latency", &sql_script[i].stats.latency);
+ printSimpleStats(" - latency", &sstats->latency);
+ }
/* Report per-command latencies */
if (is_latencies)
{
Command **commands;
- printf(" - statement latencies in milliseconds:\n");
+ if (per_script_stats)
+ printf(" - statement latencies in milliseconds:\n");
+ else
+ printf("statement latencies in milliseconds:\n");
for (commands = sql_script[i].commands;
*commands != NULL;
commands++)
+ {
+ SimpleStats *cstats = &(*commands)->stats;
+
printf(" %11.3f %s\n",
- 1000.0 * (*commands)->stats.sum /
- (*commands)->stats.count,
+ (cstats->count > 0) ?
+ 1000.0 * cstats->sum / cstats->count : 0.0,
(*commands)->line);
+ }
}
}
}
@@ -3984,7 +3997,6 @@ main(int argc, char **argv)
break;
case 'r':
benchmarking_option_set = true;
- per_script_stats = true;
is_latencies = true;
break;
case 's':
@@ -4861,7 +4873,8 @@ threadRun(void *arg)
{
/* generate and show report */
StatsData cur;
- int64 run = now - last_report;
+ int64 run = now - last_report,
+ ntx;
double tps,
total_run,
latency,
@@ -4876,7 +4889,7 @@ threadRun(void *arg)
* XXX: No locking. There is no guarantee that we get an
* atomic snapshot of the transaction count and latencies, so
* these figures can well be off by a small amount. The
- * progress is report's purpose is to give a quick overview of
+ * progress report's purpose is to give a quick overview of
* how the test is going, so that shouldn't matter too much.
* (If a read from a 64-bit integer is not atomic, you might
* get a "torn" read and completely bogus latencies though!)
@@ -4890,15 +4903,21 @@ threadRun(void *arg)
cur.skipped += thread[i].stats.skipped;
}
+ /* we count only actually executed transactions */
+ ntx = (cur.cnt - cur.skipped) - (last.cnt - last.skipped);
total_run = (now - thread_start) / 1000000.0;
- tps = 1000000.0 * (cur.cnt - last.cnt) / run;
- latency = 0.001 * (cur.latency.sum - last.latency.sum) /
- (cur.cnt - last.cnt);
- sqlat = 1.0 * (cur.latency.sum2 - last.latency.sum2)
- / (cur.cnt - last.cnt);
- stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
- lag = 0.001 * (cur.lag.sum - last.lag.sum) /
- (cur.cnt - last.cnt);
+ tps = 1000000.0 * ntx / run;
+ if (ntx > 0)
+ {
+ latency = 0.001 * (cur.latency.sum - last.latency.sum) / ntx;
+ sqlat = 1.0 * (cur.latency.sum2 - last.latency.sum2) / ntx;
+ stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
+ lag = 0.001 * (cur.lag.sum - last.lag.sum) / ntx;
+ }
+ else
+ {
+ latency = sqlat = stdev = lag = 0;
+ }
if (progress_timestamp)
{
@@ -4915,7 +4934,10 @@ threadRun(void *arg)
(long) tv.tv_sec, (long) (tv.tv_usec / 1000));
}
else
+ {
+ /* round seconds are expected, but the thread may be late */
snprintf(tbuf, sizeof(tbuf), "%.1f s", total_run);
+ }
fprintf(stderr,
"progress: %s, %.1f tps, lat %.3f ms stddev %.3f",
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 864d580c64d..c0958813121 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -427,7 +427,7 @@ pgbench(
0,
[ qr{processed: [01]/10},
qr{type: .*/001_pgbench_sleep},
- qr{above the 1.0 ms latency limit: [01] } ],
+ qr{above the 1.0 ms latency limit: [01]/} ],
[qr{^$}i],
'pgbench late throttling',
{ '001_pgbench_sleep' => q{\sleep 2ms} });
--
GitLab