]> granicus.if.org Git - postgresql/commitdiff
pgbench: fix stats reporting when some transactions are skipped.
authorTom Lane <tgl@sss.pgh.pa.us>
Tue, 21 Nov 2017 22:30:48 +0000 (17:30 -0500)
committerTom Lane <tgl@sss.pgh.pa.us>
Tue, 21 Nov 2017 22:30:48 +0000 (17:30 -0500)
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
src/bin/pgbench/pgbench.c
src/bin/pgbench/t/001_pgbench_with_server.pl

index c48a69713abf674940479f06a7a3b4b9844cdfe7..f6e93c3ade662edd68eb1dc058deccbf763ade36 100644 (file)
@@ -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)
index ceb2fcc3ad63fbc9edb44ad4c745c3a6e7ce63d2..bd96eae5e6be5145db18f679ec2670a4547c6f3f 100644 (file)
@@ -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",
index 864d580c64d23d9c40bb94e8f6b827fb497331d1..c09588131216e54e5835d16b4bc14430695e75de 100644 (file)
@@ -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} });