aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorTom Lane <tgl@sss.pgh.pa.us>2017-09-04 16:24:08 -0400
committerTom Lane <tgl@sss.pgh.pa.us>2017-09-04 16:24:08 -0400
commitc23bb6badfa2048d17c08ebcfd81adf942292e51 (patch)
treeb01788f615e04376dcf0fc049657a65e14761306
parent9d36a386608d7349964e76120e48987e3ec67d04 (diff)
downloadpostgresql-c23bb6badfa2048d17c08ebcfd81adf942292e51.tar.gz
postgresql-c23bb6badfa2048d17c08ebcfd81adf942292e51.zip
Fix some subtle problems in pgbench transaction stats counting.
With --latency-limit, transactions might get skipped even beyond the transaction count limit specified by -t, throwing off the expected number of transactions and thus the denominator for later stats. Be sure to stop skipping transactions once -t is reached. Also, include skipped transactions in the "cnt" fields; this requires discounting them again in a couple of places, but most places are better off with this definition. In particular this is needed to get correct overall stats for the combination of -R/-L/-t options. Merge some more processing into processXactStats() to simplify this. In passing, add a check that --progress-timestamp is specified only when --progress is. We might consider back-patching this, but given that it only matters for a combination of options, and given the lack of field complaints, consensus seems to be not to bother. Fabien Coelho, reviewed by Nikolay Shaplov Discussion: https://postgr.es/m/alpine.DEB.2.20.1704171422500.4025@lancre
-rw-r--r--src/bin/pgbench/pgbench.c71
1 files changed, 43 insertions, 28 deletions
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index b64e3fbee21..364e25447e4 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -229,7 +229,7 @@ typedef struct SimpleStats
typedef struct StatsData
{
time_t start_time; /* interval start time, for aggregates */
- int64 cnt; /* number of transactions */
+ int64 cnt; /* number of transactions, including skipped */
int64 skipped; /* number of transactions skipped under --rate
* and --latency-limit */
SimpleStats latency;
@@ -329,7 +329,7 @@ typedef struct
bool prepared[MAX_SCRIPTS]; /* whether client prepared the script */
/* per client collected stats */
- int64 cnt; /* transaction count */
+ int64 cnt; /* client transaction count, for -t */
int ecnt; /* error count */
} CState;
@@ -2062,10 +2062,11 @@ doCustom(TState *thread, CState *st, StatsData *agg)
}
/*
- * If this --latency-limit is used, and this slot is already
- * late so that the transaction will miss the latency limit
- * even if it completed immediately, we skip this time slot
- * and iterate till the next slot that isn't late yet.
+ * If --latency-limit is used, and this slot is already late
+ * so that the transaction will miss the latency limit even if
+ * it completed immediately, we skip this time slot and
+ * iterate till the next slot that isn't late yet. But don't
+ * iterate beyond the -t limit, if one is given.
*/
if (latency_limit)
{
@@ -2074,7 +2075,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
if (INSTR_TIME_IS_ZERO(now))
INSTR_TIME_SET_CURRENT(now);
now_us = INSTR_TIME_GET_MICROSEC(now);
- while (thread->throttle_trigger < now_us - latency_limit)
+ while (thread->throttle_trigger < now_us - latency_limit &&
+ (nxacts <= 0 || st->cnt < nxacts))
{
processXactStats(thread, st, &now, true, agg);
/* next rendez-vous */
@@ -2082,6 +2084,12 @@ doCustom(TState *thread, CState *st, StatsData *agg)
thread->throttle_trigger += wait;
st->txn_scheduled = thread->throttle_trigger;
}
+ /* stop client if -t exceeded */
+ if (nxacts > 0 && st->cnt >= nxacts)
+ {
+ st->state = CSTATE_FINISHED;
+ break;
+ }
}
st->state = CSTATE_THROTTLE;
@@ -2393,15 +2401,8 @@ doCustom(TState *thread, CState *st, StatsData *agg)
*/
case CSTATE_END_TX:
- /*
- * transaction finished: calculate latency and log the
- * transaction
- */
- if (progress || throttle_delay || latency_limit ||
- per_script_stats || use_log)
- processXactStats(thread, st, &now, false, agg);
- else
- thread->stats.cnt++;
+ /* transaction finished: calculate latency and do log */
+ processXactStats(thread, st, &now, false, agg);
if (is_connect)
{
@@ -2410,7 +2411,6 @@ doCustom(TState *thread, CState *st, StatsData *agg)
INSTR_TIME_SET_ZERO(now);
}
- ++st->cnt;
if ((st->cnt >= nxacts && duration <= 0) || timer_exceeded)
{
/* exit success */
@@ -2540,7 +2540,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.)
+ * (This is also called when a transaction is late and thus skipped.
+ * Note that even skipped transactions are counted in the "cnt" fields.)
*/
static void
processXactStats(TState *thread, CState *st, instr_time *now,
@@ -2548,19 +2549,22 @@ 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;
- if ((!skipped) && INSTR_TIME_IS_ZERO(*now))
- INSTR_TIME_SET_CURRENT(*now);
-
- if (!skipped)
+ if (detailed && !skipped)
{
+ if (INSTR_TIME_IS_ZERO(*now))
+ INSTR_TIME_SET_CURRENT(*now);
+
/* compute latency & lag */
latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;
lag = INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled;
}
- if (progress || throttle_delay || latency_limit)
+ if (thread_details)
{
+ /* keep detailed thread stats */
accumStats(&thread->stats, skipped, latency, lag);
/* count transactions over the latency limit, if needed */
@@ -2568,7 +2572,13 @@ processXactStats(TState *thread, CState *st, instr_time *now,
thread->latency_late++;
}
else
+ {
+ /* no detailed stats, just count */
thread->stats.cnt++;
+ }
+
+ /* client stat is just counting */
+ st->cnt++;
if (use_log)
doLog(thread, st, agg, skipped, latency, lag);
@@ -3534,7 +3544,7 @@ 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, nxacts * nclients);
+ total->cnt - total->skipped, nxacts * nclients);
}
else
{
@@ -3550,12 +3560,12 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
if (throttle_delay && latency_limit)
printf("number of transactions skipped: " INT64_FORMAT " (%.3f %%)\n",
total->skipped,
- 100.0 * total->skipped / (total->skipped + total->cnt));
+ 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->skipped + total->cnt));
+ 100.0 * latency_late / total->cnt);
if (throttle_delay || progress || latency_limit)
printSimpleStats("latency", &total->latency);
@@ -3604,8 +3614,7 @@ printResults(TState *threads, StatsData *total, instr_time total_time,
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.skipped + sql_script[i].stats.cnt));
+ 100.0 * sql_script[i].stats.skipped / sql_script[i].stats.cnt);
if (num_scripts > 1)
printSimpleStats(" - latency", &sql_script[i].stats.latency);
@@ -4144,6 +4153,12 @@ main(int argc, char **argv)
exit(1);
}
+ if (progress_timestamp && progress == 0)
+ {
+ fprintf(stderr, "--progress-timestamp is allowed only under --progress\n");
+ exit(1);
+ }
+
/*
* save main process id in the global variable because process id will be
* changed after fork.