diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index 4aa8a5031a..e4b75b266e 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -204,10 +204,10 @@ typedef struct
* sent */
int sleeping; /* 1 indicates that the client is napping */
bool throttling; /* whether nap is for throttling */
- int64 until; /* napping until (usec) */
Variable *variables; /* array of variable definitions */
int nvariables;
- instr_time txn_begin; /* used for measuring transaction latencies */
+ int64 txn_scheduled; /* scheduled start time of transaction (usec) */
+ instr_time txn_begin; /* used for measuring schedule lag times */
instr_time stmt_begin; /* used for measuring statement latencies */
int64 txn_latencies; /* cumulated latencies */
int64 txn_sqlats; /* cumulated square latencies */
@@ -278,12 +278,17 @@ typedef struct
long start_time; /* when does the interval start */
int cnt; /* number of transactions */
- double min_duration; /* min/max durations */
- double max_duration;
- double sum; /* sum(duration), sum(duration^2) - for
- * estimates */
- double sum2;
+ double min_latency; /* min/max latencies */
+ double max_latency;
+ double sum_latency; /* sum(latency), sum(latency^2) - for
+ * estimates */
+ double sum2_latency;
+
+ double min_lag;
+ double max_lag;
+ double sum_lag; /* sum(lag) */
+ double sum2_lag; /* sum(lag*lag) */
} AggVals;
static Command **sql_files[MAX_FILES]; /* SQL script files */
@@ -892,12 +897,18 @@ agg_vals_init(AggVals *aggs, instr_time start)
{
/* basic counters */
aggs->cnt = 0; /* number of transactions */
- aggs->sum = 0; /* SUM(duration) */
- aggs->sum2 = 0; /* SUM(duration*duration) */
+ aggs->sum_latency = 0; /* SUM(latency) */
+ aggs->sum2_latency = 0; /* SUM(latency*latency) */
/* min and max transaction duration */
- aggs->min_duration = 0;
- aggs->max_duration = 0;
+ aggs->min_latency = 0;
+ aggs->max_latency = 0;
+
+ /* schedule lag counters */
+ aggs->sum_lag = 0;
+ aggs->sum2_lag = 0;
+ aggs->min_lag = 0;
+ aggs->max_lag = 0;
/* start of the current interval */
aggs->start_time = INSTR_TIME_GET_DOUBLE(start);
@@ -940,7 +951,7 @@ top:
thread->throttle_trigger += wait;
- st->until = thread->throttle_trigger;
+ st->txn_scheduled = thread->throttle_trigger;
st->sleeping = 1;
st->throttling = true;
st->is_throttled = true;
@@ -956,13 +967,13 @@ top:
INSTR_TIME_SET_CURRENT(now);
now_us = INSTR_TIME_GET_MICROSEC(now);
- if (st->until <= now_us)
+ if (st->txn_scheduled <= now_us)
{
st->sleeping = 0; /* Done sleeping, go ahead with next command */
if (st->throttling)
{
/* Measure lag of throttled transaction relative to target */
- int64 lag = now_us - st->until;
+ int64 lag = now_us - st->txn_scheduled;
thread->throttle_lag += lag;
if (lag > thread->throttle_lag_max)
@@ -976,6 +987,11 @@ top:
if (st->listen)
{ /* are we receiver? */
+ instr_time now;
+ bool now_valid = false;
+
+ INSTR_TIME_SET_ZERO(now); /* initialize to keep compiler quiet */
+
if (commands[st->state]->type == SQL_COMMAND)
{
if (debug)
@@ -995,10 +1011,13 @@ top:
*/
if (is_latencies)
{
- instr_time now;
int cnum = commands[st->state]->command_num;
- INSTR_TIME_SET_CURRENT(now);
+ if (!now_valid)
+ {
+ INSTR_TIME_SET_CURRENT(now);
+ now_valid = true;
+ }
INSTR_TIME_ACCUM_DIFF(thread->exec_elapsed[cnum],
now, st->stmt_begin);
thread->exec_count[cnum]++;
@@ -1007,12 +1026,16 @@ top:
/* transaction finished: record latency under progress or throttling */
if ((progress || throttle_delay) && commands[st->state + 1] == NULL)
{
- instr_time diff;
int64 latency;
- INSTR_TIME_SET_CURRENT(diff);
- INSTR_TIME_SUBTRACT(diff, st->txn_begin);
- latency = INSTR_TIME_GET_MICROSEC(diff);
+ if (!now_valid)
+ {
+ INSTR_TIME_SET_CURRENT(now);
+ now_valid = true;
+ }
+
+ latency = INSTR_TIME_GET_MICROSEC(now) - st->txn_scheduled;
+
st->txn_latencies += latency;
/*
@@ -1030,9 +1053,8 @@ top:
*/
if (logfile && commands[st->state + 1] == NULL)
{
- instr_time now;
- instr_time diff;
- double usec;
+ double lag;
+ double latency;
/*
* write the log entry if this row belongs to the random sample,
@@ -1041,10 +1063,13 @@ top:
if (sample_rate == 0.0 ||
pg_erand48(thread->random_state) <= sample_rate)
{
- INSTR_TIME_SET_CURRENT(now);
- diff = now;
- INSTR_TIME_SUBTRACT(diff, st->txn_begin);
- usec = (double) INSTR_TIME_GET_MICROSEC(diff);
+ if (!now_valid)
+ {
+ INSTR_TIME_SET_CURRENT(now);
+ now_valid = true;
+ }
+ latency = (double) (INSTR_TIME_GET_MICROSEC(now) - st->txn_scheduled);
+ lag = (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled);
/* should we aggregate the results or not? */
if (agg_interval > 0)
@@ -1056,15 +1081,27 @@ top:
if (agg->start_time + agg_interval >= INSTR_TIME_GET_DOUBLE(now))
{
agg->cnt += 1;
- agg->sum += usec;
- agg->sum2 += usec * usec;
+ agg->sum_latency += latency;
+ agg->sum2_latency += latency * latency;
/* first in this aggregation interval */
- if ((agg->cnt == 1) || (usec < agg->min_duration))
- agg->min_duration = usec;
+ if ((agg->cnt == 1) || (latency < agg->min_latency))
+ agg->min_latency = latency;
- if ((agg->cnt == 1) || (usec > agg->max_duration))
- agg->max_duration = usec;
+ if ((agg->cnt == 1) || (latency > agg->max_latency))
+ agg->max_latency = latency;
+
+ /* and the same for schedule lag */
+ if (throttle_delay)
+ {
+ agg->sum_lag += lag;
+ agg->sum2_lag += lag * lag;
+
+ if ((agg->cnt == 1) || (lag < agg->min_lag))
+ agg->min_lag = lag;
+ if ((agg->cnt == 1) || (lag > agg->max_lag))
+ agg->max_lag = lag;
+ }
}
else
{
@@ -1080,23 +1117,34 @@ top:
* ifdef in usage), so we don't need to handle
* this in a special way (see below).
*/
- fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f\n",
+ fprintf(logfile, "%ld %d %.0f %.0f %.0f %.0f",
agg->start_time,
agg->cnt,
- agg->sum,
- agg->sum2,
- agg->min_duration,
- agg->max_duration);
+ agg->sum_latency,
+ agg->sum2_latency,
+ agg->min_latency,
+ agg->max_latency);
+ if (throttle_delay)
+ fprintf(logfile, " %.0f %.0f %.0f %.0f",
+ agg->sum_lag,
+ agg->sum2_lag,
+ agg->min_lag,
+ agg->max_lag);
+ fputc('\n', logfile);
/* move to the next inteval */
agg->start_time = agg->start_time + agg_interval;
/* reset for "no transaction" intervals */
agg->cnt = 0;
- agg->min_duration = 0;
- agg->max_duration = 0;
- agg->sum = 0;
- agg->sum2 = 0;
+ agg->min_latency = 0;
+ agg->max_latency = 0;
+ agg->sum_latency = 0;
+ agg->sum2_latency = 0;
+ agg->min_lag = 0;
+ agg->max_lag = 0;
+ agg->sum_lag = 0;
+ agg->sum2_lag = 0;
}
/*
@@ -1104,10 +1152,14 @@ top:
* current)
*/
agg->cnt = 1;
- agg->min_duration = usec;
- agg->max_duration = usec;
- agg->sum = usec;
- agg->sum2 = usec * usec;
+ agg->min_latency = latency;
+ agg->max_latency = latency;
+ agg->sum_latency = latency;
+ agg->sum2_latency = latency * latency;
+ agg->min_lag = lag;
+ agg->max_lag = lag;
+ agg->sum_lag = lag;
+ agg->sum2_lag = lag * lag;
}
}
else
@@ -1119,8 +1171,8 @@ top:
* This is more than we really ought to know about
* instr_time
*/
- fprintf(logfile, "%d %d %.0f %d %ld %ld\n",
- st->id, st->cnt, usec, st->use_file,
+ fprintf(logfile, "%d %d %.0f %d %ld %ld",
+ st->id, st->cnt, latency, st->use_file,
(long) now.tv_sec, (long) now.tv_usec);
#else
@@ -1128,9 +1180,12 @@ top:
* On Windows, instr_time doesn't provide a timestamp
* anyway
*/
- fprintf(logfile, "%d %d %.0f %d 0 0\n",
+ fprintf(logfile, "%d %d %.0f %d 0 0",
st->id, st->cnt, usec, st->use_file);
#endif
+ if (throttle_delay)
+ fprintf(logfile, " %.0f", lag);
+ fputc('\n', logfile);
}
}
}
@@ -1219,8 +1274,17 @@ top:
/* Record transaction start time under logging, progress or throttling */
if ((logfile || progress || throttle_delay) && st->state == 0)
+ {
INSTR_TIME_SET_CURRENT(st->txn_begin);
+ /*
+ * When not throttling, this is also the transaction's scheduled start
+ * time.
+ */
+ if (!throttle_delay)
+ st->txn_scheduled = INSTR_TIME_GET_MICROSEC(st->txn_begin);
+ }
+
/* Record statement start time if per-command latencies are requested */
if (is_latencies)
INSTR_TIME_SET_CURRENT(st->stmt_begin);
@@ -1489,7 +1553,7 @@ top:
usec *= 1000000;
INSTR_TIME_SET_CURRENT(now);
- st->until = INSTR_TIME_GET_MICROSEC(now) + usec;
+ st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now) + usec;
st->sleeping = 1;
st->listen = 1;
@@ -3108,7 +3172,7 @@ threadRun(void *arg)
now_usec = INSTR_TIME_GET_MICROSEC(now);
}
- this_usec = st->until - now_usec;
+ this_usec = st->txn_scheduled - now_usec;
if (min_usec > this_usec)
min_usec = this_usec;
}
diff --git a/doc/src/sgml/pgbench.sgml b/doc/src/sgml/pgbench.sgml
index 408e7fb194..4187fc1a0e 100644
--- a/doc/src/sgml/pgbench.sgml
+++ b/doc/src/sgml/pgbench.sgml
@@ -403,8 +403,10 @@ pgbench options> dbname>
Show progress report every sec> seconds. The report
includes the time since the beginning of the run, the tps since the
last report, and the transaction latency average and standard
- deviation since the last report. Under throttling (