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);