pgbench rate limiting changes transaction latency computation

Hi,

I noticed that pgbench's -R influences not just the computation of lag,
but also of latency. That doesn't look right to me, but maybe I'm just
missing something?

It's quite easy to demonstrate when running pgbench with/without
progress report at a transaction rate that's around the limit of what
the server can do:

andres(at)alap4:~/src/postgresql$ pgbench -n -M prepared -c 1 -j 1 -T 100000 -P1 -r -S pgbench_10
progress: 1.0 s, 37416.3 tps, lat 0.027 ms stddev 0.013
progress: 2.0 s, 37345.1 tps, lat 0.027 ms stddev 0.011
progress: 3.0 s, 38787.8 tps, lat 0.026 ms stddev 0.009
...

andres(at)alap4:~/src/postgresql$ pgbench -n -M prepared -c 1 -j 1 -T 100000 -P1 -r -S -R 37000 pgbench_10
progress: 1.0 s, 32792.8 tps, lat 81.795 ms stddev 35.552, lag 81.765 ms
progress: 2.0 s, 37770.6 tps, lat 113.194 ms stddev 4.651, lag 113.168 ms
progress: 3.0 s, 37006.3 tps, lat 113.905 ms stddev 5.007, lag 113.878 ms

That's obviously a very different result.

ISTM that's because processXactStats() computes latency as:

latency = INSTR_TIME_GET_MICROSEC(*now) - st->txn_scheduled;

which is set differently when throttling is enabled:

/*
* When not throttling, this is also the transaction's
* scheduled start time.
*/
if (!throttle_delay)
st->txn_scheduled = INSTR_TIME_GET_MICROSEC(now);

replacing latency computation with

latency = INSTR_TIME_GET_MICROSEC(*now) - INSTR_TIME_GET_MICROSEC(st->txn_begin);

immediately makes the result make more sense:

andres(at)alap4:~/src/postgresql$ pgbench -n -M prepared -c 1 -j 1 -T 100000 -P1 -r -S -R 37000 pgbench_10
progress: 1.0 s, 37141.7 tps, lat 0.026 ms stddev 0.011, lag 1.895 ms
progress: 2.0 s, 36805.6 tps, lat 0.026 ms stddev 0.012, lag 0.670 ms
progress: 3.0 s, 37033.5 tps, lat 0.026 ms stddev 0.012, lag 1.067 ms

and you still get lag if the rate is too high:

andres(at)alap4:~/src/postgresql$ pgbench -n -M prepared -c 1 -j 1 -T 100000 -P1 -r -S -R 80000 pgbench_10
progress: 1.0 s, 37628.8 tps, lat 0.026 ms stddev 0.016, lag 287.379 ms
progress: 2.0 s, 39651.8 tps, lat 0.025 ms stddev 0.008, lag 790.527 ms
progress: 3.0 s, 39254.8 tps, lat 0.025 ms stddev 0.009, lag 1290.833 ms
progress: 4.0 s, 38859.5 tps, lat 0.026 ms stddev 0.009, lag 1808.529 ms
progress: 5.0 s, 39699.0 tps, lat 0.025 ms stddev 0.008, lag 2307.732 ms
progress: 6.0 s, 39297.0 tps, lat 0.025 ms stddev 0.009, lag 2813.291 ms
progress: 7.0 s, 39880.6 tps, lat 0.025 ms stddev 0.008, lag 3315.430 ms

Fabien, is this a bug, or am I misunderstanding something?

Greetings,

Andres Freund