Refactor code to print pgbench progress reports.
threadRun() function is very long and deeply-nested. Extract the code to print progress reports to a separate function, to make it slightly easier to read. Author: Fabien Coelho Discussion: https://www.postgresql.org/message-id/alpine.DEB.2.21.1903101225270.17271%40lancre
This commit is contained in:
Heikki Linnakangas
parent
5857be907d
commit
9f75e37723
@ -4893,6 +4893,99 @@ addScript(ParsedScript script)
|
|||||||
num_scripts++;
|
num_scripts++;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/*
|
||||||
|
* Print progress report.
|
||||||
|
*
|
||||||
|
* On entry, *last and *last_report contain the statistics and time of last
|
||||||
|
* progress report. On exit, they are updated with the new stats.
|
||||||
|
*/
|
||||||
|
static void
|
||||||
|
printProgressReport(TState *thread, int64 test_start, int64 now,
|
||||||
|
StatsData *last, int64 *last_report)
|
||||||
|
{
|
||||||
|
/* generate and show report */
|
||||||
|
int64 run = now - *last_report,
|
||||||
|
ntx;
|
||||||
|
double tps,
|
||||||
|
total_run,
|
||||||
|
latency,
|
||||||
|
sqlat,
|
||||||
|
lag,
|
||||||
|
stdev;
|
||||||
|
char tbuf[315];
|
||||||
|
StatsData cur;
|
||||||
|
|
||||||
|
/*
|
||||||
|
* Add up the statistics of all threads.
|
||||||
|
*
|
||||||
|
* XXX: No locking. There is no guarantee that we get an atomic snapshot
|
||||||
|
* of the transaction count and latencies, so these figures can well be
|
||||||
|
* off by a small amount. The progress report's purpose is to give a
|
||||||
|
* quick overview of how the test is going, so that shouldn't matter too
|
||||||
|
* much. (If a read from a 64-bit integer is not atomic, you might get a
|
||||||
|
* "torn" read and completely bogus latencies though!)
|
||||||
|
*/
|
||||||
|
initStats(&cur, 0);
|
||||||
|
for (int i = 0; i < nthreads; i++)
|
||||||
|
{
|
||||||
|
mergeSimpleStats(&cur.latency, &thread[i].stats.latency);
|
||||||
|
mergeSimpleStats(&cur.lag, &thread[i].stats.lag);
|
||||||
|
cur.cnt += thread[i].stats.cnt;
|
||||||
|
cur.skipped += thread[i].stats.skipped;
|
||||||
|
}
|
||||||
|
|
||||||
|
/* we count only actually executed transactions */
|
||||||
|
ntx = (cur.cnt - cur.skipped) - (last->cnt - last->skipped);
|
||||||
|
total_run = (now - test_start) / 1000000.0;
|
||||||
|
tps = 1000000.0 * ntx / run;
|
||||||
|
if (ntx > 0)
|
||||||
|
{
|
||||||
|
latency = 0.001 * (cur.latency.sum - last->latency.sum) / ntx;
|
||||||
|
sqlat = 1.0 * (cur.latency.sum2 - last->latency.sum2) / ntx;
|
||||||
|
stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
|
||||||
|
lag = 0.001 * (cur.lag.sum - last->lag.sum) / ntx;
|
||||||
|
}
|
||||||
|
else
|
||||||
|
{
|
||||||
|
latency = sqlat = stdev = lag = 0;
|
||||||
|
}
|
||||||
|
|
||||||
|
if (progress_timestamp)
|
||||||
|
{
|
||||||
|
/*
|
||||||
|
* On some platforms the current system timestamp is available in
|
||||||
|
* now_time, but rather than get entangled with that, we just eat the
|
||||||
|
* cost of an extra syscall in all cases.
|
||||||
|
*/
|
||||||
|
struct timeval tv;
|
||||||
|
|
||||||
|
gettimeofday(&tv, NULL);
|
||||||
|
snprintf(tbuf, sizeof(tbuf), "%ld.%03ld s",
|
||||||
|
(long) tv.tv_sec, (long) (tv.tv_usec / 1000));
|
||||||
|
}
|
||||||
|
else
|
||||||
|
{
|
||||||
|
/* round seconds are expected, but the thread may be late */
|
||||||
|
snprintf(tbuf, sizeof(tbuf), "%.1f s", total_run);
|
||||||
|
}
|
||||||
|
|
||||||
|
fprintf(stderr,
|
||||||
|
"progress: %s, %.1f tps, lat %.3f ms stddev %.3f",
|
||||||
|
tbuf, tps, latency, stdev);
|
||||||
|
|
||||||
|
if (throttle_delay)
|
||||||
|
{
|
||||||
|
fprintf(stderr, ", lag %.3f ms", lag);
|
||||||
|
if (latency_limit)
|
||||||
|
fprintf(stderr, ", " INT64_FORMAT " skipped",
|
||||||
|
cur.skipped - last->skipped);
|
||||||
|
}
|
||||||
|
fprintf(stderr, "\n");
|
||||||
|
|
||||||
|
*last = cur;
|
||||||
|
*last_report = now;
|
||||||
|
}
|
||||||
|
|
||||||
static void
|
static void
|
||||||
printSimpleStats(const char *prefix, SimpleStats *ss)
|
printSimpleStats(const char *prefix, SimpleStats *ss)
|
||||||
{
|
{
|
||||||
@ -6199,89 +6292,7 @@ threadRun(void *arg)
|
|||||||
now = INSTR_TIME_GET_MICROSEC(now_time);
|
now = INSTR_TIME_GET_MICROSEC(now_time);
|
||||||
if (now >= next_report)
|
if (now >= next_report)
|
||||||
{
|
{
|
||||||
/* generate and show report */
|
printProgressReport(thread, thread_start, now, &last, &last_report);
|
||||||
StatsData cur;
|
|
||||||
int64 run = now - last_report,
|
|
||||||
ntx;
|
|
||||||
double tps,
|
|
||||||
total_run,
|
|
||||||
latency,
|
|
||||||
sqlat,
|
|
||||||
lag,
|
|
||||||
stdev;
|
|
||||||
char tbuf[315];
|
|
||||||
|
|
||||||
/*
|
|
||||||
* Add up the statistics of all threads.
|
|
||||||
*
|
|
||||||
* XXX: No locking. There is no guarantee that we get an
|
|
||||||
* atomic snapshot of the transaction count and latencies, so
|
|
||||||
* these figures can well be off by a small amount. The
|
|
||||||
* progress report's purpose is to give a quick overview of
|
|
||||||
* how the test is going, so that shouldn't matter too much.
|
|
||||||
* (If a read from a 64-bit integer is not atomic, you might
|
|
||||||
* get a "torn" read and completely bogus latencies though!)
|
|
||||||
*/
|
|
||||||
initStats(&cur, 0);
|
|
||||||
for (i = 0; i < nthreads; i++)
|
|
||||||
{
|
|
||||||
mergeSimpleStats(&cur.latency, &thread[i].stats.latency);
|
|
||||||
mergeSimpleStats(&cur.lag, &thread[i].stats.lag);
|
|
||||||
cur.cnt += thread[i].stats.cnt;
|
|
||||||
cur.skipped += thread[i].stats.skipped;
|
|
||||||
}
|
|
||||||
|
|
||||||
/* we count only actually executed transactions */
|
|
||||||
ntx = (cur.cnt - cur.skipped) - (last.cnt - last.skipped);
|
|
||||||
total_run = (now - thread_start) / 1000000.0;
|
|
||||||
tps = 1000000.0 * ntx / run;
|
|
||||||
if (ntx > 0)
|
|
||||||
{
|
|
||||||
latency = 0.001 * (cur.latency.sum - last.latency.sum) / ntx;
|
|
||||||
sqlat = 1.0 * (cur.latency.sum2 - last.latency.sum2) / ntx;
|
|
||||||
stdev = 0.001 * sqrt(sqlat - 1000000.0 * latency * latency);
|
|
||||||
lag = 0.001 * (cur.lag.sum - last.lag.sum) / ntx;
|
|
||||||
}
|
|
||||||
else
|
|
||||||
{
|
|
||||||
latency = sqlat = stdev = lag = 0;
|
|
||||||
}
|
|
||||||
|
|
||||||
if (progress_timestamp)
|
|
||||||
{
|
|
||||||
/*
|
|
||||||
* On some platforms the current system timestamp is
|
|
||||||
* available in now_time, but rather than get entangled
|
|
||||||
* with that, we just eat the cost of an extra syscall in
|
|
||||||
* all cases.
|
|
||||||
*/
|
|
||||||
struct timeval tv;
|
|
||||||
|
|
||||||
gettimeofday(&tv, NULL);
|
|
||||||
snprintf(tbuf, sizeof(tbuf), "%ld.%03ld s",
|
|
||||||
(long) tv.tv_sec, (long) (tv.tv_usec / 1000));
|
|
||||||
}
|
|
||||||
else
|
|
||||||
{
|
|
||||||
/* round seconds are expected, but the thread may be late */
|
|
||||||
snprintf(tbuf, sizeof(tbuf), "%.1f s", total_run);
|
|
||||||
}
|
|
||||||
|
|
||||||
fprintf(stderr,
|
|
||||||
"progress: %s, %.1f tps, lat %.3f ms stddev %.3f",
|
|
||||||
tbuf, tps, latency, stdev);
|
|
||||||
|
|
||||||
if (throttle_delay)
|
|
||||||
{
|
|
||||||
fprintf(stderr, ", lag %.3f ms", lag);
|
|
||||||
if (latency_limit)
|
|
||||||
fprintf(stderr, ", " INT64_FORMAT " skipped",
|
|
||||||
cur.skipped - last.skipped);
|
|
||||||
}
|
|
||||||
fprintf(stderr, "\n");
|
|
||||||
|
|
||||||
last = cur;
|
|
||||||
last_report = now;
|
|
||||||
|
|
||||||
/*
|
/*
|
||||||
* Ensure that the next report is in the future, in case
|
* Ensure that the next report is in the future, in case
|
||||||
|
|||||||
Loading…
x
Reference in New Issue
Block a user