Re: pgbench progress report improvements - split 3

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.

Improve pgbench measurements & progress report

These changes are coupled because measures are changed, and their
reporting as well. Submitting separate patches for these interlinked
features would result in conflicting or dependent patches, so I wish to
avoid that. Also it would require more reviewer time.

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

The reporting is every 5 seconds for initialization,
and currently no report for benchmarking.

I strongly suggest to change this default to 5 seconds for both,
if people do not veto any change of the default behavior...
The rational is that benchmarking 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.

The previous progress report under initialization, which printed a line
every 100,000 rows, is removed, as it is much to verbose for most
hardware, and pretty long for any significant scale.

- 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 no concensus yet.

- 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.