Patch (4): Redefine "latency" as reported by pgbench and report "lag" more.
Here is a first partial patch, which focusses on measuring latency and
reporting the measure under --progress.
**
Improve pgbench measurements & progress report
Measure transaction latency instead under --rate and --progress.
The previous computed figure does not make sense under throttling:
as sleep throttling time was included in the figures, the displayed
results were plain false.
The latency and its standard deviation are printed out under progress and
in the final report when available.
It could be made "always" available, but that would require to accept
additional gettimeofday calls. I do not think that there is a performance
issue here, but there is significant opposition to the idea.
Sample output under benchmarking with --progress=1
progress: 1.0 s, 2626.1 tps, 0.374 stddev 0.597 ms lat
progress: 2.0 s, 2766.6 tps, 0.358 stddev 0.588 ms lat
progress: 3.0 s, 2567.4 tps, 0.385 stddev 0.665 ms lat
progress: 4.0 s, 3014.2 tps, 0.328 stddev 0.593 ms lat
progress: 5.0 s, 2959.3 tps, 0.334 stddev 0.553 ms lat
...
progress: 16.0 s, 5009.2 tps, 0.197 stddev 0.381 ms lat
...
progress: 24.0 s, 7051.2 tps, 0.139 stddev 0.284 ms lat
...
progress: 50.0 s, 6860.5 tps, 0.143 stddev 0.052 ms lat
...
The "warmup" is quite fast because the DB is on a SSD. In the beginning
the standard deviation is well over the average transaction time, but
when the steady state is reached (later) it is much below.
--
Fabien.
diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index 06dd709..a48498a 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -172,6 +172,7 @@ int agg_interval; /* log aggregates instead of individual
* transactions */
int progress = 0; /* thread progress report every this seconds */
int progress_nclients = 0; /* number of clients for progress report */
+int progress_nthreads = 0; /* number of threads for progress report */
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 */
@@ -214,6 +215,8 @@ typedef struct
int nvariables;
instr_time txn_begin; /* used for measuring transaction latencies */
instr_time stmt_begin; /* used for measuring statement latencies */
+ int64 txn_latencies; /* cumulated latencies */
+ int64 txn_sqlats; /* cumulated square latencies */
bool is_throttled; /* whether transaction throttling is done */
int use_file; /* index in sql_files for this client */
bool prepared[MAX_FILES];
@@ -243,6 +246,8 @@ typedef struct
{
instr_time conn_time;
int xacts;
+ int64 latencies;
+ int64 sqlats;
int64 throttle_lag;
int64 throttle_lag_max;
} TResult;
@@ -1003,6 +1008,21 @@ top:
}
/*
+ * always record latency under progress or throttling
+ */
+ if ((progress || throttle_delay) && commands[st->state + 1] == NULL)
+ {
+ instr_time now, diff;
+ int64 latency;
+ INSTR_TIME_SET_CURRENT(now);
+ diff = now;
+ INSTR_TIME_SUBTRACT(diff, st->txn_begin);
+ latency = INSTR_TIME_GET_MICROSEC(diff);
+ st->txn_latencies += latency;
+ st->txn_sqlats += latency*latency;
+ }
+
+ /*
* if transaction finished, record the time it took in the log
*/
if (logfile && commands[st->state + 1] == NULL)
@@ -1191,8 +1211,8 @@ top:
goto top;
}
- /* Record transaction start time if logging is enabled */
- if (logfile && st->state == 0)
+ /* Record transaction start time under logging, progress or throttling */
+ if ((logfile || progress || throttle_delay) && st->state == 0)
INSTR_TIME_SET_CURRENT(st->txn_begin);
/* Record statement start time if per-command latencies are requested */
@@ -2096,6 +2116,7 @@ static void
printResults(int ttype, int normal_xacts, int nclients,
TState *threads, int nthreads,
instr_time total_time, instr_time conn_total_time,
+ int64 total_latencies, int64 total_sqlats,
int64 throttle_lag, int64 throttle_lag_max)
{
double time_include,
@@ -2135,6 +2156,22 @@ printResults(int ttype, int normal_xacts, int nclients,
normal_xacts);
}
+ if (throttle_delay || progress)
+ {
+ /* compute and show latency average and standard deviation */
+ double latency = 0.001 * total_latencies / normal_xacts;
+ double sqlat = (double) total_sqlats / normal_xacts;
+ printf("latency average: %.3f ms\n"
+ "latency stddev: %.3f ms\n",
+ latency, 0.001 * sqrt(sqlat - 1000000*latency*latency));
+ }
+ else
+ {
+ /* only an average latency computed from the duration is available */
+ printf("latency average: %.3f ms\n",
+ 1000.0 * duration / normal_xacts);
+ }
+
if (throttle_delay)
{
/*
@@ -2143,7 +2180,7 @@ printResults(int ttype, int normal_xacts, int nclients,
* transaction. The measured lag may be caused by thread/client load,
* the database load, or the Poisson throttling process.
*/
- printf("average rate limit schedule lag: %.3f ms (max %.3f ms)\n",
+ printf("rate limit schedule lag: avg %.3f (max %.3f) ms\n",
0.001 * throttle_lag / normal_xacts, 0.001 * throttle_lag_max);
}
@@ -2254,7 +2291,9 @@ main(int argc, char **argv)
instr_time start_time; /* start up time */
instr_time total_time;
instr_time conn_total_time;
- int total_xacts;
+ int total_xacts = 0;
+ int64 total_latencies = 0;
+ int64 total_sqlats = 0;
int64 throttle_lag = 0;
int64 throttle_lag_max = 0;
@@ -2608,6 +2647,7 @@ main(int argc, char **argv)
*/
main_pid = (int) getpid();
progress_nclients = nclients;
+ progress_nthreads = nthreads;
if (nclients > 1)
{
@@ -2816,7 +2856,6 @@ main(int argc, char **argv)
}
/* wait for threads and accumulate results */
- total_xacts = 0;
INSTR_TIME_SET_ZERO(conn_total_time);
for (i = 0; i < nthreads; i++)
{
@@ -2832,6 +2871,8 @@ main(int argc, char **argv)
TResult *r = (TResult *) ret;
total_xacts += r->xacts;
+ total_latencies += r->latencies;
+ total_sqlats += r->sqlats;
throttle_lag += r->throttle_lag;
if (r->throttle_lag_max > throttle_lag_max)
throttle_lag_max = r->throttle_lag_max;
@@ -2845,7 +2886,8 @@ main(int argc, char **argv)
INSTR_TIME_SET_CURRENT(total_time);
INSTR_TIME_SUBTRACT(total_time, start_time);
printResults(ttype, total_xacts, nclients, threads, nthreads,
- total_time, conn_total_time, throttle_lag, throttle_lag_max);
+ total_time, conn_total_time,
+ total_latencies, total_sqlats, throttle_lag, throttle_lag_max);
return 0;
}
@@ -2866,7 +2908,7 @@ threadRun(void *arg)
int64 thread_start = INSTR_TIME_GET_MICROSEC(thread->start_time);
int64 last_report = thread_start;
int64 next_report = last_report + progress * 1000000;
- int64 last_count = 0;
+ int64 last_count = 0, last_lats = 0, last_sqlats = 0, last_lags = 0;
AggVals aggs;
@@ -3066,21 +3108,40 @@ threadRun(void *arg)
if (now >= next_report)
{
/* generate and show report */
- int64 count = 0;
+ int64 count = 0, lats = 0, sqlats = 0;
+ int64 lags = thread->throttle_lag;
int64 run = now - last_report;
- float tps, total_run, latency;
+ double tps, total_run, latency, sqlat, stdev, lag;
for (i = 0 ; i < nstate ; i++)
+ {
count += state[i].cnt;
+ lats += state[i].txn_latencies;
+ sqlats += state[i].txn_sqlats;
+ }
total_run = (now - thread_start) / 1000000.0;
tps = 1000000.0 * (count - last_count) / run;
- latency = 1000.0 * nstate / tps;
+ latency = 0.001 * (lats - last_lats) / (count - last_count);
+ sqlat = 1.0 * (sqlats - last_sqlats) / (count - last_count);
+ stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
+ lag = 0.001 * (lags - last_lags) / (count - last_count);
- fprintf(stderr, "progress %d: %.1f s, %.1f tps, %.3f ms lat\n",
- thread->tid, total_run, tps, latency);
+ if (throttle_delay)
+ fprintf(stderr,
+ "progress %d: %.1f s, %.1f tps, "
+ "%.3f stddev %.3f ms lat, %.3f ms lag\n",
+ thread->tid, total_run, tps, latency, stdev, lag);
+ else
+ fprintf(stderr,
+ "progress %d: %.1f s, %.1f tps, "
+ "%.3f stddev %.3f ms lat\n",
+ thread->tid, total_run, tps, latency, stdev);
last_count = count;
+ last_lats = lats;
+ last_sqlats = sqlats;
+ last_lags = lags;
last_report = now;
next_report += progress * 1000000;
}
@@ -3096,21 +3157,42 @@ threadRun(void *arg)
if (now >= next_report)
{
/* generate and show report */
- int64 count = 0;
+ int64 count = 0, lats = 0, sqlats = 0, lags = 0;
int64 run = now - last_report;
- float tps, total_run, latency;
+ float tps, total_run, latency, sqlat, lag, stdev;
for (i = 0 ; i < progress_nclients ; i++)
+ {
count += state[i].cnt;
+ lats += state[i].txn_latencies;
+ sqlats += state[i].txn_sqlats;
+ }
+
+ for (i = 0 ; i < progress_nthreads ; i++)
+ lags += thread[i].throttle_lag;
total_run = (now - thread_start) / 1000000.0;
tps = 1000000.0 * (count - last_count) / run;
- latency = 1000.0 * progress_nclients / tps;
+ latency = 0.001 * (lats - last_lats) / (count - last_count);
+ sqlat = 1.0 * (sqlats - last_sqlats) / (count - last_count);
+ stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
+ lag = 0.001 * (lags - last_lags) / (count - last_count);
- fprintf(stderr, "progress: %.1f s, %.1f tps, %.3f ms lat\n",
- total_run, tps, latency);
+ if (throttle_delay)
+ fprintf(stderr,
+ "progress: %.1f s, %.1f tps, "
+ "%.3f stddev %.3f ms lat, %.3f ms lag\n",
+ total_run, tps, latency, stdev, lag);
+ else
+ fprintf(stderr,
+ "progress: %.1f s, %.1f tps, "
+ "%.3f stddev %.3f ms lat\n",
+ total_run, tps, latency, stdev);
last_count = count;
+ last_lats = lats;
+ last_sqlats = sqlats;
+ last_lags = lags;
last_report = now;
next_report += progress * 1000000;
}
@@ -3122,8 +3204,14 @@ done:
INSTR_TIME_SET_CURRENT(start);
disconnect_all(state, nstate);
result->xacts = 0;
+ result->latencies = 0;
+ result->sqlats = 0;
for (i = 0; i < nstate; i++)
+ {
result->xacts += state[i].cnt;
+ result->latencies += state[i].txn_latencies;
+ result->sqlats += state[i].txn_sqlats;
+ }
result->throttle_lag = thread->throttle_lag;
result->throttle_lag_max = thread->throttle_lag_max;
INSTR_TIME_SET_CURRENT(end);
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
