[about logging...]
Here is an attempt at updating the log features, including the aggregate
and sampling stuff, with skipped transactions under throttling.
I moved the logging stuff into a function which is called when a
transaction is skipped or finished.
From a log file format perspective, I think that "-" would be better than
"skipped".
--
Fabien.
diff --git a/contrib/pgbench/pgbench.c b/contrib/pgbench/pgbench.c
index 087e0d3..72f00d8 100644
--- a/contrib/pgbench/pgbench.c
+++ b/contrib/pgbench/pgbench.c
@@ -141,6 +141,18 @@ double sample_rate = 0.0;
int64 throttle_delay = 0;
/*
+ * Transactions which take longer that this limit are counted as late
+ * and reported as such, although they are completed anyway.
+ *
+ * When under throttling: execution time slots which are more than
+ * this late (in us) are simply skipped, and the corresponding transaction
+ * is counted as such... it is not even started;
+ * otherwise above the limit transactions are counted as such, with the latency
+ * measured wrt the transaction schedule, not its actual start.
+ */
+int64 latency_limit = 0;
+
+/*
* tablespace selection
*/
char *tablespace = NULL;
@@ -238,6 +250,8 @@ typedef struct
int64 throttle_trigger; /* previous/next throttling (us) */
int64 throttle_lag; /* total transaction lag behind throttling */
int64 throttle_lag_max; /* max transaction lag */
+ int64 throttle_latency_skipped; /* lagging transactions skipped */
+ int64 latency_late; /* late transactions */
} TState;
#define INVALID_THREAD ((pthread_t) 0)
@@ -250,6 +264,8 @@ typedef struct
int64 sqlats;
int64 throttle_lag;
int64 throttle_lag_max;
+ int64 throttle_latency_skipped;
+ int64 latency_late;
} TResult;
/*
@@ -295,6 +311,8 @@ typedef struct
double max_lag;
double sum_lag; /* sum(lag) */
double sum2_lag; /* sum(lag*lag) */
+
+ int skipped; /* skipped transactions under --rate --limit */
} AggVals;
static Command **sql_files[MAX_FILES]; /* SQL script files */
@@ -372,6 +390,10 @@ usage(void)
" -f, --file=FILENAME read transaction script from FILENAME\n"
" -j, --jobs=NUM number of threads (default: 1)\n"
" -l, --log write transaction times to log file\n"
+ " -L, --limit=NUM count transactions lasting more than NUM ms.\n"
+ " under throttling (--rate), transactions behind schedule\n"
+ " more than NUM ms are skipped, and those finishing more\n"
+ " than NUM ms after their scheduled start are counted.\n"
" -M, --protocol=simple|extended|prepared\n"
" protocol for submitting queries (default: simple)\n"
" -n, --no-vacuum do not run VACUUM before tests\n"
@@ -991,13 +1013,13 @@ void
agg_vals_init(AggVals *aggs, instr_time start)
{
/* basic counters */
- aggs->cnt = 0; /* number of transactions */
+ aggs->cnt = 0; /* number of transactions (some were possibly skipped) */
aggs->sum_latency = 0; /* SUM(latency) */
aggs->sum2_latency = 0; /* SUM(latency*latency) */
/* min and max transaction duration */
- aggs->min_latency = 0;
- aggs->max_latency = 0;
+ aggs->min_latency = -1.0;
+ aggs->max_latency = -1.0;
/* schedule lag counters */
aggs->sum_lag = 0;
@@ -1005,10 +1027,173 @@ agg_vals_init(AggVals *aggs, instr_time start)
aggs->min_lag = 0;
aggs->max_lag = 0;
+ /* skipped transactions under --rate & --limit */
+ aggs->skipped = 0;
+
/* start of the current interval */
aggs->start_time = INSTR_TIME_GET_DOUBLE(start);
}
+/* generate log
+ */
+static void doLog(TState *thread, CState *st, FILE *logfile, AggVals *agg, bool skipped)
+{
+ /*
+ * write the log entry if this row belongs to the random sample,
+ * or no sampling rate was given which means log everything.
+ */
+ if (sample_rate == 0.0 ||
+ pg_erand48(thread->random_state) <= sample_rate)
+ {
+ double lag;
+ double latency;
+ instr_time now;
+
+ INSTR_TIME_SET_CURRENT(now);
+
+ latency = skipped? -1.0: (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)
+ {
+ /*
+ * are we still in the same interval? if yes, accumulate
+ * the values (print them otherwise)
+ */
+ if (agg->start_time + agg_interval >= INSTR_TIME_GET_DOUBLE(now))
+ {
+ agg->cnt += 1;
+ if (skipped)
+ agg->skipped += 1;
+ else
+ {
+ /* there is no latency to record if the transaction was skipped */
+ agg->sum_latency += latency;
+ agg->sum2_latency += latency * latency;
+
+ /* first non-skipped in this aggregation interval */
+ if ((agg->min_latency == -1.0) || (latency < agg->min_latency))
+ agg->min_latency = latency;
+
+ if ((agg->max_latency == -1.0) || (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
+ {
+ /*
+ * Loop until we reach the interval of the current
+ * transaction (and print all the empty intervals in
+ * between).
+ */
+ while (agg->start_time + agg_interval < INSTR_TIME_GET_DOUBLE(now))
+ {
+ /*
+ * This is a non-Windows branch (thanks to the
+ * 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",
+ agg->start_time,
+ agg->cnt,
+ 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);
+ if (latency_limit)
+ fprintf(logfile, " %d", agg->skipped);
+ }
+ 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_latency = -1.0;
+ agg->max_latency = -1.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;
+ agg->skipped = 0;
+ }
+
+ /*
+ * and now update the reset values (include the
+ * current)
+ */
+ agg->cnt = 1;
+ agg->skipped = skipped? 1: 0;
+ agg->min_latency = latency;
+ agg->max_latency = latency;
+ agg->sum_latency = skipped? 0.0: latency;
+ agg->sum2_latency = skipped? 0.0: latency * latency;
+ agg->min_lag = lag;
+ agg->max_lag = lag;
+ agg->sum_lag = lag;
+ agg->sum2_lag = lag * lag;
+ }
+ }
+ else
+ {
+ /* no, print raw transactions */
+#ifndef WIN32
+
+ /*
+ * This is more than we really ought to know about
+ * instr_time
+ */
+ if (skipped)
+ fprintf(logfile, "%d %d skipped %d %ld %ld",
+ 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
+
+ /*
+ * On Windows, instr_time doesn't provide a timestamp
+ * anyway
+ */
+ if (skipped)
+ 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, usec, st->use_file);
+#endif
+ if (throttle_delay)
+ fprintf(logfile, " %.0f", lag);
+ fputc('\n', logfile);
+ }
+ }
+}
+
+
/* return false iff client should be disconnected */
static bool
doCustom(TState *thread, CState *st, instr_time *conn_time, FILE *logfile, AggVals *agg)
@@ -1038,6 +1223,27 @@ top:
thread->throttle_trigger += wait;
+ if (latency_limit)
+ {
+ instr_time now;
+ int64 now_us;
+ INSTR_TIME_SET_CURRENT(now);
+ now_us = INSTR_TIME_GET_MICROSEC(now);
+ while (thread->throttle_trigger < now_us - latency_limit)
+ {
+ /* if too far behind, this slot is skipped, and we
+ * iterate till the next nearly on time slot.
+ */
+ int64 wait = getPoissonRand(thread, throttle_delay);
+ thread->throttle_trigger += wait;
+ thread->throttle_latency_skipped ++;
+
+ /* record in log if required */
+ if (logfile)
+ doLog(thread, st, logfile, agg, true);
+ }
+ }
+
st->txn_scheduled = thread->throttle_trigger;
st->sleeping = 1;
st->throttling = true;
@@ -1110,8 +1316,11 @@ top:
thread->exec_count[cnum]++;
}
- /* transaction finished: record latency under progress or throttling */
- if ((progress || throttle_delay) && commands[st->state + 1] == NULL)
+ /* transaction finished: record latency under progress or throttling,
+ * or if latency limit is set
+ */
+ if ((progress || throttle_delay || latency_limit) &&
+ commands[st->state + 1] == NULL)
{
int64 latency;
@@ -1133,149 +1342,18 @@ top:
* would take 256 hours.
*/
st->txn_sqlats += latency * latency;
+
+ /* record over the limit transactions if needed.
+ */
+ if (latency_limit && latency > latency_limit)
+ thread->latency_late++;
}
/*
* if transaction finished, record the time it took in the log
*/
if (logfile && commands[st->state + 1] == NULL)
- {
- double lag;
- double latency;
-
- /*
- * write the log entry if this row belongs to the random sample,
- * or no sampling rate was given which means log everything.
- */
- if (sample_rate == 0.0 ||
- pg_erand48(thread->random_state) <= sample_rate)
- {
- 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)
- {
- /*
- * are we still in the same interval? if yes, accumulate
- * the values (print them otherwise)
- */
- if (agg->start_time + agg_interval >= INSTR_TIME_GET_DOUBLE(now))
- {
- agg->cnt += 1;
- agg->sum_latency += latency;
- 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;
- 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
- {
- /*
- * Loop until we reach the interval of the current
- * transaction (and print all the empty intervals in
- * between).
- */
- while (agg->start_time + agg_interval < INSTR_TIME_GET_DOUBLE(now))
- {
- /*
- * This is a non-Windows branch (thanks to the
- * 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",
- agg->start_time,
- agg->cnt,
- 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_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;
- }
-
- /*
- * and now update the reset values (include the
- * current)
- */
- agg->cnt = 1;
- 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
- {
- /* no, print raw transactions */
-#ifndef WIN32
-
- /*
- * This is more than we really ought to know about
- * instr_time
- */
- 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
-
- /*
- * On Windows, instr_time doesn't provide a timestamp
- * anyway
- */
- fprintf(logfile, "%d %d %.0f %d 0 0",
- st->id, st->cnt, latency, st->use_file);
-#endif
- if (throttle_delay)
- fprintf(logfile, " %.0f", lag);
- fputc('\n', logfile);
- }
- }
- }
+ doLog(thread, st, logfile, agg, false);
if (commands[st->state]->type == SQL_COMMAND)
{
@@ -1360,7 +1438,7 @@ top:
}
/* 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);
@@ -2426,7 +2504,8 @@ printResults(int ttype, int64 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)
+ int64 throttle_lag, int64 throttle_lag_max,
+ int64 throttle_latency_skipped, int64 latency_late)
{
double time_include,
tps_include,
@@ -2465,7 +2544,17 @@ printResults(int ttype, int64 normal_xacts, int nclients,
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 */
double latency = 0.001 * total_latencies / normal_xacts;
@@ -2483,7 +2572,6 @@ printResults(int ttype, int64 normal_xacts, int nclients,
}
if (throttle_delay)
- {
/*
* Report average transaction lag under rate limit throttling. This
* is the delay between scheduled and actual start times for the
@@ -2492,7 +2580,6 @@ printResults(int ttype, int64 normal_xacts, int nclients,
*/
printf("rate limit schedule lag: avg %.3f (max %.3f) ms\n",
0.001 * throttle_lag / normal_xacts, 0.001 * throttle_lag_max);
- }
printf("tps = %f (including connections establishing)\n", tps_include);
printf("tps = %f (excluding connections establishing)\n", tps_exclude);
@@ -2580,6 +2667,7 @@ main(int argc, char **argv)
{"sampling-rate", required_argument, NULL, 4},
{"aggregate-interval", required_argument, NULL, 5},
{"rate", required_argument, NULL, 'R'},
+ {"limit", required_argument, NULL, 'L'},
{NULL, 0, NULL, 0}
};
@@ -2609,6 +2697,8 @@ main(int argc, char **argv)
int64 total_sqlats = 0;
int64 throttle_lag = 0;
int64 throttle_lag_max = 0;
+ int64 throttle_latency_skipped = 0;
+ int64 latency_late = 0;
int i;
@@ -2653,7 +2743,7 @@ main(int argc, char **argv)
state = (CState *) pg_malloc(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)
{
@@ -2850,6 +2940,18 @@ main(int argc, char **argv)
throttle_delay = (int64) (1000000.0 / throttle_value);
}
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:
/* This covers long options which take no argument. */
if (foreign_keys || unlogged_tables)
@@ -3145,6 +3247,8 @@ main(int argc, char **argv)
thread->random_state[0] = random();
thread->random_state[1] = random();
thread->random_state[2] = random();
+ thread->throttle_latency_skipped = 0;
+ thread->latency_late = 0;
if (is_latencies)
{
@@ -3219,6 +3323,8 @@ main(int argc, char **argv)
total_latencies += r->latencies;
total_sqlats += r->sqlats;
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)
throttle_lag_max = r->throttle_lag_max;
INSTR_TIME_ADD(conn_total_time, r->conn_time);
@@ -3241,7 +3347,8 @@ main(int argc, char **argv)
INSTR_TIME_SUBTRACT(total_time, start_time);
printResults(ttype, total_xacts, nclients, threads, nthreads,
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;
}
@@ -3266,7 +3373,8 @@ threadRun(void *arg)
int64 last_count = 0,
last_lats = 0,
last_sqlats = 0,
- last_lags = 0;
+ last_lags = 0,
+ last_skipped = 0;
AggVals aggs;
@@ -3469,7 +3577,8 @@ threadRun(void *arg)
/* generate and show report */
int64 count = 0,
lats = 0,
- sqlats = 0;
+ sqlats = 0,
+ skipped = 0;
int64 lags = thread->throttle_lag;
int64 run = now - last_report;
double tps,
@@ -3492,23 +3601,26 @@ threadRun(void *arg)
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);
+ 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)
- fprintf(stderr,
- "progress %d: %.1f s, %.1f tps, "
- "lat %.3f ms stddev %.3f, lag %.3f ms\n",
- thread->tid, total_run, tps, latency, stdev, lag);
- else
- fprintf(stderr,
- "progress %d: %.1f s, %.1f tps, "
- "lat %.3f ms stddev %.3f\n",
- thread->tid, total_run, tps, latency, stdev);
+ {
+ fprintf(stderr, ", lag %.3f ms", lag);
+ if (latency_limit)
+ fprintf(stderr, ", " INT64_FORMAT " skipped", skipped);
+ }
+ fprintf(stderr, "\n");
last_count = count;
last_lats = lats;
last_sqlats = sqlats;
last_lags = lags;
last_report = now;
+ last_skipped = thread->throttle_latency_skipped;
next_report += (int64) progress *1000000;
}
}
@@ -3527,7 +3639,8 @@ threadRun(void *arg)
int64 count = 0,
lats = 0,
sqlats = 0,
- lags = 0;
+ lags = 0,
+ skipped = 0;
int64 run = now - last_report;
double tps,
total_run,
@@ -3552,23 +3665,26 @@ threadRun(void *arg)
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);
+ 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)
- fprintf(stderr,
- "progress: %.1f s, %.1f tps, "
- "lat %.3f ms stddev %.3f, lag %.3f ms\n",
- total_run, tps, latency, stdev, lag);
- else
- fprintf(stderr,
- "progress: %.1f s, %.1f tps, "
- "lat %.3f ms stddev %.3f\n",
- total_run, tps, latency, stdev);
+ {
+ fprintf(stderr, ", lag %.3f ms", lag);
+ if (latency_limit)
+ fprintf(stderr, ", " INT64_FORMAT " skipped", skipped);
+ }
+ fprintf(stderr, "\n");
last_count = count;
last_lats = lats;
last_sqlats = sqlats;
last_lags = lags;
last_report = now;
+ last_skipped = thread->throttle_latency_skipped;
next_report += (int64) progress *1000000;
}
}
@@ -3589,6 +3705,9 @@ done:
}
result->throttle_lag = thread->throttle_lag;
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_ACCUM_DIFF(result->conn_time, end, start);
if (logfile)
diff --git a/doc/src/sgml/pgbench.sgml b/doc/src/sgml/pgbench.sgml
index c4e0cbd..d3e8985 100644
--- a/doc/src/sgml/pgbench.sgml
+++ b/doc/src/sgml/pgbench.sgml
@@ -345,6 +345,23 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
</varlistentry>
<varlistentry>
+ <term><option>-L</option> <replaceable>limit</></term>
+ <term><option>--limit=</option><replaceable>limit</></term>
+ <listitem>
+ <para>
+ Under normal operations, transaction which last more than
+ <replaceable>limit</> milliseconds are counted and reported.
+ </para>
+ <para>
+ Under throttling option <option>--rate=...</>, transactions behind
+ schedule by <replaceable>limit</> ms are simply skipped and counted
+ as such, then transactions finished later than the scheduled time plus
+ <replaceable>limit</> are counted and reported.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
<term><option>-M</option> <replaceable>querymode</></term>
<term><option>--protocol=</option><replaceable>querymode</></term>
<listitem>
@@ -439,7 +456,9 @@ pgbench <optional> <replaceable>options</> </optional> <replaceable>dbname</>
schedule moves forward based on when the client first started, not
when the previous transaction ended. That approach means that when
transactions go past their original scheduled end time, it is
- possible for later ones to catch up again.
+ possible for later ones to catch up again. It can be changed with
+ option <option>--limit</> which skips and counts transactions
+ late by more than this delay.
</para>
<para>
When throttling is active, the transaction latency reported at the
@@ -940,7 +959,7 @@ END;
The format of the log is:
<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</> [<replaceable>schedule_lag</replaceable> [<replaceable>skipped_transactions</>]]
</synopsis>
where <replaceable>time</> is the total elapsed transaction time in microseconds,
@@ -950,10 +969,13 @@ END;
UNIX epoch format timestamp and an offset
in microseconds (suitable for creating an ISO 8601
timestamp with fractional seconds) showing when
- the transaction completed. The last field, <replaceable>schedule_lag</>, is
- the difference between the transaction's scheduled start time, and the
- time it actually started, in microseconds. It is only present when the
- <option>--rate</> option is used.
+ the transaction completed.
+ Field <replaceable>schedule_lag</> is the difference between the transaction's
+ scheduled start time, and the time it actually started, in 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>--limit</> are used.
</para>
<para>
@@ -974,12 +996,12 @@ END;
<refsect2>
<title>Aggregated Logging</title>
-
+
<para>
With the <option>--aggregate-interval</option> option, the logs use a bit different format:
<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</> [<replaceable>lag_sum</> <replaceable>lag_2_sum</> <replaceable>min_lag</> <replaceable>max_lag</> [<replaceable>skipped_transactions</>]]
</synopsis>
where <replaceable>interval_start</> is the start of the interval (UNIX epoch
@@ -990,8 +1012,9 @@ END;
<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
<replaceable>max_latency</> - maximum latency within the interval. A transaction is
- counted into the interval when it was committed. The last four fields,
- <replaceable>lag_sum</>, <replaceable>lag_2_sum</>, <replaceable>min_lag</>, and <replaceable>max_lag</>, are only present if the --rate option is used.
+ 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 <option>--rate</> option is used.
+ The very last one <replaceable>skipped_transactions</> also requires option <option>--limit</>.
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
scheduled start time and the time it actually started.
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
