Subject: Re: Major pgbench synthetic SELECT workload regression, Ubuntu 23.04+PG15

From: Andres Freund <[email-masked]>
Date: Thu, 8 Jun 2023 15:18:07 -0700

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

---

From: Andres Freund <[email-masked]>
Date: Thu, 8 Jun 2023 15:23:13 -0700

Hi,

> 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

---

From: Gregory Smith <[email-masked]>
Date: Thu, 8 Jun 2023 20:20:18 -0400

> 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.

> 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.

> 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.

---

From: Andres Freund <[email-masked]>
Date: Thu, 8 Jun 2023 18:21:47 -0700

Hi,

> 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

---

From: Gregory Smith <[email-masked]>
Date: Fri, 9 Jun 2023 03:27:51 -0400

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.

> 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  [email-masked]
Director of Open Source Strategy

---

From: Gurjeet Singh <[email-masked]>
Date: Fri, 9 Jun 2023 01:05:43 -0700

> 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.

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

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

---

From: Gregory Smith <[email-masked]>
Date: Fri, 9 Jun 2023 08:52:33 -0400

On Fri, Jun 9, 2023 at 4:06 AM Gurjeet Singh <[email-masked]> wrote:

> 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.

---

From: Melanie Plageman <[email-masked]>
Date: Mon, 12 Jun 2023 10:28:05 -0400

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

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