MIME-Version: 1.0
References: <CAHLJuCUFGcDb1OkBcLtuWoXv5aPbWMj9uSm3q-AR3CA9CcYp_Q@mail.gmail.com>
 <20230608221807.p77h43zotlfvkg65@awork3.anarazel.de> <CAHLJuCVK9Rmxwh-0rmsrbO5-gaiOYsNCN=YE3uQ1ckQaq_YV_A@mail.gmail.com>
 <20230609012147.5j3gw2dikjf76fti@awork3.anarazel.de>
In-Reply-To: <20230609012147.5j3gw2dikjf76fti@awork3.anarazel.de>
From: Gregory Smith <gregsmithpgsql@gmail.com>
Date: Fri, 9 Jun 2023 03:27:51 -0400
Message-ID: <CAHLJuCX0NC7HOZPD-AOXjfQGE8j++sxXkLCcDkWecM_wMJoxzg@mail.gmail.com>
Subject: Re: Major pgbench synthetic SELECT workload regression, Ubuntu 23.04+PG15
To: Andres Freund <andres@anarazel.de>
Cc: PostgreSQL-development <pgsql-hackers@postgresql.org>
Content-Type: multipart/alternative; boundary="0000000000001fd32505fdad4fe8"
Archived-At: <https://www.postgresql.org/message-id/CAHLJuCX0NC7HOZPD-AOXjfQGE8j%2B%2BsxXkLCcDkWecM_wMJoxzg%40mail.gmail.com>
Precedence: bulk

--0000000000001fd32505fdad4fe8
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

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 =3D 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=E2=80=AFPM Andres Freund <andres@anarazel.de> w=
rote:

> 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=3D0, and that's why the performance kept droppin=
g
*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

--0000000000001fd32505fdad4fe8
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div>Let me start with the happy ending to this thread:<br=
></div><div><br></div><div dir=3D"ltr"><span style=3D"font-family:monospace=
">$ pgbench -S -T 10 -c 32 -j 32 -M prepared -P 1 pgbench</span><div><span =
style=3D"font-family:monospace">pgbench (15.3 (Ubuntu 15.3-1.pgdg23.04+1))<=
br>progress: 1.0 s, 1015713.0 tps, lat 0.031 ms stddev 0.007, 0 failed<br>p=
rogress: 2.0 s, 1083780.4 tps, lat 0.029 ms stddev 0.007, 0 failed...<br>pr=
ogress: 8.0 s, 1084574.1 tps, lat 0.029 ms stddev 0.001, 0 failed<br>progre=
ss: 9.0 s, 1082665.1 tps, lat 0.029 ms stddev 0.001, 0 failed</span></div><=
div><span style=3D"font-family:monospace">tps =3D 1077739.910163 (without i=
nitial connection time)</span></div><div><br></div><div>Which even seems a =
whole 0.9% faster than 14 on this hardware!=C2=A0 The wonders never cease.<=
/div><div><br></div>On Thu, Jun 8, 2023 at 9:21=E2=80=AFPM Andres Freund &l=
t;<a href=3D"mailto:andres@anarazel.de">andres@anarazel.de</a>&gt; wrote:</=
div><div class=3D"gmail_quote"><blockquote class=3D"gmail_quote" style=3D"m=
argin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left=
:1ex">You might need to add --no-children to the perf report invocation, ot=
herwise<br>
it&#39;ll show you the call graph inverted.<br></blockquote><div><br></div>=
<div>My problem was not writing kernel symbols out, I was only getting addr=
esses for some reason.=C2=A0 This worked:</div><div><br></div><div><span st=
yle=3D"font-family:monospace">=C2=A0 sudo perf record -g --call-graph dwarf=
 -d --phys-data -a sleep 1</span></div><div><span style=3D"font-family:mono=
space">=C2=A0 perf report --stdio<br></span></div><div><br></div><div>And o=
nce I looked at the stack trace I immediately saw the problem, fixed the co=
nfig option, and this report is now closed as PEBKAC on my part.=C2=A0 Some=
how I didn&#39;t notice the 15 installs on both systems had log_min_duratio=
n_statement=3D0, and that&#39;s why the performance kept dropping *only* on=
 the fastest runs.<br></div><div><br></div><div>What I&#39;ve learned today=
 then is that if someone sees osq_lock in simple perf top out on oddly slow=
 server, it&#39;s possible they are overloading a device writing out log fi=
le data, and leaving out the boring parts the call trace you might see is:<=
br></div><div><br></div><div>EmitErrorReport<br>=C2=A0__GI___libc_write<br>=
=C2=A0 ksys_write<br>=C2=A0 =C2=A0__fdget_pos<br>=C2=A0 =C2=A0 mutex_lock<b=
r>=C2=A0 =C2=A0 =C2=A0__mutex_lock_slowpath<br>=C2=A0 =C2=A0 =C2=A0 __mutex=
_lock.constprop.0<br>=C2=A0 =C2=A0 =C2=A0 =C2=A071.20% osq_lock</div><div><=
br></div><div>Everyone was stuck trying to find the end of the log file to =
write to it, and that was the entirety of the problem.=C2=A0 Hope that call=
 trace and info helps out some future goofball making the same mistake.=C2=
=A0 I&#39;d wager this will come up again.<br></div><div><br></div>Thanks t=
o everyone who helped out and I&#39;m looking forward to PG16 testing now t=
hat I have this rusty, embarrassing warm-up out of the way.</div><div class=
=3D"gmail_quote"><br></div><div class=3D"gmail_quote">--<br>Greg Smith=C2=
=A0 <a href=3D"mailto:greg.smith@crunchydata.com">greg.smith@crunchydata.co=
m</a><br>Director of Open Source Strategy</div></div>

--0000000000001fd32505fdad4fe8--