Re: pgbench progress report improvements - split 3 - Mailing list pgsql-hackers

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
warmupeffects (esp on HDD,   less true on SSD). Seeing how the current performance evolve would   help pgbench users
realisethat. 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
muchto 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
thinkthat 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.
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.