Add wait events for server logging destination writes
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 = 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 = on (syslogger pipe):
master: NULL 100.0% (2184/2184)
patched: IO/SysloggerWrite 99.1% (2204/2224), NULL 0.9%
- logging_collector = 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.
Applies on current master. A couple of things I'm unsure about and
would appreciate input on: whether the event names fit the surrounding
conventions, and whether splitting the Windows path into its own patch
is the right call.
Thanks,
Seongjun Shin
Attachments:
v1-0001-Add-wait-events-for-server-logging-destination-wr.patchapplication/octet-stream; name=v1-0001-Add-wait-events-for-server-logging-destination-wr.patchDownload+8-1
v1-0002-Report-StderrWrite-wait-event-around-WriteConsole.patchapplication/octet-stream; name=v1-0002-Report-StderrWrite-wait-event-around-WriteConsole.patchDownload+3-1
Hi,
cfbot caught a build failure on v1, in the SanityCheck task on Linux
and Windows: elog.c uses pgstat_report_wait_start()/end() and the
WAIT_EVENT_* constants but didn't include utils/wait_event.h. It only
built here because of an accidental transitive include on my machine;
on the CI images the declarations weren't visible.
v2 fixes that by adding the missing #include "utils/wait_event.h" to
elog.c, folded into 0001 so that patch builds on its own. No other
changes; the wait events and the reported write paths are the same as
in v1.
v2-0001 adds the two events and covers the write(2) paths.
v2-0002 covers the Windows WriteConsoleW() path, split out as before.
Applies cleanly on current master; full build passes locally.
Thanks,
Seongjun Shin
2026년 5월 31일 (일) 오후 5:50, 신성준 <shinsj4653@gmail.com>님이 작성:
Show quoted text
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 = 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 = on (syslogger pipe):
master: NULL 100.0% (2184/2184)
patched: IO/SysloggerWrite 99.1% (2204/2224), NULL 0.9%- logging_collector = 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.Applies on current master. A couple of things I'm unsure about and
would appreciate input on: whether the event names fit the surrounding
conventions, and whether splitting the Windows path into its own patch
is the right call.Thanks,
Seongjun Shin
Attachments:
v2-0001-Add-wait-events-for-server-logging-destination-wr.patchapplication/octet-stream; name=v2-0001-Add-wait-events-for-server-logging-destination-wr.patchDownload+9-1
v2-0002-Report-StderrWrite-wait-event-around-WriteConsole.patchapplication/octet-stream; name=v2-0002-Report-StderrWrite-wait-event-around-WriteConsole.patchDownload+3-1
On Sun, May 31, 2026 at 4:50 AM 신성준 <shinsj4653@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 = 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 = on (syslogger pipe):
master: NULL 100.0% (2184/2184)
patched: IO/SysloggerWrite 99.1% (2204/2224), NULL 0.9%- logging_collector = 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.
Show quoted text
On Sun, May 31, 2026 at 07:42:41PM +0900, 신성준 wrote:
cfbot caught a build failure on v1, in the SanityCheck task on Linux
and Windows: elog.c uses pgstat_report_wait_start()/end() and the
WAIT_EVENT_* constants but didn't include utils/wait_event.h. It only
built here because of an accidental transitive include on my machine;
on the CI images the declarations weren't visible.v2 fixes that by adding the missing #include "utils/wait_event.h" to
elog.c, folded into 0001 so that patch builds on its own. No other
changes; the wait events and the reported write paths are the same as
in v1.v2-0001 adds the two events and covers the write(2) paths.
v2-0002 covers the Windows WriteConsoleW() path, split out as before.Applies cleanly on current master; full build passes locally.
Hmm. Usually we split the event numbers so as there is one for each
code path, but here we are just dealing with the same routine that
sends chunks. Using the same numbers seem fine by me.
If others have any thoughts or comments, feel free.
--
Michael
Hello.
At Sun, 31 May 2026 17:50:08 +0900, 신성준 <shinsj4653@gmail.com> wrote in
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.
Should we also consider instrumenting ReportEventW()/ReportEventA()?
They seem to be another Windows-specific logging output path.
Also, if the intention is to cover all places where logging output can
block, I wonder whether the syslog() calls should be covered as
well. If they are intentionally excluded, perhaps a short comment
explaining the rationale would be useful.
Regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Hi,
Thanks Kirk, glad it's useful.
Kyotaro Horiguchi wrote:
Should we also consider instrumenting ReportEventW()/ReportEventA()?
They seem to be another Windows-specific logging output path.Also, if the intention is to cover all places where logging output
can block, I wonder whether the syslog() calls should be covered as
well.
Good points -- both are blocking output paths and there's no real
reason to leave them out, so v3 instruments them rather than excluding
them with a comment. The intent is exactly to cover the places where
logging output can block, so this makes the series consistent.
v3 adds two more WaitEventIO events:
IO / SyslogWrite - syslog(3) in write_syslog()
IO / EventlogWrite - ReportEventW()/ReportEventA() in write_eventlog()
Same approach as before: the wait is reported only around the leaf
call, using the existing pgstat_report_wait_start()/end() helpers, so
it stays allocation-free and safe on the error-reporting path, and the
series still touches just elog.c and wait_event_names.txt.
This also matches Michael's point on v2 -- each event covers a routine
rather than a single call site, so SyslogWrite wraps the syslog(3)
calls in write_syslog() and EventlogWrite wraps both ReportEvent
variants in write_eventlog(), the same way SysloggerWrite already
covers the two writes in write_pipe_chunks().
As before, 0001 is the portable part and 0002 is the Windows part
(WriteConsoleW plus the new EventlogWrite).
One caveat: EventlogWrite is Windows-only, so I couldn't get a runtime
before/after for it here -- I've only confirmed it builds (cfbot's
Windows task should cover that). The other events still show up in the
sampling I posted earlier. If someone on Windows can exercise the
event-log path I'd appreciate a confirmation.
Applies cleanly on current master; full build passes locally on both
Autoconf and Meson, with no new warnings.
Thanks,
Seongjun Shin
2026년 6월 1일 (월) 오후 2:49, Kyotaro Horiguchi <horikyota.ntt@gmail.com>님이 작성:
Show quoted text
Hello.
At Sun, 31 May 2026 17:50:08 +0900, 신성준 <shinsj4653@gmail.com> wrote in
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.Should we also consider instrumenting ReportEventW()/ReportEventA()?
They seem to be another Windows-specific logging output path.Also, if the intention is to cover all places where logging output can
block, I wonder whether the syslog() calls should be covered as
well. If they are intentionally excluded, perhaps a short comment
explaining the rationale would be useful.Regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Attachments:
v3-0001-Add-wait-events-for-server-logging-destination-wr.patchapplication/octet-stream; name=v3-0001-Add-wait-events-for-server-logging-destination-wr.patchDownload+14-1
v3-0002-Add-wait-events-for-Windows-specific-logging-outp.patchapplication/octet-stream; name=v3-0002-Add-wait-events-for-Windows-specific-logging-outp.patchDownload+8-1
Hi,
cfbot flagged v3 as needing a rebase -- it stopped applying after the
recent changes to elog.c (the switch to a const WCHAR pointer in
write_eventlog(), pgindent, etc.) and the new COPY pipe wait events in
wait_event_names.txt.
v4 is the same change rebased over current master, no functional
difference from v3. The only real conflict was in write_eventlog(),
where the EventlogWrite wrapping now sits on top of the const
utf16_const pointer; everything else merged cleanly.
Still applies as two patches:
v4-0001 - portable part (SysloggerWrite, StderrWrite, SyslogWrite)
v4-0002 - Windows part (WriteConsoleW plus EventlogWrite)
Builds clean on current master with both Autoconf and Meson, no new
warnings.
Thanks,
Seongjun Shin
2026년 6월 7일 (일) 오전 1:25, 신성준 <shinsj4653@gmail.com>님이 작성:
Show quoted text
Hi,
Thanks Kirk, glad it's useful.
Kyotaro Horiguchi wrote:
Should we also consider instrumenting ReportEventW()/ReportEventA()?
They seem to be another Windows-specific logging output path.Also, if the intention is to cover all places where logging output
can block, I wonder whether the syslog() calls should be covered as
well.Good points -- both are blocking output paths and there's no real
reason to leave them out, so v3 instruments them rather than excluding
them with a comment. The intent is exactly to cover the places where
logging output can block, so this makes the series consistent.v3 adds two more WaitEventIO events:
IO / SyslogWrite - syslog(3) in write_syslog()
IO / EventlogWrite - ReportEventW()/ReportEventA() in write_eventlog()Same approach as before: the wait is reported only around the leaf
call, using the existing pgstat_report_wait_start()/end() helpers, so
it stays allocation-free and safe on the error-reporting path, and the
series still touches just elog.c and wait_event_names.txt.This also matches Michael's point on v2 -- each event covers a routine
rather than a single call site, so SyslogWrite wraps the syslog(3)
calls in write_syslog() and EventlogWrite wraps both ReportEvent
variants in write_eventlog(), the same way SysloggerWrite already
covers the two writes in write_pipe_chunks().As before, 0001 is the portable part and 0002 is the Windows part
(WriteConsoleW plus the new EventlogWrite).One caveat: EventlogWrite is Windows-only, so I couldn't get a runtime
before/after for it here -- I've only confirmed it builds (cfbot's
Windows task should cover that). The other events still show up in the
sampling I posted earlier. If someone on Windows can exercise the
event-log path I'd appreciate a confirmation.Applies cleanly on current master; full build passes locally on both
Autoconf and Meson, with no new warnings.Thanks,
Seongjun Shin2026년 6월 1일 (월) 오후 2:49, Kyotaro Horiguchi <horikyota.ntt@gmail.com>님이 작성:
Hello.
At Sun, 31 May 2026 17:50:08 +0900, 신성준 <shinsj4653@gmail.com> wrote in
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.Should we also consider instrumenting ReportEventW()/ReportEventA()?
They seem to be another Windows-specific logging output path.Also, if the intention is to cover all places where logging output can
block, I wonder whether the syslog() calls should be covered as
well. If they are intentionally excluded, perhaps a short comment
explaining the rationale would be useful.Regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Attachments:
v4-0001-Add-wait-events-for-server-logging-destination-wr.patchapplication/octet-stream; name=v4-0001-Add-wait-events-for-server-logging-destination-wr.patchDownload+14-1
v4-0002-Add-wait-events-for-Windows-specific-logging-outp.patchapplication/octet-stream; name=v4-0002-Add-wait-events-for-Windows-specific-logging-outp.patchDownload+8-1
On 6 Jun 2026, at 21:52, 신성준 <shinsj4653@gmail.com> wrote:
Hi Seongjun,
Naming is a hard thing. Anyone who can tell syslog from syslogger
without checking man is probably a computer themselves.
+1: a blocking logging write shows as wait_event IS NULL today, which
most tools read as on-CPU. This is very real for us. In our managed
Postgres the root filesystem that holds the logs sits on slow
network-backed HDD, so when the syslogger pipe backs up the backends
stall on the log write and the whole node looks like a CPU overload.
This patch would have made that directly visible.
Worth a line in the commit message: the call that actually blocks on a
slow log device is write_syslogger_file() in the syslogger, which has no
shared memory and isn't in pg_stat_activity. It surfaces on backends as
the pipe fills and they block on the pipe write (SysloggerWrite), so
the backend side is the right, visible layer.
One thing worth checking: wait events are single-slot by design (no
nesting - discussed back in 2016 [0]/messages/by-id/CANP8+jKsS6SDo011AUWrLdBcBMv0KJha69t7eFGqEtqx9FVfag@mail.gmail.com), and pgstat_report_wait_end()
just writes 0. So if any ereport() path runs while a wait event is
already set, instrumenting the logging write here clobbers that outer
event. Probably rare, but I'm not sure it never happens.
EventlogWrite necessarily shows up in the event list on all platforms
(the generator has no per-platform gating), but the description already
says "Windows event log", so that seems fine...
Thanks for working on this!
Best regards, Andrey Borodin.
[0]: /messages/by-id/CANP8+jKsS6SDo011AUWrLdBcBMv0KJha69t7eFGqEtqx9FVfag@mail.gmail.com
Hi Andrey,
+1: a blocking logging write shows as wait_event IS NULL today, which most
tools read as on-CPU. This is very real for us. In our managed Postgres the
root filesystem that holds the logs sits on slow network-backed HDD, so when
the syslogger pipe backs up the backends stall on the log write and the whole
node looks like a CPU overload. This patch would have made that directly
visible.
Thanks for the review, and for the production example. That node-looks-like-a-
CPU-overload case is exactly what this is meant to make visible.
Worth a line in the commit message: the call that actually blocks on a slow
log device is write_syslogger_file() in the syslogger, which has no shared
memory and isn't in pg_stat_activity. It surfaces on backends as the pipe
fills and they block on the pipe write (SysloggerWrite), so the backend side
is the right, visible layer.
Agreed. In v5 I'll add that to the commit message, and a short code comment to
the same effect: the syslogger does the file write in write_syslogger_file()
and isn't in pg_stat_activity, so the backend-side SysloggerWrite is where the
stall becomes visible.
Naming is a hard thing. Anyone who can tell syslog from syslogger without
checking man is probably a computer themselves.
Fair. I kept each name aligned with the routine it wraps, and the descriptions
spell out the difference, so I'd lean toward leaving them unless others object.
One thing worth checking: wait events are single-slot by design (no nesting -
discussed back in 2016 [0]), and pgstat_report_wait_end() just writes 0. So
if any ereport() path runs while a wait event is already set, instrumenting
the logging write here clobbers that outer event. Probably rare, but I'm not
sure it never happens.
Right about the mechanism. pgstat_report_wait_end() unconditionally writes 0,
so a log message emitted while an outer wait event is set would briefly mask
that event until the outer code reports its own end.
Two things, though. First, this is a pre-existing property of the subsystem,
not something the patch introduces: every pgstat_report_wait_start()/end() pair
behaves this way, and as the 2016 thread you linked concluded, the single
unsynchronized write is what keeps the mechanism cheap enough to stay on by
default, so nesting was deliberately left out. The patch follows that
convention rather than diverging from it. Second, the wrapped regions are tight
and log output is normally emitted outside them, so the overlap window should
be rare in practice, though I agree it isn't provably never.
So I'd prefer not to add save/restore here, since that would diverge from what
the rest of the tree relies on. I'll add a brief comment at these sites noting
the single-slot behavior. If reviewers would rather have a guard, a minimal
option that stays within the single-write model is to report the logging event
only when the slot is currently 0, which preserves the outer event at the cost
of not showing the logging write while nested. Happy to go that way if that's
the consensus.
EventlogWrite necessarily shows up in the event list on all platforms (the
generator has no per-platform gating), but the description already says
"Windows event log", so that seems fine...
Agreed, I'll leave it as-is.
I'll hold v5 until Nikolay's Linux and Windows testing comments land too, so I
can fold everything into one revision.
Thanks again,
Seongjun
2026년 6월 15일 (월) 오전 3:49, Andrey Borodin <x4mmm@yandex-team.ru>님이 작성:
Show quoted text
On 6 Jun 2026, at 21:52, 신성준 <shinsj4653@gmail.com> wrote:
Hi Seongjun,
Naming is a hard thing. Anyone who can tell syslog from syslogger
without checking man is probably a computer themselves.+1: a blocking logging write shows as wait_event IS NULL today, which
most tools read as on-CPU. This is very real for us. In our managed
Postgres the root filesystem that holds the logs sits on slow
network-backed HDD, so when the syslogger pipe backs up the backends
stall on the log write and the whole node looks like a CPU overload.
This patch would have made that directly visible.Worth a line in the commit message: the call that actually blocks on a
slow log device is write_syslogger_file() in the syslogger, which has no
shared memory and isn't in pg_stat_activity. It surfaces on backends as
the pipe fills and they block on the pipe write (SysloggerWrite), so
the backend side is the right, visible layer.One thing worth checking: wait events are single-slot by design (no
nesting - discussed back in 2016 [0]), and pgstat_report_wait_end()
just writes 0. So if any ereport() path runs while a wait event is
already set, instrumenting the logging write here clobbers that outer
event. Probably rare, but I'm not sure it never happens.EventlogWrite necessarily shows up in the event list on all platforms
(the generator has no per-platform gating), but the description already
says "Windows event log", so that seems fine...Thanks for working on this!
Best regards, Andrey Borodin.
[0] /messages/by-id/CANP8+jKsS6SDo011AUWrLdBcBMv0KJha69t7eFGqEtqx9FVfag@mail.gmail.com
Hi Seongjun,
Thanks for the patch -- I picked this up as the registered reviewer.
Since the patch just brackets the existing log writes with
pgstat_report_wait_start()/end(), I started by pinning down what those
two do.
Each is a single store through my_wait_event_info -- start writes the
event id, end unconditionally writes 0 -- and the pointer is statically
initialized to &local_my_wait_event_info, so it is never NULL.
A normal or aux backend later repoints it at shared memory
(MyProc->wait_event_info) in InitProcess()/InitAuxiliaryProcess(); the
postmaster and other pre-PGPROC contexts never do, and keep writing to
the local dummy.
The read side is asymmetric: no code reads the my_wait_event_info
pointer itself; pg_stat_activity has another backend read the target
backend's MyProc->wait_event_info (shared memory) directly
(pgstatfuncs.c).
So pgstat_report_wait_start()/end() only set and clear an integer and
are safe in themselves; for this patch the only thing left to review is
whether the instrumentation is placed correctly.
The patch adds four wait events. The start/end pairing is fine, so I
checked whether each event matches what it actually instruments and what
the wait_event_names.txt description claims, one by one:
- SYSLOG_WRITE -- "Waiting for a write to the system logger (syslog)."
write_syslog() instruments the libc syslog() call to the OS syslog
daemon. Target and description match.
- EVENTLOG_WRITE -- "Waiting for a write to the Windows event log."
write_eventlog() instruments ReportEventW/A, i.e. the Windows event
log write. Accurate. (The instrumentation is WIN32-only, but the name
is exposed in the catalog on all platforms; the description says
"Windows", so there's no confusion.)
- STDERR_WRITE -- "Waiting for a write to the server's standard error
stream."
write_console() instruments the stderr write. Matches.
- SYSLOGGER_WRITE -- "Waiting for a write to the syslogger pipe."
write_pipe_chunks() instruments the backend->pipe write. The
description is scoped to "pipe", so it is literally accurate.
In short, setting aside scope changes such as adding or removing events,
I agree on the correctness of where the instrumentation is placed (the
code) and of the per-event descriptions (the message).
On the single-slot point Andrey raised: I agree it is real -- a log line
emitted while an unrelated outer wait event is already set will have
these events overwrite that slot and then zero it
(pgstat_report_wait_end writes 0 unconditionally). In
practice, though, core has essentially no place where a *returning* LOG
is emitted while a distinct outer event is set: most waits are bracketed
inside WaitEventSetWait and the log line comes out after it returns, and
the one spot that does log with its own event still set
(AddToDataDirLockFile) runs in the postmaster, where no outer event is
present, so it is harmless.
It is a property of the single-slot mechanism rather than something
specific to this patch, so the comment you plan to add at the wrapped
sites in v5 looks right. If it were to be handled in general, your own
"report only when the slot is 0" idea could be generalized with a small
depth counter -- set on 0->1, clear on 1->0 -- to preserve the outer
event. But that makes the nested logging wait invisible and touches the
mechanism broadly, so it belongs in a separate change rather than this
patch.
Thanks for working on this.
Regards,
Henson
Hi Henson,
Thanks for the review, and for tracing through
pgstat_report_wait_start()/end() first -- once the helpers are just a
single store, placement is the only thing left to check, and thanks for
going through all four events against their descriptions.
the comment you plan to add at the wrapped sites in v5 looks right
[...] it belongs in a separate change rather than this patch.
Agreed. v5 adds that comment and leaves any general depth-counter
handling out.
v5 folds in the review:
- a short comment at each wrapped site noting the single-slot
behavior;
- Andrey's commit-message point that the real blocking call is
write_syslogger_file() in the syslogger (no PGPROC, not in
pg_stat_activity), so the backend-side SysloggerWrite is where the
stall shows up -- now in the 0001 commit message and a comment on
write_pipe_chunks().
No functional change from v4.
I'd said I'd hold v5 for platform testing, but since the review has
landed I'd rather post it than sit on the thread. Testing is still
welcome, especially the Windows EventlogWrite path -- cfbot confirms it
builds, but I can't exercise the runtime event-log write here. I'll fold
anything that turns up into a follow-up.
v5-0001 - portable part (SysloggerWrite, StderrWrite, SyslogWrite)
v5-0002 - Windows part (WriteConsoleW plus EventlogWrite)
Applies on current master; builds clean under Autoconf and Meson.
Thanks again,
Seongjun Shin
Attachments:
v5-0001-Add-wait-events-for-server-logging-destination-wr.patchapplication/octet-stream; name=v5-0001-Add-wait-events-for-server-logging-destination-wr.patchDownload+29-1
v5-0002-Add-wait-events-for-Windows-specific-logging-outp.patchapplication/octet-stream; name=v5-0002-Add-wait-events-for-Windows-specific-logging-outp.patchDownload+12-1
On Tue, Jun 30, 2026 at 10:02 AM 신성준 <shinsj4653@gmail.com> wrote:
Hi Henson,
Thanks for the review, and for tracing through
pgstat_report_wait_start()/end() first -- once the helpers are just a
single store, placement is the only thing left to check, and thanks for
going through all four events against their descriptions.the comment you plan to add at the wrapped sites in v5 looks right
[...] it belongs in a separate change rather than this patch.Agreed. v5 adds that comment and leaves any general depth-counter
handling out.v5 folds in the review:
- a short comment at each wrapped site noting the single-slot
behavior;
- Andrey's commit-message point that the real blocking call is
write_syslogger_file() in the syslogger (no PGPROC, not in
pg_stat_activity), so the backend-side SysloggerWrite is where the
stall shows up -- now in the 0001 commit message and a comment on
write_pipe_chunks().No functional change from v4.
I'd said I'd hold v5 for platform testing, but since the review has
landed I'd rather post it than sit on the thread. Testing is still
welcome, especially the Windows EventlogWrite path -- cfbot confirms it
builds, but I can't exercise the runtime event-log write here. I'll fold
anything that turns up into a follow-up.v5-0001 - portable part (SysloggerWrite, StderrWrite, SyslogWrite)
v5-0002 - Windows part (WriteConsoleW plus EventlogWrite)Applies on current master; builds clean under Autoconf and Meson.
Thanks again,
Seongjun Shin
Hi Seongjun,
(I reviewed and tested v4 back in June but never sent the results;
now doing it for v5.)
I ran runtime tests of this patch set on Linux, macOS, and Windows;
results below. tl;dr: both v5 patches apply cleanly (git am) to
current master (11ed011ae22) and build clean, and all four events
show up in pg_stat_activity under load -- including EventlogWrite on
Windows, which I believe was the one path previously only
build-verified. +1 from me.
** Methodology **
8 backends each run a plpgsql loop of 50k RAISE LOG calls with an
8 kB payload, while a separate connection samples pg_stat_activity
every ~2 ms and tallies wait_event. The driver scripts and the
Windows CI job are public:
https://github.com/NikolayS/postgres/tree/ci/windows-waitevents
workflow: .github/workflows/windows-waitevents.yml
** Results **
Linux (tested June 15 with v4; gcc 13, meson debug; I did not rerun
since the v4->v5 code delta is comment-only):
logging_collector = on -> IO/SysloggerWrite 3652 (46.3% of all
samples, null wait_event included)
logging_collector = off -> IO/StderrWrite 1376 (17.6%)
macOS (v5 on master@11ed011ae22; clang 17, meson debug):
logging_collector = on -> IO/SysloggerWrite 47362 samples
(the only wait event observed)
logging_collector = off -> IO/StderrWrite 13710 samples
Windows (v5 on master@11ed011ae22; MSVC/meson, windows-latest,
log_destination = 'stderr,eventlog'):
IO/EventlogWrite 20091 samples
IO/StderrWrite 642 samples
Run: https://github.com/NikolayS/postgres/actions/runs/29425495163
(the job fails hard if EventlogWrite is never sampled; it passed)
Counts are pg_stat_activity rows summed over sampler ticks and
backends, and run lengths differed, so they are not comparable
across platforms.
One caveat on Windows coverage: GitHub Actions redirects stderr, so
the WriteConsoleW branch of write_console() is not truly exercised
there -- the samples above go through the write(fileno(stderr))
branch plus write_eventlog(). I don't see it as blocking -- the
WriteConsoleW wrapping is mechanically identical to its sibling.
The NULL share varies with how fast the log device is: these are
debug builds on fast storage, so backends spend most of their time
formatting on-CPU. On a saturated pipe or a slow log device --
exactly Andrey's network-HDD case -- the attributable share grows,
which is precisely what the patch makes visible.
** Review notes on v5 **
I checked the v4->v5 delta -- comments and commit-message text only
(single-slot masking notes at each wrapped site, and the explanation
that the on-disk write happens in write_syslogger_file() in the
syslogger, which has no PGPROC, so the backend-side SysloggerWrite on
the pipe write is where a stall becomes visible). That addresses the
points from Andrey's and Henson's reviews, thank you.
One optional thought on write_syslog(): openlog() is called with
LOG_NDELAY, so the connection to the syslog socket is opened right
there on the first call in each process, and in principle that can
block too (e.g. glibc's stream-socket fallback with a busy syslog
daemon). That call could also be wrapped with SyslogWrite. It is
once per process, so take it or leave it -- not blocking.
Nik
Hi Seongjun,
(I reviewed and tested v4 back in June but never sent the results;
now doing it for v5.)I ran runtime tests of this patch set on Linux, macOS, and Windows;
results below. tl;dr: both v5 patches apply cleanly (git am) to
current master (11ed011ae22) and build clean, and all four events
show up in pg_stat_activity under load -- including EventlogWrite on
Windows, which I believe was the one path previously only
build-verified. +1 from me.** Methodology **
8 backends each run a plpgsql loop of 50k RAISE LOG calls with an
8 kB payload, while a separate connection samples pg_stat_activity
every ~2 ms and tallies wait_event. The driver scripts and the
Windows CI job are public:https://github.com/NikolayS/postgres/tree/ci/windows-waitevents
workflow: .github/workflows/windows-waitevents.yml** Results **
Linux (tested June 15 with v4; gcc 13, meson debug; I did not rerun
since the v4->v5 code delta is comment-only):logging_collector = on -> IO/SysloggerWrite 3652 (46.3% of all
samples, null wait_event included)
logging_collector = off -> IO/StderrWrite 1376 (17.6%)macOS (v5 on master@11ed011ae22; clang 17, meson debug):
logging_collector = on -> IO/SysloggerWrite 47362 samples
(the only wait event observed)
logging_collector = off -> IO/StderrWrite 13710 samplesWindows (v5 on master@11ed011ae22; MSVC/meson, windows-latest,
log_destination = 'stderr,eventlog'):IO/EventlogWrite 20091 samples
IO/StderrWrite 642 samplesRun: https://github.com/NikolayS/postgres/actions/runs/29425495163
(the job fails hard if EventlogWrite is never sampled; it passed)Counts are pg_stat_activity rows summed over sampler ticks and
backends, and run lengths differed, so they are not comparable
across platforms.One caveat on Windows coverage: GitHub Actions redirects stderr, so
the WriteConsoleW branch of write_console() is not truly exercised
there -- the samples above go through the write(fileno(stderr))
branch plus write_eventlog(). I don't see it as blocking -- the
WriteConsoleW wrapping is mechanically identical to its sibling.The NULL share varies with how fast the log device is: these are
debug builds on fast storage, so backends spend most of their time
formatting on-CPU. On a saturated pipe or a slow log device --
exactly Andrey's network-HDD case -- the attributable share grows,
which is precisely what the patch makes visible.** Review notes on v5 **
I checked the v4->v5 delta -- comments and commit-message text only
(single-slot masking notes at each wrapped site, and the explanation
that the on-disk write happens in write_syslogger_file() in the
syslogger, which has no PGPROC, so the backend-side SysloggerWrite on
the pipe write is where a stall becomes visible). That addresses the
points from Andrey's and Henson's reviews, thank you.One optional thought on write_syslog(): openlog() is called with
LOG_NDELAY, so the connection to the syslog socket is opened right
there on the first call in each process, and in principle that can
block too (e.g. glibc's stream-socket fallback with a busy syslog
daemon). That call could also be wrapped with SyslogWrite. It is
once per process, so take it or leave it -- not blocking.Nik
Hi Nik,
Thanks for running this on all three platforms.
EventlogWrite is the one I'm happiest to see. It's Windows-only
(ReportEventW/A), so until now I could only confirm it compiles. Seeing
it in pg_stat_activity -- 20091 samples, with the job set to fail if
it's never sampled -- is the runtime check the thread was missing, and
it closes the last open item.
Agreed on the WriteConsoleW caveat. I've written the coverage into the
commit messages rather than leave it implicit: SysloggerWrite,
StderrWrite and SyslogWrite sampled at runtime on Linux and macOS, and
EventlogWrite confirmed on Windows via your CI run; WriteConsoleW is
covered by build and review only, since it needs a real console. Your
results are credited there. (And +1 on the NULL share -- it's small
on fast debug builds and grows once the log device is the bottleneck,
which is the case the patch is for.)
Good catch on openlog(). With LOG_NDELAY the socket is connected on the
first log in each process, so it can block the same way the syslog()
calls can; wrapping those but not this felt inconsistent. v6 wraps it,
reusing SyslogWrite since it's the same write_syslog() routine.
That openlog() wrap is the only functional change from v5; otherwise v6
is a rebase plus the commit-message note. I checked it by:
- git am of both patches onto current master (5174d157a03), clean;
- full Meson build (cassert, debug) -- no warnings;
- regression and isolation suites green (245 and 130 tests).
v6-0001 - portable part (SysloggerWrite, StderrWrite, SyslogWrite, now
including the openlog() call)
v6-0002 - Windows part (WriteConsoleW plus EventlogWrite)
Henson, the only change since your v5 review is the openlog() wrap
above. Final comments from anyone are welcome.
Thanks again for the testing and the review.
Seongjun