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

diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index b64e3fbee21bcdbd66c795abacdebc9241d74ea8..364e25447e431330aab526e989eb28ffe6366ab6 100644 (file)
--- 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.