Add --latency-limit option to pgbench.
This allows transactions that take longer than specified limit to be counted separately. With --rate, transactions that are already late by the time we get to execute them are skipped altogether. Using --latency-limit with --rate allows you to "catch up" more quickly, if there's a hickup in the server causing a lot of transactions to stall momentarily. Fabien COELHO, reviewed by Rukh Meski and heavily refactored by me.
This commit is contained in:
parent
30d7ae3c76
commit
98aed6c721
|
@ -140,6 +140,14 @@ double sample_rate = 0.0;
|
||||||
*/
|
*/
|
||||||
int64 throttle_delay = 0;
|
int64 throttle_delay = 0;
|
||||||
|
|
||||||
|
/*
|
||||||
|
* Transactions which take longer than this limit (in usec) are counted as
|
||||||
|
* late, and reported as such, although they are completed anyway. When
|
||||||
|
* throttling is enabled, execution time slots that are more than this late
|
||||||
|
* are skipped altogether, and counted separately.
|
||||||
|
*/
|
||||||
|
int64 latency_limit = 0;
|
||||||
|
|
||||||
/*
|
/*
|
||||||
* tablespace selection
|
* tablespace selection
|
||||||
*/
|
*/
|
||||||
|
@ -238,6 +246,8 @@ typedef struct
|
||||||
int64 throttle_trigger; /* previous/next throttling (us) */
|
int64 throttle_trigger; /* previous/next throttling (us) */
|
||||||
int64 throttle_lag; /* total transaction lag behind throttling */
|
int64 throttle_lag; /* total transaction lag behind throttling */
|
||||||
int64 throttle_lag_max; /* max transaction lag */
|
int64 throttle_lag_max; /* max transaction lag */
|
||||||
|
int64 throttle_latency_skipped; /* lagging transactions skipped */
|
||||||
|
int64 latency_late; /* late transactions */
|
||||||
} TState;
|
} TState;
|
||||||
|
|
||||||
#define INVALID_THREAD ((pthread_t) 0)
|
#define INVALID_THREAD ((pthread_t) 0)
|
||||||
|
@ -250,6 +260,8 @@ typedef struct
|
||||||
int64 sqlats;
|
int64 sqlats;
|
||||||
int64 throttle_lag;
|
int64 throttle_lag;
|
||||||
int64 throttle_lag_max;
|
int64 throttle_lag_max;
|
||||||
|
int64 throttle_latency_skipped;
|
||||||
|
int64 latency_late;
|
||||||
} TResult;
|
} TResult;
|
||||||
|
|
||||||
/*
|
/*
|
||||||
|
@ -284,6 +296,8 @@ typedef struct
|
||||||
|
|
||||||
long start_time; /* when does the interval start */
|
long start_time; /* when does the interval start */
|
||||||
int cnt; /* number of transactions */
|
int cnt; /* number of transactions */
|
||||||
|
int skipped; /* number of transactions skipped under
|
||||||
|
* --rate and --latency-limit */
|
||||||
|
|
||||||
double min_latency; /* min/max latencies */
|
double min_latency; /* min/max latencies */
|
||||||
double max_latency;
|
double max_latency;
|
||||||
|
@ -348,7 +362,7 @@ static void setalarm(int seconds);
|
||||||
static void *threadRun(void *arg);
|
static void *threadRun(void *arg);
|
||||||
|
|
||||||
static void doLog(TState *thread, CState *st, FILE *logfile, instr_time *now,
|
static void doLog(TState *thread, CState *st, FILE *logfile, instr_time *now,
|
||||||
AggVals *agg);
|
AggVals *agg, bool skipped);
|
||||||
|
|
||||||
static void
|
static void
|
||||||
usage(void)
|
usage(void)
|
||||||
|
@ -375,6 +389,8 @@ usage(void)
|
||||||
" -f, --file=FILENAME read transaction script from FILENAME\n"
|
" -f, --file=FILENAME read transaction script from FILENAME\n"
|
||||||
" -j, --jobs=NUM number of threads (default: 1)\n"
|
" -j, --jobs=NUM number of threads (default: 1)\n"
|
||||||
" -l, --log write transaction times to log file\n"
|
" -l, --log write transaction times to log file\n"
|
||||||
|
" -L, --latency-limit=NUM count transactions lasting more than NUM ms\n"
|
||||||
|
" as late.\n"
|
||||||
" -M, --protocol=simple|extended|prepared\n"
|
" -M, --protocol=simple|extended|prepared\n"
|
||||||
" protocol for submitting queries (default: simple)\n"
|
" protocol for submitting queries (default: simple)\n"
|
||||||
" -n, --no-vacuum do not run VACUUM before tests\n"
|
" -n, --no-vacuum do not run VACUUM before tests\n"
|
||||||
|
@ -994,7 +1010,9 @@ void
|
||||||
agg_vals_init(AggVals *aggs, instr_time start)
|
agg_vals_init(AggVals *aggs, instr_time start)
|
||||||
{
|
{
|
||||||
/* basic counters */
|
/* basic counters */
|
||||||
aggs->cnt = 0; /* number of transactions */
|
aggs->cnt = 0; /* number of transactions (includes skipped) */
|
||||||
|
aggs->skipped = 0; /* xacts skipped under --rate --latency-limit */
|
||||||
|
|
||||||
aggs->sum_latency = 0; /* SUM(latency) */
|
aggs->sum_latency = 0; /* SUM(latency) */
|
||||||
aggs->sum2_latency = 0; /* SUM(latency*latency) */
|
aggs->sum2_latency = 0; /* SUM(latency*latency) */
|
||||||
|
|
||||||
|
@ -1050,8 +1068,34 @@ top:
|
||||||
int64 wait = getPoissonRand(thread, throttle_delay);
|
int64 wait = getPoissonRand(thread, throttle_delay);
|
||||||
|
|
||||||
thread->throttle_trigger += wait;
|
thread->throttle_trigger += wait;
|
||||||
|
|
||||||
st->txn_scheduled = thread->throttle_trigger;
|
st->txn_scheduled = thread->throttle_trigger;
|
||||||
|
|
||||||
|
/*
|
||||||
|
* 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)
|
||||||
|
{
|
||||||
|
int64 now_us;
|
||||||
|
|
||||||
|
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)
|
||||||
|
{
|
||||||
|
thread->throttle_latency_skipped++;
|
||||||
|
|
||||||
|
if (logfile)
|
||||||
|
doLog(thread, st, logfile, &now, agg, true);
|
||||||
|
|
||||||
|
wait = getPoissonRand(thread, throttle_delay);
|
||||||
|
thread->throttle_trigger += wait;
|
||||||
|
st->txn_scheduled = thread->throttle_trigger;
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
st->sleeping = 1;
|
st->sleeping = 1;
|
||||||
st->throttling = true;
|
st->throttling = true;
|
||||||
st->is_throttled = true;
|
st->is_throttled = true;
|
||||||
|
@ -1119,12 +1163,13 @@ top:
|
||||||
if (commands[st->state + 1] == NULL)
|
if (commands[st->state + 1] == NULL)
|
||||||
{
|
{
|
||||||
/* only calculate latency if an option is used that needs it */
|
/* only calculate latency if an option is used that needs it */
|
||||||
if (progress || throttle_delay)
|
if (progress || throttle_delay || latency_limit)
|
||||||
{
|
{
|
||||||
int64 latency;
|
int64 latency;
|
||||||
|
|
||||||
if (INSTR_TIME_IS_ZERO(now))
|
if (INSTR_TIME_IS_ZERO(now))
|
||||||
INSTR_TIME_SET_CURRENT(now);
|
INSTR_TIME_SET_CURRENT(now);
|
||||||
|
|
||||||
latency = INSTR_TIME_GET_MICROSEC(now) - st->txn_scheduled;
|
latency = INSTR_TIME_GET_MICROSEC(now) - st->txn_scheduled;
|
||||||
|
|
||||||
st->txn_latencies += latency;
|
st->txn_latencies += latency;
|
||||||
|
@ -1137,11 +1182,15 @@ top:
|
||||||
* transactions, overflow would take 256 hours.
|
* transactions, overflow would take 256 hours.
|
||||||
*/
|
*/
|
||||||
st->txn_sqlats += latency * latency;
|
st->txn_sqlats += latency * latency;
|
||||||
|
|
||||||
|
/* record over the limit transactions if needed. */
|
||||||
|
if (latency_limit && latency > latency_limit)
|
||||||
|
thread->latency_late++;
|
||||||
}
|
}
|
||||||
|
|
||||||
/* record the time it took in the log */
|
/* record the time it took in the log */
|
||||||
if (logfile)
|
if (logfile)
|
||||||
doLog(thread, st, logfile, &now, agg);
|
doLog(thread, st, logfile, &now, agg, false);
|
||||||
}
|
}
|
||||||
|
|
||||||
if (commands[st->state]->type == SQL_COMMAND)
|
if (commands[st->state]->type == SQL_COMMAND)
|
||||||
|
@ -1227,7 +1276,7 @@ top:
|
||||||
}
|
}
|
||||||
|
|
||||||
/* Record transaction start time under logging, progress or throttling */
|
/* Record transaction start time under logging, progress or throttling */
|
||||||
if ((logfile || progress || throttle_delay) && st->state == 0)
|
if ((logfile || progress || throttle_delay || latency_limit) && st->state == 0)
|
||||||
{
|
{
|
||||||
INSTR_TIME_SET_CURRENT(st->txn_begin);
|
INSTR_TIME_SET_CURRENT(st->txn_begin);
|
||||||
|
|
||||||
|
@ -1605,7 +1654,8 @@ top:
|
||||||
* print log entry after completing one transaction.
|
* print log entry after completing one transaction.
|
||||||
*/
|
*/
|
||||||
static void
|
static void
|
||||||
doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg,
|
||||||
|
bool skipped)
|
||||||
{
|
{
|
||||||
double lag;
|
double lag;
|
||||||
double latency;
|
double latency;
|
||||||
|
@ -1622,7 +1672,10 @@ doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
||||||
INSTR_TIME_SET_CURRENT(*now);
|
INSTR_TIME_SET_CURRENT(*now);
|
||||||
|
|
||||||
latency = (double) (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled);
|
latency = (double) (INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled);
|
||||||
lag = (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled);
|
if (skipped)
|
||||||
|
lag = latency;
|
||||||
|
else
|
||||||
|
lag = (double) (INSTR_TIME_GET_MICROSEC(st->txn_begin) - st->txn_scheduled);
|
||||||
|
|
||||||
/* should we aggregate the results or not? */
|
/* should we aggregate the results or not? */
|
||||||
if (agg_interval > 0)
|
if (agg_interval > 0)
|
||||||
|
@ -1634,26 +1687,34 @@ doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
||||||
if (agg->start_time + agg_interval >= INSTR_TIME_GET_DOUBLE(*now))
|
if (agg->start_time + agg_interval >= INSTR_TIME_GET_DOUBLE(*now))
|
||||||
{
|
{
|
||||||
agg->cnt += 1;
|
agg->cnt += 1;
|
||||||
agg->sum_latency += latency;
|
if (skipped)
|
||||||
agg->sum2_latency += latency * latency;
|
|
||||||
|
|
||||||
/* first in this aggregation interval */
|
|
||||||
if ((agg->cnt == 1) || (latency < agg->min_latency))
|
|
||||||
agg->min_latency = latency;
|
|
||||||
|
|
||||||
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;
|
/* there is no latency to record if the transaction was skipped */
|
||||||
agg->sum2_lag += lag * lag;
|
agg->skipped += 1;
|
||||||
|
}
|
||||||
|
else
|
||||||
|
{
|
||||||
|
agg->sum_latency += latency;
|
||||||
|
agg->sum2_latency += latency * latency;
|
||||||
|
|
||||||
if ((agg->cnt == 1) || (lag < agg->min_lag))
|
/* first in this aggregation interval */
|
||||||
agg->min_lag = lag;
|
if ((agg->cnt == 1) || (latency < agg->min_latency))
|
||||||
if ((agg->cnt == 1) || (lag > agg->max_lag))
|
agg->min_latency = latency;
|
||||||
agg->max_lag = lag;
|
|
||||||
|
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
|
else
|
||||||
|
@ -1677,11 +1738,15 @@ doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
||||||
agg->min_latency,
|
agg->min_latency,
|
||||||
agg->max_latency);
|
agg->max_latency);
|
||||||
if (throttle_delay)
|
if (throttle_delay)
|
||||||
|
{
|
||||||
fprintf(logfile, " %.0f %.0f %.0f %.0f",
|
fprintf(logfile, " %.0f %.0f %.0f %.0f",
|
||||||
agg->sum_lag,
|
agg->sum_lag,
|
||||||
agg->sum2_lag,
|
agg->sum2_lag,
|
||||||
agg->min_lag,
|
agg->min_lag,
|
||||||
agg->max_lag);
|
agg->max_lag);
|
||||||
|
if (latency_limit)
|
||||||
|
fprintf(logfile, " %d", agg->skipped);
|
||||||
|
}
|
||||||
fputc('\n', logfile);
|
fputc('\n', logfile);
|
||||||
|
|
||||||
/* move to the next inteval */
|
/* move to the next inteval */
|
||||||
|
@ -1689,6 +1754,7 @@ doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
||||||
|
|
||||||
/* reset for "no transaction" intervals */
|
/* reset for "no transaction" intervals */
|
||||||
agg->cnt = 0;
|
agg->cnt = 0;
|
||||||
|
agg->skipped = 0;
|
||||||
agg->min_latency = 0;
|
agg->min_latency = 0;
|
||||||
agg->max_latency = 0;
|
agg->max_latency = 0;
|
||||||
agg->sum_latency = 0;
|
agg->sum_latency = 0;
|
||||||
|
@ -1701,10 +1767,11 @@ doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
||||||
|
|
||||||
/* reset the values to include only the current transaction. */
|
/* reset the values to include only the current transaction. */
|
||||||
agg->cnt = 1;
|
agg->cnt = 1;
|
||||||
|
agg->skipped = skipped ? 1 : 0;
|
||||||
agg->min_latency = latency;
|
agg->min_latency = latency;
|
||||||
agg->max_latency = latency;
|
agg->max_latency = latency;
|
||||||
agg->sum_latency = latency;
|
agg->sum_latency = skipped ? 0.0 : latency;
|
||||||
agg->sum2_latency = latency * latency;
|
agg->sum2_latency = skipped ? 0.0 : latency * latency;
|
||||||
agg->min_lag = lag;
|
agg->min_lag = lag;
|
||||||
agg->max_lag = lag;
|
agg->max_lag = lag;
|
||||||
agg->sum_lag = lag;
|
agg->sum_lag = lag;
|
||||||
|
@ -1717,14 +1784,23 @@ doLog(TState *thread, CState *st, FILE *logfile, instr_time *now, AggVals *agg)
|
||||||
#ifndef WIN32
|
#ifndef WIN32
|
||||||
|
|
||||||
/* This is more than we really ought to know about instr_time */
|
/* This is more than we really ought to know about instr_time */
|
||||||
fprintf(logfile, "%d %d %.0f %d %ld %ld",
|
if (skipped)
|
||||||
st->id, st->cnt, latency, st->use_file,
|
fprintf(logfile, "%d %d skipped %d %ld %ld",
|
||||||
(long) now->tv_sec, (long) now->tv_usec);
|
st->id, st->cnt, st->use_file,
|
||||||
|
(long) now->tv_sec, (long) now->tv_usec);
|
||||||
|
else
|
||||||
|
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
|
#else
|
||||||
|
|
||||||
/* On Windows, instr_time doesn't provide a timestamp anyway */
|
/* On Windows, instr_time doesn't provide a timestamp anyway */
|
||||||
fprintf(logfile, "%d %d %.0f %d 0 0",
|
if (skipped)
|
||||||
st->id, st->cnt, latency, st->use_file);
|
fprintf(logfile, "%d %d skipped %d 0 0",
|
||||||
|
st->id, st->cnt, st->use_file);
|
||||||
|
else
|
||||||
|
fprintf(logfile, "%d %d %.0f %d 0 0",
|
||||||
|
st->id, st->cnt, latency, st->use_file);
|
||||||
#endif
|
#endif
|
||||||
if (throttle_delay)
|
if (throttle_delay)
|
||||||
fprintf(logfile, " %.0f", lag);
|
fprintf(logfile, " %.0f", lag);
|
||||||
|
@ -2424,7 +2500,8 @@ printResults(int ttype, int64 normal_xacts, int nclients,
|
||||||
TState *threads, int nthreads,
|
TState *threads, int nthreads,
|
||||||
instr_time total_time, instr_time conn_total_time,
|
instr_time total_time, instr_time conn_total_time,
|
||||||
int64 total_latencies, int64 total_sqlats,
|
int64 total_latencies, int64 total_sqlats,
|
||||||
int64 throttle_lag, int64 throttle_lag_max)
|
int64 throttle_lag, int64 throttle_lag_max,
|
||||||
|
int64 throttle_latency_skipped, int64 latency_late)
|
||||||
{
|
{
|
||||||
double time_include,
|
double time_include,
|
||||||
tps_include,
|
tps_include,
|
||||||
|
@ -2463,7 +2540,17 @@ printResults(int ttype, int64 normal_xacts, int nclients,
|
||||||
normal_xacts);
|
normal_xacts);
|
||||||
}
|
}
|
||||||
|
|
||||||
if (throttle_delay || progress)
|
if (throttle_delay && latency_limit)
|
||||||
|
printf("number of transactions skipped: " INT64_FORMAT " (%.3f %%)\n",
|
||||||
|
throttle_latency_skipped,
|
||||||
|
100.0 * throttle_latency_skipped / (throttle_latency_skipped + normal_xacts));
|
||||||
|
|
||||||
|
if (latency_limit)
|
||||||
|
printf("number of transactions above the %.1f ms latency limit: " INT64_FORMAT " (%.3f %%)\n",
|
||||||
|
latency_limit / 1000.0, latency_late,
|
||||||
|
100.0 * latency_late / (throttle_latency_skipped + normal_xacts));
|
||||||
|
|
||||||
|
if (throttle_delay || progress || latency_limit)
|
||||||
{
|
{
|
||||||
/* compute and show latency average and standard deviation */
|
/* compute and show latency average and standard deviation */
|
||||||
double latency = 0.001 * total_latencies / normal_xacts;
|
double latency = 0.001 * total_latencies / normal_xacts;
|
||||||
|
@ -2578,6 +2665,7 @@ main(int argc, char **argv)
|
||||||
{"sampling-rate", required_argument, NULL, 4},
|
{"sampling-rate", required_argument, NULL, 4},
|
||||||
{"aggregate-interval", required_argument, NULL, 5},
|
{"aggregate-interval", required_argument, NULL, 5},
|
||||||
{"rate", required_argument, NULL, 'R'},
|
{"rate", required_argument, NULL, 'R'},
|
||||||
|
{"latency-limit", required_argument, NULL, 'L'},
|
||||||
{NULL, 0, NULL, 0}
|
{NULL, 0, NULL, 0}
|
||||||
};
|
};
|
||||||
|
|
||||||
|
@ -2607,6 +2695,8 @@ main(int argc, char **argv)
|
||||||
int64 total_sqlats = 0;
|
int64 total_sqlats = 0;
|
||||||
int64 throttle_lag = 0;
|
int64 throttle_lag = 0;
|
||||||
int64 throttle_lag_max = 0;
|
int64 throttle_lag_max = 0;
|
||||||
|
int64 throttle_latency_skipped = 0;
|
||||||
|
int64 latency_late = 0;
|
||||||
|
|
||||||
int i;
|
int i;
|
||||||
|
|
||||||
|
@ -2651,7 +2741,7 @@ main(int argc, char **argv)
|
||||||
state = (CState *) pg_malloc(sizeof(CState));
|
state = (CState *) pg_malloc(sizeof(CState));
|
||||||
memset(state, 0, sizeof(CState));
|
memset(state, 0, sizeof(CState));
|
||||||
|
|
||||||
while ((c = getopt_long(argc, argv, "ih:nvp:dqSNc:j:Crs:t:T:U:lf:D:F:M:P:R:", long_options, &optindex)) != -1)
|
while ((c = getopt_long(argc, argv, "ih:nvp:dqSNc:j:Crs:t:T:U:lf:D:F:M:P:R:L:", long_options, &optindex)) != -1)
|
||||||
{
|
{
|
||||||
switch (c)
|
switch (c)
|
||||||
{
|
{
|
||||||
|
@ -2848,6 +2938,18 @@ main(int argc, char **argv)
|
||||||
throttle_delay = (int64) (1000000.0 / throttle_value);
|
throttle_delay = (int64) (1000000.0 / throttle_value);
|
||||||
}
|
}
|
||||||
break;
|
break;
|
||||||
|
case 'L':
|
||||||
|
{
|
||||||
|
double limit_ms = atof(optarg);
|
||||||
|
if (limit_ms <= 0.0)
|
||||||
|
{
|
||||||
|
fprintf(stderr, "invalid latency limit: %s\n", optarg);
|
||||||
|
exit(1);
|
||||||
|
}
|
||||||
|
benchmarking_option_set = true;
|
||||||
|
latency_limit = (int64) (limit_ms * 1000);
|
||||||
|
}
|
||||||
|
break;
|
||||||
case 0:
|
case 0:
|
||||||
/* This covers long options which take no argument. */
|
/* This covers long options which take no argument. */
|
||||||
if (foreign_keys || unlogged_tables)
|
if (foreign_keys || unlogged_tables)
|
||||||
|
@ -3143,6 +3245,8 @@ main(int argc, char **argv)
|
||||||
thread->random_state[0] = random();
|
thread->random_state[0] = random();
|
||||||
thread->random_state[1] = random();
|
thread->random_state[1] = random();
|
||||||
thread->random_state[2] = random();
|
thread->random_state[2] = random();
|
||||||
|
thread->throttle_latency_skipped = 0;
|
||||||
|
thread->latency_late = 0;
|
||||||
|
|
||||||
if (is_latencies)
|
if (is_latencies)
|
||||||
{
|
{
|
||||||
|
@ -3217,6 +3321,8 @@ main(int argc, char **argv)
|
||||||
total_latencies += r->latencies;
|
total_latencies += r->latencies;
|
||||||
total_sqlats += r->sqlats;
|
total_sqlats += r->sqlats;
|
||||||
throttle_lag += r->throttle_lag;
|
throttle_lag += r->throttle_lag;
|
||||||
|
throttle_latency_skipped += r->throttle_latency_skipped;
|
||||||
|
latency_late += r->latency_late;
|
||||||
if (r->throttle_lag_max > throttle_lag_max)
|
if (r->throttle_lag_max > throttle_lag_max)
|
||||||
throttle_lag_max = r->throttle_lag_max;
|
throttle_lag_max = r->throttle_lag_max;
|
||||||
INSTR_TIME_ADD(conn_total_time, r->conn_time);
|
INSTR_TIME_ADD(conn_total_time, r->conn_time);
|
||||||
|
@ -3239,7 +3345,8 @@ main(int argc, char **argv)
|
||||||
INSTR_TIME_SUBTRACT(total_time, start_time);
|
INSTR_TIME_SUBTRACT(total_time, start_time);
|
||||||
printResults(ttype, total_xacts, nclients, threads, nthreads,
|
printResults(ttype, total_xacts, nclients, threads, nthreads,
|
||||||
total_time, conn_total_time, total_latencies, total_sqlats,
|
total_time, conn_total_time, total_latencies, total_sqlats,
|
||||||
throttle_lag, throttle_lag_max);
|
throttle_lag, throttle_lag_max, throttle_latency_skipped,
|
||||||
|
latency_late);
|
||||||
|
|
||||||
return 0;
|
return 0;
|
||||||
}
|
}
|
||||||
|
@ -3264,7 +3371,8 @@ threadRun(void *arg)
|
||||||
int64 last_count = 0,
|
int64 last_count = 0,
|
||||||
last_lats = 0,
|
last_lats = 0,
|
||||||
last_sqlats = 0,
|
last_sqlats = 0,
|
||||||
last_lags = 0;
|
last_lags = 0,
|
||||||
|
last_skipped = 0;
|
||||||
|
|
||||||
AggVals aggs;
|
AggVals aggs;
|
||||||
|
|
||||||
|
@ -3467,7 +3575,8 @@ threadRun(void *arg)
|
||||||
/* generate and show report */
|
/* generate and show report */
|
||||||
int64 count = 0,
|
int64 count = 0,
|
||||||
lats = 0,
|
lats = 0,
|
||||||
sqlats = 0;
|
sqlats = 0,
|
||||||
|
skipped = 0;
|
||||||
int64 lags = thread->throttle_lag;
|
int64 lags = thread->throttle_lag;
|
||||||
int64 run = now - last_report;
|
int64 run = now - last_report;
|
||||||
double tps,
|
double tps,
|
||||||
|
@ -3490,23 +3599,26 @@ threadRun(void *arg)
|
||||||
sqlat = 1.0 * (sqlats - last_sqlats) / (count - last_count);
|
sqlat = 1.0 * (sqlats - last_sqlats) / (count - last_count);
|
||||||
stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
|
stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
|
||||||
lag = 0.001 * (lags - last_lags) / (count - last_count);
|
lag = 0.001 * (lags - last_lags) / (count - last_count);
|
||||||
|
skipped = thread->throttle_latency_skipped - last_skipped;
|
||||||
|
|
||||||
|
fprintf(stderr,
|
||||||
|
"progress %d: %.1f s, %.1f tps, "
|
||||||
|
"lat %.3f ms stddev %.3f",
|
||||||
|
thread->tid, total_run, tps, latency, stdev);
|
||||||
if (throttle_delay)
|
if (throttle_delay)
|
||||||
fprintf(stderr,
|
{
|
||||||
"progress %d: %.1f s, %.1f tps, "
|
fprintf(stderr, ", lag %.3f ms", lag);
|
||||||
"lat %.3f ms stddev %.3f, lag %.3f ms\n",
|
if (latency_limit)
|
||||||
thread->tid, total_run, tps, latency, stdev, lag);
|
fprintf(stderr, ", skipped " INT64_FORMAT, skipped);
|
||||||
else
|
}
|
||||||
fprintf(stderr,
|
fprintf(stderr, "\n");
|
||||||
"progress %d: %.1f s, %.1f tps, "
|
|
||||||
"lat %.3f ms stddev %.3f\n",
|
|
||||||
thread->tid, total_run, tps, latency, stdev);
|
|
||||||
|
|
||||||
last_count = count;
|
last_count = count;
|
||||||
last_lats = lats;
|
last_lats = lats;
|
||||||
last_sqlats = sqlats;
|
last_sqlats = sqlats;
|
||||||
last_lags = lags;
|
last_lags = lags;
|
||||||
last_report = now;
|
last_report = now;
|
||||||
|
last_skipped = thread->throttle_latency_skipped;
|
||||||
next_report += (int64) progress *1000000;
|
next_report += (int64) progress *1000000;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
@ -3525,7 +3637,8 @@ threadRun(void *arg)
|
||||||
int64 count = 0,
|
int64 count = 0,
|
||||||
lats = 0,
|
lats = 0,
|
||||||
sqlats = 0,
|
sqlats = 0,
|
||||||
lags = 0;
|
lags = 0,
|
||||||
|
skipped = 0;
|
||||||
int64 run = now - last_report;
|
int64 run = now - last_report;
|
||||||
double tps,
|
double tps,
|
||||||
total_run,
|
total_run,
|
||||||
|
@ -3550,23 +3663,26 @@ threadRun(void *arg)
|
||||||
sqlat = 1.0 * (sqlats - last_sqlats) / (count - last_count);
|
sqlat = 1.0 * (sqlats - last_sqlats) / (count - last_count);
|
||||||
stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
|
stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
|
||||||
lag = 0.001 * (lags - last_lags) / (count - last_count);
|
lag = 0.001 * (lags - last_lags) / (count - last_count);
|
||||||
|
skipped = thread->throttle_latency_skipped - last_skipped;
|
||||||
|
|
||||||
|
fprintf(stderr,
|
||||||
|
"progress: %.1f s, %.1f tps, "
|
||||||
|
"lat %.3f ms stddev %.3f",
|
||||||
|
total_run, tps, latency, stdev);
|
||||||
if (throttle_delay)
|
if (throttle_delay)
|
||||||
fprintf(stderr,
|
{
|
||||||
"progress: %.1f s, %.1f tps, "
|
fprintf(stderr, ", lag %.3f ms", lag);
|
||||||
"lat %.3f ms stddev %.3f, lag %.3f ms\n",
|
if (latency_limit)
|
||||||
total_run, tps, latency, stdev, lag);
|
fprintf(stderr, ", " INT64_FORMAT " skipped", skipped);
|
||||||
else
|
}
|
||||||
fprintf(stderr,
|
fprintf(stderr, "\n");
|
||||||
"progress: %.1f s, %.1f tps, "
|
|
||||||
"lat %.3f ms stddev %.3f\n",
|
|
||||||
total_run, tps, latency, stdev);
|
|
||||||
|
|
||||||
last_count = count;
|
last_count = count;
|
||||||
last_lats = lats;
|
last_lats = lats;
|
||||||
last_sqlats = sqlats;
|
last_sqlats = sqlats;
|
||||||
last_lags = lags;
|
last_lags = lags;
|
||||||
last_report = now;
|
last_report = now;
|
||||||
|
last_skipped = thread->throttle_latency_skipped;
|
||||||
next_report += (int64) progress *1000000;
|
next_report += (int64) progress *1000000;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
@ -3587,6 +3703,9 @@ done:
|
||||||
}
|
}
|
||||||
result->throttle_lag = thread->throttle_lag;
|
result->throttle_lag = thread->throttle_lag;
|
||||||
result->throttle_lag_max = thread->throttle_lag_max;
|
result->throttle_lag_max = thread->throttle_lag_max;
|
||||||
|
result->throttle_latency_skipped = thread->throttle_latency_skipped;
|
||||||
|
result->latency_late = thread->latency_late;
|
||||||
|
|
||||||
INSTR_TIME_SET_CURRENT(end);
|
INSTR_TIME_SET_CURRENT(end);
|
||||||
INSTR_TIME_ACCUM_DIFF(result->conn_time, end, start);
|
INSTR_TIME_ACCUM_DIFF(result->conn_time, end, start);
|
||||||
if (logfile)
|
if (logfile)
|
||||||
|
|
|
@ -344,6 +344,24 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
|
||||||
</listitem>
|
</listitem>
|
||||||
</varlistentry>
|
</varlistentry>
|
||||||
|
|
||||||
|
<varlistentry>
|
||||||
|
<term><option>-L</option> <replaceable>limit</></term>
|
||||||
|
<term><option>--latency-limit=</option><replaceable>limit</></term>
|
||||||
|
<listitem>
|
||||||
|
<para>
|
||||||
|
Transaction which last more than <replaceable>limit</> milliseconds
|
||||||
|
are counted and reported separately, as <firstterm>late</>.
|
||||||
|
</para>
|
||||||
|
<para>
|
||||||
|
When throttling is used (<option>--rate=...</>), transactions that
|
||||||
|
lag behind schedule by more than <replaceable>limit</> ms, and thus
|
||||||
|
have no hope of meeting the latency limit, are not sent to the server
|
||||||
|
at all. They are counted and reported separately as
|
||||||
|
<firstterm>skipped</>.
|
||||||
|
</para>
|
||||||
|
</listitem>
|
||||||
|
</varlistentry>
|
||||||
|
|
||||||
<varlistentry>
|
<varlistentry>
|
||||||
<term><option>-M</option> <replaceable>querymode</></term>
|
<term><option>-M</option> <replaceable>querymode</></term>
|
||||||
<term><option>--protocol=</option><replaceable>querymode</></term>
|
<term><option>--protocol=</option><replaceable>querymode</></term>
|
||||||
|
@ -453,6 +471,15 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
|
||||||
latency.
|
latency.
|
||||||
</para>
|
</para>
|
||||||
|
|
||||||
|
<para>
|
||||||
|
If <option>--latency-limit</> is used together with <option>--rate</>,
|
||||||
|
a transaction can lag behind so much that it is already over the
|
||||||
|
latency limit when the previous transaction ends, because the latency
|
||||||
|
is calculated from the scheduled start time. Such transactions are
|
||||||
|
not sent to the server, but are skipped altogether and counted
|
||||||
|
separately.
|
||||||
|
</para>
|
||||||
|
|
||||||
<para>
|
<para>
|
||||||
A high schedule lag time is an indication that the system cannot
|
A high schedule lag time is an indication that the system cannot
|
||||||
process transactions at the specified rate, with the chosen number of
|
process transactions at the specified rate, with the chosen number of
|
||||||
|
@ -940,7 +967,7 @@ END;
|
||||||
The format of the log is:
|
The format of the log is:
|
||||||
|
|
||||||
<synopsis>
|
<synopsis>
|
||||||
<replaceable>client_id</> <replaceable>transaction_no</> <replaceable>time</> <replaceable>file_no</> <replaceable>time_epoch</> <replaceable>time_us</> [<replaceable>schedule_lag</replaceable>]
|
<replaceable>client_id</> <replaceable>transaction_no</> <replaceable>time</> <replaceable>file_no</> <replaceable>time_epoch</> <replaceable>time_us</> <optional><replaceable>schedule_lag</replaceable></optional>
|
||||||
</synopsis>
|
</synopsis>
|
||||||
|
|
||||||
where <replaceable>time</> is the total elapsed transaction time in microseconds,
|
where <replaceable>time</> is the total elapsed transaction time in microseconds,
|
||||||
|
@ -950,20 +977,40 @@ END;
|
||||||
UNIX epoch format timestamp and an offset
|
UNIX epoch format timestamp and an offset
|
||||||
in microseconds (suitable for creating an ISO 8601
|
in microseconds (suitable for creating an ISO 8601
|
||||||
timestamp with fractional seconds) showing when
|
timestamp with fractional seconds) showing when
|
||||||
the transaction completed. The last field, <replaceable>schedule_lag</>, is
|
the transaction completed.
|
||||||
the difference between the transaction's scheduled start time, and the
|
Field <replaceable>schedule_lag</> is the difference between the
|
||||||
time it actually started, in microseconds. It is only present when the
|
transaction's scheduled start time, and the time it actually started, in
|
||||||
<option>--rate</> option is used.
|
microseconds. It is only present when the <option>--rate</> option is used.
|
||||||
|
The last field <replaceable>skipped_transactions</> reports the number of
|
||||||
|
transactions skipped because they were too far behind schedule. It is only
|
||||||
|
present when both options <option>--rate</> and <option>--latency-limit</>
|
||||||
|
are used.
|
||||||
</para>
|
</para>
|
||||||
|
|
||||||
<para>
|
<para>
|
||||||
Here are example outputs:
|
Here is a snippet of the log file generated:
|
||||||
<screen>
|
<screen>
|
||||||
0 199 2241 0 1175850568 995598
|
0 199 2241 0 1175850568 995598
|
||||||
0 200 2465 0 1175850568 998079
|
0 200 2465 0 1175850568 998079
|
||||||
0 201 2513 0 1175850569 608
|
0 201 2513 0 1175850569 608
|
||||||
0 202 2038 0 1175850569 2663
|
0 202 2038 0 1175850569 2663
|
||||||
</screen></para>
|
</screen>
|
||||||
|
|
||||||
|
Another example with --rate=100 and --latency-limit=5 (note the additional
|
||||||
|
<replaceable>schedule_lag</> column):
|
||||||
|
<screen>
|
||||||
|
0 81 4621 0 1412881037 912698 3005
|
||||||
|
0 82 6173 0 1412881037 914578 4304
|
||||||
|
0 83 skipped 0 1412881037 914578 5217
|
||||||
|
0 83 skipped 0 1412881037 914578 5099
|
||||||
|
0 83 4722 0 1412881037 916203 3108
|
||||||
|
0 84 4142 0 1412881037 918023 2333
|
||||||
|
0 85 2465 0 1412881037 919759 740
|
||||||
|
</screen>
|
||||||
|
In this example, transaction 82 was late, because it's latency (6.173 ms) was
|
||||||
|
over the 5 ms limit. The next two transactions were skipped, because they
|
||||||
|
were already late before they were even started.
|
||||||
|
</para>
|
||||||
|
|
||||||
<para>
|
<para>
|
||||||
When running a long test on hardware that can handle a lot of transactions,
|
When running a long test on hardware that can handle a lot of transactions,
|
||||||
|
@ -979,7 +1026,7 @@ END;
|
||||||
With the <option>--aggregate-interval</option> option, the logs use a bit different format:
|
With the <option>--aggregate-interval</option> option, the logs use a bit different format:
|
||||||
|
|
||||||
<synopsis>
|
<synopsis>
|
||||||
<replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</> [<replaceable>lag_sum</> <replaceable>lag_2_sum</> <replaceable>min_lag</> <replaceable>max_lag</>]
|
<replaceable>interval_start</> <replaceable>num_of_transactions</> <replaceable>latency_sum</> <replaceable>latency_2_sum</> <replaceable>min_latency</> <replaceable>max_latency</> <optional><replaceable>lag_sum</> <replaceable>lag_2_sum</> <replaceable>min_lag</> <replaceable>max_lag</> <optional><replaceable>skipped_transactions</></optional></optional>
|
||||||
</synopsis>
|
</synopsis>
|
||||||
|
|
||||||
where <replaceable>interval_start</> is the start of the interval (UNIX epoch
|
where <replaceable>interval_start</> is the start of the interval (UNIX epoch
|
||||||
|
@ -990,8 +1037,11 @@ END;
|
||||||
<replaceable>latency_2_sum</> is a sum of 2nd powers of latencies. The last two
|
<replaceable>latency_2_sum</> is a sum of 2nd powers of latencies. The last two
|
||||||
fields are <replaceable>min_latency</> - a minimum latency within the interval, and
|
fields are <replaceable>min_latency</> - a minimum latency within the interval, and
|
||||||
<replaceable>max_latency</> - maximum latency within the interval. A transaction is
|
<replaceable>max_latency</> - maximum latency within the interval. A transaction is
|
||||||
counted into the interval when it was committed. The last four fields,
|
counted into the interval when it was committed. The fields in the end,
|
||||||
<replaceable>lag_sum</>, <replaceable>lag_2_sum</>, <replaceable>min_lag</>, and <replaceable>max_lag</>, are only present if the --rate option is used.
|
<replaceable>lag_sum</>, <replaceable>lag_2_sum</>, <replaceable>min_lag</>,
|
||||||
|
and <replaceable>max_lag</>, are only present if the <option>--rate</>
|
||||||
|
option is used. The very last one, <replaceable>skipped_transactions</>,
|
||||||
|
is only present if the option <option>--latency-limit</> is present, too.
|
||||||
They are calculated from the time each transaction had to wait for the
|
They are calculated from the time each transaction had to wait for the
|
||||||
previous one to finish, i.e. the difference between each transaction's
|
previous one to finish, i.e. the difference between each transaction's
|
||||||
scheduled start time and the time it actually started.
|
scheduled start time and the time it actually started.
|
||||||
|
|
Loading…
Reference in New Issue