pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedsomething is wonky with pgbench pipelining
5+ messages / 3 participants
[nested] [flat]
Commits from this thread:
2021-08-05 87bff68840 fa604e0dd0 pgbench: When using pipelining only do PQconsumeInput() when necessary.
* something is wonky with pgbench pipelining
@ 2021-07-20 18:00 Andres Freund <andres@anarazel.de>
0 siblings, 1 reply; 5+ messages in thread
From: Andres Freund @ 2021-07-20 18:00 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: pgsql-hackers
Hi,
I think something is slightly off with pgbench (or libpq) pipelining. Consider
e.g. the following pgbench workload:
\startpipeline
SELECT 1;
SELECT 1;
SELECT 1;
SELECT 1;
SELECT 1;
SELECT 1;
SELECT 1;
\endpipeline
A pgbench run using that results in in endless repetitions of the below:
pgbench -Mprepared -c 1 -T1000 -f ~/tmp/select1_batch.sql
sendto(3, "B\0\0\0\22\0P0_1\0\0\0\0\0\0\1\0\0D\0\0\0\6P\0E\0\0\0\t\0"..., 257, MSG_NOSIGNAL, NULL, 0) = 257
recvfrom(3, 0x5614032370f0, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "2\0\0\0\4T\0\0\0!\0\1?column?\0\0\0\0\0\0\0\0\0\0\27\0"..., 16384, 0, NULL, NULL) = 461
recvfrom(3, 0x56140323727c, 15988, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x56140323723b, 16053, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x5614032371fa, 16118, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x5614032371b9, 16183, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x561403237178, 16248, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x561403237137, 16313, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x5614032370f6, 16378, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
sendto(3, "B\0\0\0\22\0P0_1\0\0\0\0\0\0\1\0\0D\0\0\0\6P\0E\0\0\0\t\0"..., 257, MSG_NOSIGNAL, NULL, 0) = 257
recvfrom(3, 0x5614032370f0, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
ppoll([{fd=3, events=POLLIN}], 1, NULL, NULL, 8) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "2\0\0\0\4T\0\0\0!\0\1?column?\0\0\0\0\0\0\0\0\0\0\27\0"..., 16384, 0, NULL, NULL) = 461
recvfrom(3, 0x56140323727c, 15988, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x56140323723b, 16053, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x5614032371fa, 16118, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x5614032371b9, 16183, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x561403237178, 16248, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x561403237137, 16313, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(3, 0x5614032370f6, 16378, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
sendto(3, "B\0\0\0\22\0P0_1\0\0\0\0\0\0\1\0\0D\0\0\0\6P\0E\0\0\0\t\0"..., 257, MSG_NOSIGNAL, NULL, 0) = 257
Note how recvfrom() returning EAGAIN is called 7 times in a row? There's also
7 SQL statements in the workload...
I think what's happening is that the first recvfrom() actually gets all 7
connection results. The server doesn't have any queries to process at that
point. But we ask the kernel whether there is new network input over and over
again, despite having results to process!
With a short pipeline this doesn't matter much. But if it's longer, adding a
syscall for each statement in the pipeline does increase pgbench overhead
measurably. An easy way to avoid that is to put a PQisBusy() && before the
PQconsumeInput().
Comparing pgbench of 100 pipelined SELECT 1;'s, under perf stat yields:
perf stat -e task-clock,raw_syscalls:sys_enter,context-switches,cycles:u,cycles:k,instructions:u,instructions:k \
schedtool -a 38 -e \
/home/andres/build/postgres/dev-optimize/vpath/src/bin/pgbench/pgbench -n -Mprepared -c 1 -j1 -T5 -f ~/tmp/select1_batch.sql
default:
...
tps = 3617.823383 (without initial connection time)
...
1,339.25 msec task-clock # 0.267 CPUs utilized
1,880,855 raw_syscalls:sys_enter # 1.404 M/sec
18,084 context-switches # 13.503 K/sec
3,128,615,558 cycles:u # 2.336 GHz
1,211,509,367 cycles:k # 0.905 GHz
8,000,238,738 instructions:u # 2.56 insn per cycle
1,720,276,642 instructions:k # 1.42 insn per cycle
5.007540307 seconds time elapsed
1.004346000 seconds user
0.376209000 seconds sys
with-isbusy:
...
tps = 3990.424742 (without initial connection time)
...
1,013.71 msec task-clock # 0.202 CPUs utilized
80,203 raw_syscalls:sys_enter # 79.119 K/sec
19,947 context-switches # 19.677 K/sec
2,943,676,361 cycles:u # 2.904 GHz
346,607,769 cycles:k # 0.342 GHz
8,464,188,379 instructions:u # 2.88 insn per cycle
226,665,530 instructions:k # 0.65 insn per cycle
5.007539846 seconds time elapsed
0.906090000 seconds user
0.151015000 seconds sys
1.8 million fewer syscalls, reduced overall "on cpu" time, and particularly
0.27x of the system time... The user/kernel cycles/instruction split is also
illuminating.
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: something is wonky with pgbench pipelining
@ 2021-07-20 18:57 Alvaro Herrera <alvherre@alvh.no-ip.org>
parent: Andres Freund <andres@anarazel.de>
0 siblings, 1 reply; 5+ messages in thread
From: Alvaro Herrera @ 2021-07-20 18:57 UTC (permalink / raw)
To: Andres Freund <andres@anarazel.de>; +Cc: pgsql-hackers
On 2021-Jul-20, Andres Freund wrote:
> I think what's happening is that the first recvfrom() actually gets all 7
> connection results. The server doesn't have any queries to process at that
> point. But we ask the kernel whether there is new network input over and over
> again, despite having results to process!
Hmm, yeah, that seems a missed opportunity.
> with-isbusy:
> ...
> tps = 3990.424742 (without initial connection time)
> ...
> 1,013.71 msec task-clock # 0.202 CPUs utilized
> 80,203 raw_syscalls:sys_enter # 79.119 K/sec
> 19,947 context-switches # 19.677 K/sec
> 2,943,676,361 cycles:u # 2.904 GHz
> 346,607,769 cycles:k # 0.342 GHz
> 8,464,188,379 instructions:u # 2.88 insn per cycle
> 226,665,530 instructions:k # 0.65 insn per cycle
This is quite compelling.
If you don't mind I can get this pushed soon in the next couple of days
-- or do you want to do it yourself?
--
Álvaro Herrera PostgreSQL Developer — https://www.EnterpriseDB.com/
"La espina, desde que nace, ya pincha" (Proverbio africano)
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: something is wonky with pgbench pipelining
@ 2021-07-21 23:55 Andres Freund <andres@anarazel.de>
parent: Alvaro Herrera <alvherre@alvh.no-ip.org>
0 siblings, 1 reply; 5+ messages in thread
From: Andres Freund @ 2021-07-21 23:55 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; +Cc: pgsql-hackers
Hi,
On 2021-07-20 14:57:15 -0400, Alvaro Herrera wrote:
> On 2021-Jul-20, Andres Freund wrote:
>
> > I think what's happening is that the first recvfrom() actually gets all 7
> > connection results. The server doesn't have any queries to process at that
> > point. But we ask the kernel whether there is new network input over and over
> > again, despite having results to process!
>
> Hmm, yeah, that seems a missed opportunity.
> > with-isbusy:
> > ...
> > tps = 3990.424742 (without initial connection time)
> > ...
> > 1,013.71 msec task-clock # 0.202 CPUs utilized
> > 80,203 raw_syscalls:sys_enter # 79.119 K/sec
> > 19,947 context-switches # 19.677 K/sec
> > 2,943,676,361 cycles:u # 2.904 GHz
> > 346,607,769 cycles:k # 0.342 GHz
> > 8,464,188,379 instructions:u # 2.88 insn per cycle
> > 226,665,530 instructions:k # 0.65 insn per cycle
>
> This is quite compelling.
>
> If you don't mind I can get this pushed soon in the next couple of days
> -- or do you want to do it yourself?
I was thinking of pushing the attached, to both 14 and master, thinking
that was what you meant, but then I wasn't quite sure: It's a relatively
minor performance improvement, after all? OTOH, it arguably also just is
a bit of an API misuse...
I'm inclined to push it to 14 and master, but ...
Greetings,
Andres Freund
Attachments:
0001-pgbench-When-using-pipelining-only-do-PQconsumeInput.patch (text/x-diff, 1.6K) download
From 336497ae1df22b966c3b05826987eb3b374f551a Mon Sep 17 00:00:00 2001
From: Andres Freund <andres@anarazel.de>
Date: Wed, 21 Jul 2021 16:40:43 -0700
Subject: [PATCH] pgbench: When using pipelining only do PQconsumeInput() when
necessary.
Up to now we did a PQconsumeInput() for each pipelined query, asking the OS
for more input - which it often won't have, as all results might already have
been sent. That turns out to have a noticeable performance impact.
Alvaro Herrera reviewed the idea to add the PQisBusy() check, but not this
concrete patch.
Author: Andres Freund <andres@anarazel.de>
Discussion: https://postgr.es/m/20210720180039.23rivhdft3l4mayn@alap3.anarazel.de
Backpatch: 14, where libpq/pgbench pipelining was introduced.
---
src/bin/pgbench/pgbench.c | 9 ++++++++-
1 file changed, 8 insertions(+), 1 deletion(-)
diff --git a/src/bin/pgbench/pgbench.c b/src/bin/pgbench/pgbench.c
index 364b5a2e47d..129cf2ed61d 100644
--- a/src/bin/pgbench/pgbench.c
+++ b/src/bin/pgbench/pgbench.c
@@ -3460,7 +3460,14 @@ advanceConnectionState(TState *thread, CState *st, StatsData *agg)
*/
case CSTATE_WAIT_RESULT:
pg_log_debug("client %d receiving", st->id);
- if (!PQconsumeInput(st->con))
+
+ /*
+ * Only check for new network data if we processed all data
+ * fetched prior. Otherwise we end up doing a syscall for each
+ * individual pipelined query, which has a measurable
+ * performance impact.
+ */
+ if (PQisBusy(st->con) && !PQconsumeInput(st->con))
{
/* there's something wrong */
commandFailed(st, "SQL", "perhaps the backend died while processing");
--
2.32.0.rc2
* Re: something is wonky with pgbench pipelining
@ 2021-07-24 23:08 Andres Freund <andres@anarazel.de>
parent: Andres Freund <andres@anarazel.de>
0 siblings, 1 reply; 5+ messages in thread
From: Andres Freund @ 2021-07-24 23:08 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@alvh.no-ip.org>; Michael Paquier <michael@paquier.xyz>; Andrew Dunstan <andrew@dunslane.net>; Peter Geoghegan <pg@bowt.ie>; +Cc: pgsql-hackers
Hi,
Adding RMT.
On 2021-07-21 16:55:08 -0700, Andres Freund wrote:
> On 2021-07-20 14:57:15 -0400, Alvaro Herrera wrote:
> > On 2021-Jul-20, Andres Freund wrote:
> >
> > > I think what's happening is that the first recvfrom() actually gets all 7
> > > connection results. The server doesn't have any queries to process at that
> > > point. But we ask the kernel whether there is new network input over and over
> > > again, despite having results to process!
> >
> > Hmm, yeah, that seems a missed opportunity.
>
> > > with-isbusy:
> > > ...
> > > tps = 3990.424742 (without initial connection time)
> > > ...
> > > 1,013.71 msec task-clock # 0.202 CPUs utilized
> > > 80,203 raw_syscalls:sys_enter # 79.119 K/sec
> > > 19,947 context-switches # 19.677 K/sec
> > > 2,943,676,361 cycles:u # 2.904 GHz
> > > 346,607,769 cycles:k # 0.342 GHz
> > > 8,464,188,379 instructions:u # 2.88 insn per cycle
> > > 226,665,530 instructions:k # 0.65 insn per cycle
> >
> > This is quite compelling.
> >
> > If you don't mind I can get this pushed soon in the next couple of days
> > -- or do you want to do it yourself?
>
> I was thinking of pushing the attached, to both 14 and master, thinking
> that was what you meant, but then I wasn't quite sure: It's a relatively
> minor performance improvement, after all? OTOH, it arguably also just is
> a bit of an API misuse...
>
> I'm inclined to push it to 14 and master, but ...
RMT: ^
Greetings,
Andres Freund
^ permalink raw reply [nested|flat] 5+ messages in thread
* Re: something is wonky with pgbench pipelining
@ 2021-07-26 07:07 Michael Paquier <michael@paquier.xyz>
parent: Andres Freund <andres@anarazel.de>
0 siblings, 0 replies; 5+ messages in thread
From: Michael Paquier @ 2021-07-26 07:07 UTC (permalink / raw)
To: Andres Freund <andres@anarazel.de>; +Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>; Andrew Dunstan <andrew@dunslane.net>; Peter Geoghegan <pg@bowt.ie>; pgsql-hackers
On Sat, Jul 24, 2021 at 04:08:33PM -0700, Andres Freund wrote:
> On 2021-07-21 16:55:08 -0700, Andres Freund wrote:
>> I'm inclined to push it to 14 and master, but ...
>
> RMT: ^
If it were me, I think that I would have back-patched this change even
if found after the GA release of 14 as there is no advantages in
keeping the current behavior either except overloading pgbench with
unnecessary system calls. No objections from me to change that now
for 14~.
--
Michael
Attachments:
signature.asc (application/pgp-signature, 832B) download
^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2021-07-26 07:07 UTC | newest]
Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2021-07-20 18:00 something is wonky with pgbench pipelining Andres Freund <andres@anarazel.de>
2021-07-20 18:57 ` Alvaro Herrera <alvherre@alvh.no-ip.org>
2021-07-21 23:55 ` Andres Freund <andres@anarazel.de>
2021-07-24 23:08 ` Andres Freund <andres@anarazel.de>
2021-07-26 07:07 ` Michael Paquier <michael@paquier.xyz>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox