Re: pgbench progress report improvements - split 3 v2

> Split 3 of the initial submission, which actually deal with data measured and
> reported on stderr under various options.
>
> This version currently takes into account many comments by Noah Mish. In
> particular, the default "no report" behavior under benchmarking is not
> changed, although I really think that it should. Also, the standard deviation
> is only shown when available, which is not in under all settings, because of
> concerns expressed about the cost of additional calls to gettimeofday. ISTM
> that these concerned are misplaced in this particular case.

Yet another version to fulfill requirements by Robert Haas not to change
current default behaviors. The initialization progress is reported every
100-k rows, and there is no progress report for benchmarking.

Improve pgbench measurements & progress report

These changes are coupled because measures are changed, and their
reporting as well. Submitting separate patches for these different
features would result in conflicting or dependent patches, so I
wish to avoid that if possible.

- Use same progress and quiet options both under init & bench.

However, the default reporting is NOT changed, as required by
Robert Haas. It is currently every 100k rows when initializing,
and nothing when benchmarking.

I would suggest to change this default to a few seconds for both.
The 100-k row report is very verbose an unreadable on good hardware.
For benchmarking, the rational is that it is error prone as it must
run a long time to be significant because of warmup effects (esp on HDD,
less true on SSD). Seeing how the current performance evolve would
help pgbench users realise that. See down below a sample output.

- Measure transaction latency instead of computing it,
for --rate and --progress.

The previous computed figure does not make sense under throttling:
as sleep throttling time was included in the figures, the displayed
results were plain false.

The latency and its standard deviation are printed out under progress
and in the final report when available.

It could be made "always" available, but that would require to accept
additional gettimeofday calls. I do not think that there is a
performance issue here, but there is significant opposition to the idea.

- Take thread start time at the beginning of the thread (!)

Otherwise it includes pretty slow thread/fork system start times in
the measurements. May help with bug #8326. This also helps with throttling,
as the start time is used to adjust the rate: if it is not the actual
start time, there is a bit of a rush at the beginning in order to
catch up. Taking the start time when the thread actually starts is
the sane thing to do to avoid surprises at possibly strange measures
on short runs.

Sample output under initialization with --progress=1

creating tables...
1126000 of 3000000 tuples (37%) done (elapsed 1.00 s, remaining 1.67 s).
2106000 of 3000000 tuples (70%) done (elapsed 2.00 s, remaining 0.85 s).
2824000 of 3000000 tuples (94%) done (elapsed 3.00 s, remaining 0.19 s).
3000000 of 3000000 tuples (100%) done (elapsed 3.19 s, remaining 0.00 s).
vacuum...
set primary keys...
done.

Sample output under benchmarking with --progress=1

progress: 1.0 s, 2626.1 tps, 0.374 stddev 0.597 ms lat
progress: 2.0 s, 2766.6 tps, 0.358 stddev 0.588 ms lat
progress: 3.0 s, 2567.4 tps, 0.385 stddev 0.665 ms lat
progress: 4.0 s, 3014.2 tps, 0.328 stddev 0.593 ms lat
progress: 5.0 s, 2959.3 tps, 0.334 stddev 0.553 ms lat
...
progress: 16.0 s, 5009.2 tps, 0.197 stddev 0.381 ms lat
...
progress: 24.0 s, 7051.2 tps, 0.139 stddev 0.284 ms lat
...
progress: 50.0 s, 6860.5 tps, 0.143 stddev 0.052 ms lat
...

The "warmup" is quite fast because the DB is on a SSD. In the beginning
the standard deviation is well over the average transaction time, but
when the steady state is reached (later) it is much below.

--
Fabien.