Re: pgbench - implement strict TPC-B benchmark - Mailing list pgsql-hackers

Hi,

On 2019-08-01 08:52:52 +0200, Fabien COELHO wrote:
>   sh> time pgbench -r -T 30 -M prepared
>   ...
>   latency average = 2.425 ms
>   tps = 412.394420 (including connections establishing)
>   statement latencies in milliseconds:
>     0.001  \set aid random(1, 100000 * :scale)
>     0.000  \set bid random(1, 1 * :scale)
>     0.000  \set tid random(1, 10 * :scale)
>     0.000  \set delta random(-5000, 5000)
>     0.022  BEGIN;
>     0.061  UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
>     0.038  SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
>     0.046  UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
>     0.042  UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
>     0.036  INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta,
CURRENT_TIMESTAMP);
>     2.178  END;
>   real    0m30.080s, user    0m0.406s, sys     0m0.689s
>
> The cost of pgbench interpreted part (\set) is under 1/1000.

I don't put much credence in those numbers for pgbench commands - they
don't include significant parts of the overhead of command
execution. Even just the fact that you need to process more commands
through the pretty slow pgbench interpreter has significant costs.

Using pgbench -Mprepared -n -c 8 -j 8 -S pgbench_100 -T 10 -r -P1
e.g. shows pgbench to use 189% CPU in my 4/8 core/thread laptop. That's
a pretty significant share.

And before you argue that that's just about a read-only workload:
Servers with either synchronous_commit=off, or with extremely fast WAL
commit due to BBUs/NVMe, are quite common. So you can easily get into
scenarios where pgbench overhead is an issue for read/write workloads too.

With synchronous_commit=off, I e.g. see:

$ PGOPTIONS='-c synchronous_commit=off' /usr/bin/time pgbench -Mprepared  -n -c 8 -j 8 pgbench_100 -T 10 -r
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 100
query mode: prepared
number of clients: 8
number of threads: 8
duration: 10 s
number of transactions actually processed: 179198
latency average = 0.447 ms
tps = 17892.824470 (including connections establishing)
tps = 17908.086839 (excluding connections establishing)
statement latencies in milliseconds:
         0.001  \set aid random(1, 100000 * :scale)
         0.000  \set bid random(1, 1 * :scale)
         0.000  \set tid random(1, 10 * :scale)
         0.000  \set delta random(-5000, 5000)
         0.042  BEGIN;
         0.086  UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
         0.061  SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
         0.070  UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
         0.070  UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
         0.058  INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta,
CURRENT_TIMESTAMP);
         0.054  END;
6.65user 10.64system 0:10.02elapsed 172%CPU (0avgtext+0avgdata 4588maxresident)k
0inputs+0outputs (0major+367minor)pagefaults 0swaps

And the largest part of the overhead is in pgbench's interpreter loop:
+   12.35%  pgbench  pgbench                [.] threadRun
+    4.47%  pgbench  libpq.so.5.13          [.] pqParseInput3
+    3.54%  pgbench  pgbench                [.] dopr.constprop.0
+    3.30%  pgbench  pgbench                [.] fmtint
+    3.16%  pgbench  libc-2.28.so           [.] __strcmp_avx2
+    2.95%  pgbench  libc-2.28.so           [.] malloc
+    2.95%  pgbench  libpq.so.5.13          [.] PQsendQueryPrepared
+    2.15%  pgbench  libpq.so.5.13          [.] pqPutInt
+    1.93%  pgbench  pgbench                [.] getVariable
+    1.85%  pgbench  libc-2.28.so           [.] ppoll
+    1.85%  pgbench  libc-2.28.so           [.] __strlen_avx2
+    1.85%  pgbench  libpthread-2.28.so     [.] __libc_recv
+    1.66%  pgbench  libpq.so.5.13          [.] pqPutMsgStart
+    1.63%  pgbench  libpq.so.5.13          [.] pqGetInt

And that's the just the standard pgbench read/write case, without
additional script commands or anything.


> The full time
> of the process itself counts for 1.4%, below the inevitable system time
> which is 2.3%. Pgbench overheads are pretty small compared to postgres
> connection and command execution, and system time. The above used a local
> socket, if it were an actual remote network connection, the gap would be
> larger. A profile run could collect more data, but that does not seem
> necessary.

Well, duh, that's because you're completely IO bound. You're doing
400tps. That's *nothing*. All you're measuring is how fast the WAL can
be fdatasync()ed to disk.  Of *course* pgbench isn't a relevant overhead
in that case.  I really don't understand how this can be an argument.


> Also, pgbench overheads must be compared to an actual client application,
> which deals with a database through some language (PHP, Python, JS, Java…)
> the interpreter of which would be written in C/C++ just like pgbench, and
> some library (ORM, DBI, JDBC…), possibly written in the initial language and
> relying on libpq under the hood. Ok, there could be some JIT involved, but
> it will not change that there are costs there too, and it would have to do
> pretty much the same things that pgbench is doing, plus what the application
> has to do with the data.

Uh, but those clients aren't all running on a single machine.

Greetings,

Andres Freund