Re: pgbench: option delaying queries till connections establishment?

At Thu, 27 Feb 2020 10:51:29 -0800, Andres Freund <andres(at)anarazel(dot)de> wrote in
> Hi,
>
> On 2020-02-27 10:01:00 -0800, Andres Freund wrote:
> > If so, should this be done unconditionally? A new option? Included in an
> > existing one somehow?
>
> FWIW, leaving windows, error handling, and other annoyances aside, this
> can be implemented fairly simply. See below.
>
> As an example of the difference:
>
> Before:
> andres(at)awork3:~/build/postgres/dev-optimize/vpath$ ./src/bin/pgbench/pgbench -M prepared -c 5000 -j 100 -T 100 -P1 -S
> starting vacuum...end.
> progress: 100.4 s, 515307.4 tps, lat 1.374 ms stddev 7.739
> transaction type: <builtin: select only>
> scaling factor: 30
> query mode: prepared
> number of clients: 5000
> number of threads: 100
> duration: 100 s
> number of transactions actually processed: 51728348
> latency average = 1.374 ms
> latency stddev = 7.739 ms
> tps = 513802.541226 (including connections establishing)
> tps = 521342.427158 (excluding connections establishing)
>
>
> Note that there's no progress report until the end. That's because the
> main thread didn't get a connection until the other threads were done.
>
>
> After:
>
> pgbench -M prepared -c 5000 -j 100 -T 100 -P1 -S
> starting vacuum...end.
> progress: 1.5 s, 9943.5 tps, lat 4.795 ms stddev 14.822
> progress: 2.0 s, 380312.6 tps, lat 1.728 ms stddev 15.461
> progress: 3.0 s, 478811.1 tps, lat 2.052 ms stddev 31.687
> progress: 4.0 s, 470804.6 tps, lat 1.941 ms stddev 24.661
>
>
>
> I think this also shows that "including/excluding connections
> establishing" as well as some of the other stats reported pretty
> bogus. In the 'before' case a substantial numer of the connections had
> not yet been established until the end of the test run!

I see it useful. In most cases we don't care connection time of
pgbench. Especially in the mentioned case the result is just bogus. I
think the reason for "including/excluding connection establishing" is
not that people wants to see how long connection took to establish but
that how long the substantial work took. If each client did run with
continuously re-establishing new connections the connection time would
be useful, but actually all the connections are established at once at
the beginning.

So FWIW I prefer that the barrier is applied by default (that is, it
can be disabled) and the progress time starts at the time all clients
has been established.

> starting vacuum...end.
+ time to established 5000 connections: 1323ms
! progress: 1.0 s, 330000.5 tps, lat 2.795 ms stddev 14.822
! progress: 2.0 s, 380312.6 tps, lat 1.728 ms stddev 15.461
! progress: 3.0 s, 478811.1 tps, lat 2.052 ms stddev 31.687
! progress: 4.0 s, 470804.6 tps, lat 1.941 ms stddev 24.661
> transaction type: <builtin: select only>
> scaling factor: 30
> query mode: prepared
> number of clients: 5000
> number of threads: 100
> duration: 100 s
> number of transactions actually processed: 51728348
> latency average = 1.374 ms
> latency stddev = 7.739 ms
> tps = 513802.541226 (including connections establishing)
> tps = 521342.427158 (excluding connections establishing)

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center