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
unreadableon good hardware.   For benchmarking, the rational is that it is error prone as it must   run a long time to
besignificant 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
thinkthat 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.
Thisalso helps with throttling,   as the start time is used to adjust the rate: if it is not the actual   start time,
thereis 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.19s).  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.