Major pgbench synthetic SELECT workload regression, Ubuntu 23.04+PG15

Gregory Smith <gregsmithpgsql@gmail.com> writes:

Pushing SELECT statements at socket speeds with prepared statements is a
synthetic benchmark that normally demos big pgbench numbers. My benchmark
farm moved to Ubuntu 23.04/kernel 6.2.0-20 last month, and that test is
badly broken on the system PG15 at larger core counts, with as much as an
85% drop from expectations.
... I could use some confirmation of where this happens from
other tester's hardware and Linux kernels.

FWIW, I can't reproduce any such effect with PG HEAD on RHEL 8.8
(4.18.0 kernel) or Fedora 37 (6.2.14 kernel). Admittedly this is
with less-beefy hardware than you're using, but your graphs say
this should be obvious with even a dozen clients, and I don't
see that. I'm getting results like

$ pgbench -S -T 10 -c 16 -j 16 -M prepared pgbench
tps = 472503.628370 (without initial connection time)
$ pgbench -S -T 10 -c 16 -j 16 pgbench
tps = 297844.301319 (without initial connection time)

which is about what I'd expect.

Could it be that the breakage is Ubuntu-specific? Seems unlikely,
but ...

regards, tom lane

On Thu, Jun 8, 2023 at 3:09 PM Gregory Smith <gregsmithpgsql@gmail.com> wrote:

Pushing SELECT statements at socket speeds with prepared statements is a synthetic benchmark that normally demos big pgbench numbers. My benchmark farm moved to Ubuntu 23.04/kernel 6.2.0-20 last month, and that test is badly broken on the system PG15 at larger core counts, with as much as an 85% drop from expectations.
Attached are full scaling graphs for all 4 combinations on this AMD 32 thread 5950X, and an Intel i5-13600K with 20 threads and similar impact. The regular, unprepared sockets peak speeds took a solid hit in PG15 from this issue too. I could use some confirmation of where this happens from other tester's hardware and Linux kernels.

Since it doesn't look like you included results on pre-23x Ubuntu, I
thought I would reply with my own results using your example. I also
have a 32 thread AMD 5950X but am on Ubuntu 22.10 (kernel 5.19). I did
not see the regression you mention.

HEAD
pgbench -S -T 10 -c 32 -j 32 -M prepared -p 5432 pgbench
tps = 837819.220854 (without initial connection time)

pgbench -S -T 10 -c 32 -j 32 -M simple -p 5432 pgbench
tps = 576845.930845 (without initial connection time)

REL_15_STABLE
pgbench -S -T 10 -c 32 -j 32 -M prepared -p 5432 pgbench
tps = 794380.991666 (without initial connection time)

pgbench -S -T 10 -c 32 -j 32 -M simple -p 5432 pgbench
tps = 534358.379838 (without initial connection time)

- Melanie

Hi,

On 2023-06-08 15:08:57 -0400, Gregory Smith wrote:

Pushing SELECT statements at socket speeds with prepared statements is a
synthetic benchmark that normally demos big pgbench numbers. My benchmark
farm moved to Ubuntu 23.04/kernel 6.2.0-20 last month, and that test is
badly broken on the system PG15 at larger core counts, with as much as an
85% drop from expectations. Since this is really just a benchmark workload
the user impact is very narrow, probably zero really, but as the severity
of the problem is high we should get to the bottom of what's going on.

First round of profile data suggests the lost throughput is going here:
Overhead Shared Object Symbol
74.34% [kernel] [k] osq_lock
2.26% [kernel] [k] mutex_spin_on_owner

Could you get a profile with call graphs? We need to know what leads to all
those osq_lock calls.

perf record --call-graph dwarf -a sleep 1

or such should do the trick, if run while the workload is running.

Quick test to find if you're impacted: on the server and using sockets,
run a 10 second SELECT test with/without preparation using 1 or 2
clients/[core|thread] and see if preparation is the slower result. Here's
a PGDG PG14 on port 5434 as a baseline, next to Ubuntu 23.04's regular
PG15, all using the PG15 pgbench on AMD 5950X:

I think it's unwise to compare builds of such different vintage. The compiler
options and compiler version can have substantial effects.

$ pgbench -i -s 100 pgbench -p 5434
$ pgbench -S -T 10 -c 32 -j 32 -M prepared -p 5434 pgbench
pgbench (14.8 (Ubuntu 14.8-1.pgdg23.04+1))
tps = 1058195.197298 (without initial connection time)

I recommend also using -P1. Particularly when using unix sockets, the
specifics of how client threads and server threads are scheduled plays a huge
role. How large a role can change significantly between runs and between
fairly minor changes to how things are executed (e.g. between major PG
versions).

E.g. on my workstation (two sockets, 10 cores/20 threads each), with 32
clients, performance changes back and forth between ~600k and ~850k. Whereas
with 42 clients, it's steadily at 1.1M, with little variance.

I also have seen very odd behaviour on larger machines when
/proc/sys/kernel/sched_autogroup_enabled is set to 1.

There's been plenty of recent chatter on LKML about *osq_lock*, in January
Intel reported a 20% benchmark regression on UnixBench that might be
related. Work is still ongoing this week:

I've seen such issues in the past, primarily due to contention internal to
cgroups, when the memory controller is enabled. IIRC that could be alleviated
to a substantial degree with cgroup.memory=nokmem.

Greetings,

Andres Freund

Hi,

On 2023-06-08 15:18:07 -0700, Andres Freund wrote:

E.g. on my workstation (two sockets, 10 cores/20 threads each), with 32
clients, performance changes back and forth between ~600k and ~850k. Whereas
with 42 clients, it's steadily at 1.1M, with little variance.

FWIW, this is with linux 6.2.12, compiled by myself though.

Greetings,

Andres Freund

On Thu, Jun 8, 2023 at 6:18 PM Andres Freund <andres@anarazel.de> wrote:

Could you get a profile with call graphs? We need to know what leads to all
those osq_lock calls.
perf record --call-graph dwarf -a sleep 1
or such should do the trick, if run while the workload is running.

I'm doing something wrong because I can't find the slow part in the perf
data; I'll get back to you on this one.

I think it's unwise to compare builds of such different vintage. The
compiler
options and compiler version can have substantial effects.

I recommend also using -P1. Particularly when using unix sockets, the

specifics of how client threads and server threads are scheduled plays a
huge
role.

Fair suggestions, those graphs come out of pgbench-tools where I profile
all the latency, fast results for me are ruler flat. It's taken me several
generations of water cooling experiments to reach that point, but even that
only buys me 10 seconds before I can overload a CPU to higher latency with
tougher workloads. Here's a few seconds of slightly updated examples, now
with matching PGDG sourced 14+15 on the 5950X and with
sched_autogroup_enabled=0 too:

$ pgbench -S -T 10 -c 32 -j 32 -M prepared -p 5434 -P 1 pgbench
pgbench (14.8 (Ubuntu 14.8-1.pgdg23.04+1))
progress: 1.0 s, 1032929.3 tps, lat 0.031 ms stddev 0.004
progress: 2.0 s, 1051239.0 tps, lat 0.030 ms stddev 0.001
progress: 3.0 s, 1047528.9 tps, lat 0.030 ms stddev 0.008...
$ pgbench -S -T 10 -c 32 -j 32 -M prepared -p 5432 -P 1 pgbench
pgbench (15.3 (Ubuntu 15.3-1.pgdg23.04+1))
progress: 1.0 s, 171816.4 tps, lat 0.184 ms stddev 0.029, 0 failed
progress: 2.0 s, 173501.0 tps, lat 0.184 ms stddev 0.024, 0 failed...

On the slow runs it will even do this, watch my 5950X accomplish 0 TPS for
a second!

progress: 38.0 s, 177376.9 tps, lat 0.180 ms stddev 0.039, 0 failed
progress: 39.0 s, 35861.5 tps, lat 0.181 ms stddev 0.032, 0 failed
progress: 40.0 s, 0.0 tps, lat 0.000 ms stddev 0.000, 0 failed
progress: 41.0 s, 222.1 tps, lat 304.500 ms stddev 741.413, 0 failed
progress: 42.0 s, 101199.6 tps, lat 0.530 ms stddev 18.862, 0 failed
progress: 43.0 s, 98286.9 tps, lat 0.328 ms stddev 8.156, 0 failed

Gonna have to measure seconds/transaction if this gets any worse.

I've seen such issues in the past, primarily due to contention internal to
cgroups, when the memory controller is enabled. IIRC that could be
alleviated
to a substantial degree with cgroup.memory=nokmem.

I cannot express on-list how much I dislike everything about the cgroups
code. Let me dig up the right call graph data first and will know more
then. The thing that keeps me from chasing kernel tuning too hard is
seeing the PG14 go perfectly every time. This is a really weird one. All
the suggestions much appreciated.

Hi,

On 2023-06-08 20:20:18 -0400, Gregory Smith wrote:

On Thu, Jun 8, 2023 at 6:18 PM Andres Freund <andres@anarazel.de> wrote:

Could you get a profile with call graphs? We need to know what leads to all
those osq_lock calls.
perf record --call-graph dwarf -a sleep 1
or such should do the trick, if run while the workload is running.

I'm doing something wrong because I can't find the slow part in the perf
data; I'll get back to you on this one.

You might need to add --no-children to the perf report invocation, otherwise
it'll show you the call graph inverted.

- Andres

Let me start with the happy ending to this thread:

$ pgbench -S -T 10 -c 32 -j 32 -M prepared -P 1 pgbench
pgbench (15.3 (Ubuntu 15.3-1.pgdg23.04+1))
progress: 1.0 s, 1015713.0 tps, lat 0.031 ms stddev 0.007, 0 failed
progress: 2.0 s, 1083780.4 tps, lat 0.029 ms stddev 0.007, 0 failed...
progress: 8.0 s, 1084574.1 tps, lat 0.029 ms stddev 0.001, 0 failed
progress: 9.0 s, 1082665.1 tps, lat 0.029 ms stddev 0.001, 0 failed
tps = 1077739.910163 (without initial connection time)

Which even seems a whole 0.9% faster than 14 on this hardware! The wonders
never cease.

On Thu, Jun 8, 2023 at 9:21 PM Andres Freund <andres@anarazel.de> wrote:

You might need to add --no-children to the perf report invocation,
otherwise
it'll show you the call graph inverted.

My problem was not writing kernel symbols out, I was only getting addresses
for some reason. This worked:

sudo perf record -g --call-graph dwarf -d --phys-data -a sleep 1
perf report --stdio

And once I looked at the stack trace I immediately saw the problem, fixed
the config option, and this report is now closed as PEBKAC on my part.
Somehow I didn't notice the 15 installs on both systems had
log_min_duration_statement=0, and that's why the performance kept dropping
*only* on the fastest runs.

What I've learned today then is that if someone sees osq_lock in simple
perf top out on oddly slow server, it's possible they are overloading a
device writing out log file data, and leaving out the boring parts the call
trace you might see is:

EmitErrorReport
__GI___libc_write
ksys_write
__fdget_pos
mutex_lock
__mutex_lock_slowpath
__mutex_lock.constprop.0
71.20% osq_lock

Everyone was stuck trying to find the end of the log file to write to it,
and that was the entirety of the problem. Hope that call trace and info
helps out some future goofball making the same mistake. I'd wager this
will come up again.

Thanks to everyone who helped out and I'm looking forward to PG16 testing
now that I have this rusty, embarrassing warm-up out of the way.

--
Greg Smith greg.smith@crunchydata.com
Director of Open Source Strategy

On Fri, Jun 9, 2023 at 12:28 AM Gregory Smith <gregsmithpgsql@gmail.com> wrote:

Let me start with the happy ending to this thread:

Phew! I'm sure everyone would be relieved to know this was a false alarm.

On Thu, Jun 8, 2023 at 9:21 PM Andres Freund <andres@anarazel.de> wrote:

You might need to add --no-children to the perf report invocation, otherwise
it'll show you the call graph inverted.

My problem was not writing kernel symbols out, I was only getting addresses for some reason. This worked:

sudo perf record -g --call-graph dwarf -d --phys-data -a sleep 1
perf report --stdio

There is no mention of perf or similar utilities in pgbench-tools
docs. I'm guessing Linux is the primary platform pgbench-tools gets
used on most. If so, I think it'd be useful to mention these tools and
snippets in there to make others lives easier, when they find
themselves scratching heads.

Best regards,
Gurjeet
http://Gurje.et

On Fri, Jun 9, 2023 at 4:06 AM Gurjeet Singh <gurjeet@singh.im> wrote:

There is no mention of perf or similar utilities in pgbench-tools
docs. I'm guessing Linux is the primary platform pgbench-tools gets
used on most. If so, I think it'd be useful to mention these tools and
snippets in there to make others lives easier.

That's a good idea. I've written out guides multiple times for customers
who are crashing and need to learn about stack traces, to help them becomes
self-sufficient with the troubleshooting parts it's impractical for me to
do for them. If I can talk people through gdb, I can teach them perf. I
have a lot of time to work on pgbench-tools set aside this summer, gonna
finally deprecate the gnuplot backend and make every graph as nice as the
ones I shared here.

I haven't been aggressive about pushing perf because a lot of customers at
Crunchy--a disproportionately larger number than typical I suspect--have
operations restrictions that just don't allow DBAs direct access to a
server's command line. So perf commands are just out of reach before we
even get to the permissions it requires. I may have to do something really
wild to help them, like see if the right permissions setup would allow
PL/python3 or similar to orchestrate a perf session in a SQL function.

On Fri, Jun 9, 2023 at 3:28 AM Gregory Smith <gregsmithpgsql@gmail.com> wrote:

On Thu, Jun 8, 2023 at 9:21 PM Andres Freund <andres@anarazel.de> wrote:

You might need to add --no-children to the perf report invocation, otherwise
it'll show you the call graph inverted.

My problem was not writing kernel symbols out, I was only getting addresses for some reason. This worked:

sudo perf record -g --call-graph dwarf -d --phys-data -a sleep 1
perf report --stdio

Do you know why using phys-data would have solved the problem in your
particular setup? I find figuring out what perf options I need
mystifying.
I end up trying random things from
https://wiki.postgresql.org/wiki/Profiling_with_perf, the perf man
page, and https://www.brendangregg.com/perf.html

The pg wiki page actually has a lot of detail. If you think your
particular problem is something others would encounter, it could be
good to add it there.

FWIW, I think it is helpful to have hackers threads like this where
people work through unexplained performance results with others in the
community.

- Melanie