Subject: Add wait events for server logging destination writes

From: 신성준 <[email-masked]>
Date: Sun, 31 May 2026 17:50:08 +0900

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

---

From: 신성준 <[email-masked]>
Date: Sun, 31 May 2026 19:42:41 +0900

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

---

From: Kirk Wolak <[email-masked]>
Date: Sun, 31 May 2026 12:53:09 -0400

> the new events. I can send the scripts and raw samples if anyone wants
+1
  Nice.  We have too many waits that are registered as CPU.

---

From: Michael Paquier <[email-masked]>
Date: Mon, 1 Jun 2026 13:37:34 +0900

> 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

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Mon, 01 Jun 2026 14:49:22 +0900 (JST)

Hello.

At Sun, 31 May 2026 17:50:08 +0900, 신성준 <[email-masked]> wrote in 
> 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

---

From: 신성준 <[email-masked]>
Date: Sun, 7 Jun 2026 01:25:25 +0900

Hi,

Thanks Kirk, glad it's useful.

Kyotaro Horiguchi wrote:
> 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

---

From: 신성준 <[email-masked]>
Date: Sun, 7 Jun 2026 01:52:34 +0900

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

---

From: Andrey Borodin <[email-masked]>
Date: Sun, 14 Jun 2026 23:48:48 +0500

> On 6 Jun 2026, at 21:52, 신성준 <[email-masked]> 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] https://www.postgresql.org/message-id/CANP8%2BjKsS6SDo011AUWrLdBcBMv0KJha69t7eFGqEtqx9FVfag%40mail.gmail.com

---

From: 신성준 <[email-masked]>
Date: Wed, 17 Jun 2026 01:10:18 +0900

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