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
