MIME-Version: 1.0
References: 
 <CACdN0M78U+GvpqA7oey-GA7fFSYM636aDp6H9FVvCztv9zXxSA@mail.gmail.com>
In-Reply-To: 
 <CACdN0M78U+GvpqA7oey-GA7fFSYM636aDp6H9FVvCztv9zXxSA@mail.gmail.com>
From: Kirk Wolak <wolakk@gmail.com>
Date: Sun, 31 May 2026 12:53:09 -0400
Message-ID: 
 <CACLU5mSNZEbLrwRLf_rsG1Y1D+JWnWKwvzwhpG73rjLjD3R1yA@mail.gmail.com>
Subject: Re: Add wait events for server logging destination writes
To: =?UTF-8?B?7Iug7ISx7KSA?= <shinsj4653@gmail.com>
Cc: pgsql-hackers@lists.postgresql.org, Andrey Borodin <x4mmm@yandex-team.ru>,
	Andreas Karlsson <andreas@proxel.se>, Nikolay Samokhvalov <nik@postgres.ai>
Content-Type: multipart/alternative; boundary="000000000000489e4706531feb97"
Archived-At: 
 <https://www.postgresql.org/message-id/CACLU5mSNZEbLrwRLf_rsG1Y1D%2BJWnWKwvzwhpG73rjLjD3R1yA%40mail.gmail.com>
Precedence: bulk

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

On Sun, May 31, 2026 at 4:50=E2=80=AFAM =EC=8B=A0=EC=84=B1=EC=A4=80 <shinsj=
4653@gmail.com> wrote:

> Hi hackers,
>
> The write(2) calls that flush server log output aren't covered by wait
> events. When a backend logs something, the writes go out in:
>
>   - write_pipe_chunks(): write(2) to the syslogger pipe
>   - write_console(): write(2) to stderr (WriteConsoleW() on Windows)
>
> If one of those blocks -- syslogger pipe full, slow console, slow log
> device -- pg_stat_activity just shows wait_event =3D NULL until it
> returns. Since NULL usually reads as "on CPU", a backend stuck writing
> logs looks like it's doing work, so logging-related stalls are easy to
> miss.
>
> Attached is a short series that adds two WaitEventIO events and reports
> them around those writes:
>
>   IO / SysloggerWrite - write(2) to the syslogger pipe
>   IO / StderrWrite - write(2) to stderr, and WriteConsoleW()
>
> 0001 adds the events and covers the write(2) paths. 0002 does the
> Windows WriteConsoleW() path, split out since it's platform-specific.
>
> It only wraps the leaf write call and uses the existing
> pgstat_report_wait_start()/end() helpers, so it stays allocation-free
> and safe to call from inside the error-reporting path.
>
> I did a quick before/after to make sure the events show up: 8 backends
> each emitting large RAISE LOG lines, sampling wait_event from
> pg_stat_activity every 50 ms for 20 s.
>
>   - logging_collector =3D on (syslogger pipe):
>     master:  NULL                100.0%  (2184/2184)
>     patched: IO/SysloggerWrite     99.1%  (2204/2224), NULL 0.9%
>
>   - logging_collector =3D off (stderr):
>     master:  NULL                100.0%  (2144/2144)
>     patched: IO/StderrWrite        90.7%  (1952/2152), NULL 9.3%
>
> On master that wait time is just invisible; with the patch it lands on
> the new events. I can send the scripts and raw samples if anyone wants
> to reproduce it.
>
+1
  Nice.  We have too many waits that are registered as CPU.

>
>

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

<div dir=3D"ltr"><div dir=3D"ltr"><div class=3D"gmail_default" style=3D"col=
or:rgb(0,0,0)"><br></div></div><br><div class=3D"gmail_quote gmail_quote_co=
ntainer"><div dir=3D"ltr" class=3D"gmail_attr">On Sun, May 31, 2026 at 4:50=
=E2=80=AFAM =EC=8B=A0=EC=84=B1=EC=A4=80 &lt;<a href=3D"mailto:shinsj4653@gm=
ail.com">shinsj4653@gmail.com</a>&gt; wrote:<br></div><blockquote class=3D"=
gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(20=
4,204,204);padding-left:1ex">Hi hackers,<br>
<br>
The write(2) calls that flush server log output aren&#39;t covered by wait<=
br>
events. When a backend logs something, the writes go out in:<br>
<br>
=C2=A0 - write_pipe_chunks(): write(2) to the syslogger pipe<br>
=C2=A0 - write_console(): write(2) to stderr (WriteConsoleW() on Windows)<b=
r>
<br>
If one of those blocks -- syslogger pipe full, slow console, slow log<br>
device -- pg_stat_activity just shows wait_event =3D NULL until it<br>
returns. Since NULL usually reads as &quot;on CPU&quot;, a backend stuck wr=
iting<br>
logs looks like it&#39;s doing work, so logging-related stalls are easy to<=
br>
miss.<br>
<br>
Attached is a short series that adds two WaitEventIO events and reports<br>
them around those writes:<br>
<br>
=C2=A0 IO / SysloggerWrite - write(2) to the syslogger pipe<br>
=C2=A0 IO / StderrWrite - write(2) to stderr, and WriteConsoleW()<br>
<br>
0001 adds the events and covers the write(2) paths. 0002 does the<br>
Windows WriteConsoleW() path, split out since it&#39;s platform-specific.<b=
r>
<br>
It only wraps the leaf write call and uses the existing<br>
pgstat_report_wait_start()/end() helpers, so it stays allocation-free<br>
and safe to call from inside the error-reporting path.<br>
<br>
I did a quick before/after to make sure the events show up: 8 backends<br>
each emitting large RAISE LOG lines, sampling wait_event from<br>
pg_stat_activity every 50 ms for 20 s.<br>
<br>
=C2=A0 - logging_collector =3D on (syslogger pipe):<br>
=C2=A0 =C2=A0 master:=C2=A0 NULL=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =
=C2=A0 =C2=A0 100.0%=C2=A0 (2184/2184)<br>
=C2=A0 =C2=A0 patched: IO/SysloggerWrite=C2=A0 =C2=A0 =C2=A099.1%=C2=A0 (22=
04/2224), NULL 0.9%<br>
<br>
=C2=A0 - logging_collector =3D off (stderr):<br>
=C2=A0 =C2=A0 master:=C2=A0 NULL=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =
=C2=A0 =C2=A0 100.0%=C2=A0 (2144/2144)<br>
=C2=A0 =C2=A0 patched: IO/StderrWrite=C2=A0 =C2=A0 =C2=A0 =C2=A0 90.7%=C2=
=A0 (1952/2152), NULL 9.3%<br>
<br>
On master that wait time is just invisible; with the patch it lands on<br>
the new events. I can send the scripts and raw samples if anyone wants<br>
to reproduce it.<br></blockquote><div><span class=3D"gmail_default" style=
=3D"color:rgb(0,0,0)">+1</span></div><div class=3D"gmail_default" style=3D"=
color:rgb(0,0,0)">=C2=A0 Nice.=C2=A0 We have too many waits that are regist=
ered as CPU.</div><blockquote class=3D"gmail_quote" style=3D"margin:0px 0px=
 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><br>
</blockquote></div></div>

--000000000000489e4706531feb97--