From d6a1aae4e02e3b16049ea62a74375c8e8e06070e Mon Sep 17 00:00:00 2001 From: Seongjun Shin Date: Fri, 29 May 2026 14:45:23 +0900 Subject: [PATCH v9 1/2] Add wait events for server logging destination writes When a backend writes server log output, the underlying call can block: write(2) to the syslogger pipe or to stderr once the pipe buffer fills up or the output device is slow, and syslog(3) when the system logger is slow. These blocking calls were not instrumented, so pg_stat_activity reported wait_event IS NULL during that time. Many monitoring tools interpret NULL as on-CPU work, which made heavy-logging stalls hard to attribute. This is not hypothetical. A production outage has been reported where a remote syslog destination stopped accepting data and the stall propagated back into the backends; wait_event was NULL throughout, and the cause was found only by collecting stack traces. Add three new WaitEventIO events and report them around the relevant calls: IO / SysloggerWrite - write(2) to the syslogger pipe inside write_pipe_chunks(). IO / StderrWrite - write(2) to stderr inside write_console(). IO / SyslogWrite - syslog(3) inside write_syslog(). The instrumentation is limited to the leaf write/syslog call. It uses two inline helpers added to wait_event.h, pgstat_report_wait_start_nested() and pgstat_report_wait_end_nested(), which are pgstat_report_wait_start()/end() with the restore described below added. Like those they are allocation-free and safe to call before MyProc is set up, so this remains safe to invoke from within error reporting paths. write_syslog() opens its connection with openlog(3) using LOG_NDELAY, which connects to the system logger right away rather than on the first message, and that call can block as well (for example glibc's stream-socket fallback against a busy syslog daemon). It is wrapped too, reusing the SyslogWrite event since it belongs to the same routine; the event description mentions connection setup for that reason. Where backends are forked from the postmaster they inherit the syslog connection, which the postmaster opens for its own first message, so a backend does not normally reach openlog() at all. A backend gets there after syslog_ident or syslog_facility changes and the reload is applied, since assign_syslog_facility() closes the connection in every process that applies it. The postmaster's own call never appears in pg_stat_activity. The call that actually blocks on a slow log device is write_syslogger_file() in the syslogger process, which has no PGPROC and so never appears in pg_stat_activity. Backends surface the stall as the pipe fills and they block on the pipe write, so the backend-side SysloggerWrite event is where it becomes visible. A log message can be written while another wait event is already published: an extension can log from inside its own wait region, and quickdie() reports from a signal handler that can fire inside any region. Wait events are single-slot and pgstat_report_wait_end() writes 0, so a plain start()/end() pair around the log write would not merely hide the outer event while the write is in progress but clear it for the rest of that region. Nikolay Samokhvalov showed this with an extension that published its own event, called ereport(LOG) and kept waiting: once the log call had returned, pg_stat_activity showed wait_event NULL where the extension's event had been. The new sites therefore save the published event before the write and put it back afterwards, so the outer event is hidden only while the write itself is in progress, which is when the process really is waiting on the log destination. Within core, a debug check that fails on a region opened inside another one finds a single such log write in the test suite, quickdie() with ClientRead published, and that process exits right afterwards; the restore matters for extensions and for any future core code that logs while it waits. These events were observed in pg_stat_activity under heavy-logging workloads on Linux and macOS, including runs with the syslog daemon and the syslogger deliberately stalled so that every wrapped call site was reached; the Windows-specific EventlogWrite path added in the following patch was likewise confirmed at runtime via a CI job. Author: Seongjun Shin Reviewed-by: Kirk Wolak Reviewed-by: Kyotaro Horiguchi Reviewed-by: Michael Paquier Reviewed-by: Andrey Borodin Reviewed-by: Henson Choi Reviewed-by: Nikolay Samokhvalov Reviewed-by: Jihyun Bahn Reviewed-by: Jakub Wartak Tested-by: Nikolay Samokhvalov Tested-by: Jihyun Bahn Tested-by: Jakub Wartak Discussion: https://postgr.es/m/CACdN0M78U+GvpqA7oey-GA7fFSYM636aDp6H9FVvCztv9zXxSA@mail.gmail.com --- .../utils/activity/wait_event_names.txt | 3 ++ src/backend/utils/error/elog.c | 48 +++++++++++++++++++ src/include/utils/wait_event.h | 42 ++++++++++++++++ 3 files changed, 93 insertions(+) diff --git a/src/backend/utils/activity/wait_event_names.txt b/src/backend/utils/activity/wait_event_names.txt index 3d366fd1114..4c64bceb47b 100644 --- a/src/backend/utils/activity/wait_event_names.txt +++ b/src/backend/utils/activity/wait_event_names.txt @@ -259,6 +259,9 @@ SLRU_WRITE "Waiting for a write of an SLRU page." SNAPBUILD_READ "Waiting for a read of a serialized historical catalog snapshot." SNAPBUILD_SYNC "Waiting for a serialized historical catalog snapshot to reach durable storage." SNAPBUILD_WRITE "Waiting for a write of a serialized historical catalog snapshot." +STDERR_WRITE "Waiting for a write to the server's standard error stream." +SYSLOGGER_WRITE "Waiting for a write to the syslogger pipe." +SYSLOG_WRITE "Waiting for a write to the system logger (syslog), including connection setup." TIMELINE_HISTORY_FILE_SYNC "Waiting for a timeline history file received via streaming replication to reach durable storage." TIMELINE_HISTORY_FILE_WRITE "Waiting for a write of a timeline history file received via streaming replication." TIMELINE_HISTORY_READ "Waiting for a read of a timeline history file." diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index b9d2c96b97a..0fb489ed563 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -89,6 +89,7 @@ #include "utils/pg_locale.h" #include "utils/ps_status.h" #include "utils/varlena.h" +#include "utils/wait_event.h" /* In this module, access gettext() via err_gettext() */ @@ -2811,13 +2812,26 @@ write_syslog(int level, const char *line) int len; const char *nlpos; + uint32 outer_wait_event_info; /* Open syslog connection if not done yet */ if (!openlog_done) { + /* + * With LOG_NDELAY, openlog() connects to the system logger right here + * rather than on the first message, and that can block (for example + * glibc's stream-socket fallback against a busy syslog daemon), so + * report the wait. Backends normally inherit the connection from the + * postmaster and never get here; they do after syslog_ident or + * syslog_facility changes, since assign_syslog_facility() closes the + * connection in every process that applies the reload. + */ + outer_wait_event_info = + pgstat_report_wait_start_nested(WAIT_EVENT_SYSLOG_WRITE); openlog(syslog_ident ? syslog_ident : "postgres", LOG_PID | LOG_NDELAY | LOG_NOWAIT, syslog_facility); + pgstat_report_wait_end_nested(outer_wait_event_info); openlog_done = true; } @@ -2890,10 +2904,14 @@ write_syslog(int level, const char *line) chunk_nr++; + /* See write_console() for why the nested variants are used. */ + outer_wait_event_info = + pgstat_report_wait_start_nested(WAIT_EVENT_SYSLOG_WRITE); if (syslog_sequence_numbers) syslog(level, "[%lu-%d] %s", seq, chunk_nr, buf); else syslog(level, "[%d] %s", chunk_nr, buf); + pgstat_report_wait_end_nested(outer_wait_event_info); line += buflen; len -= buflen; @@ -2902,10 +2920,13 @@ write_syslog(int level, const char *line) else { /* message short enough */ + outer_wait_event_info = + pgstat_report_wait_start_nested(WAIT_EVENT_SYSLOG_WRITE); if (syslog_sequence_numbers) syslog(level, "[%lu] %s", seq, line); else syslog(level, "%s", line); + pgstat_report_wait_end_nested(outer_wait_event_info); } } #endif /* HAVE_SYSLOG */ @@ -3028,6 +3049,7 @@ static void write_console(const char *line, int len) { ssize_t rc; + uint32 outer_wait_event_info; #ifdef WIN32 @@ -3089,8 +3111,19 @@ write_console(const char *line, int len) /* * We ignore any error from write() here. We have no useful way to report * it ... certainly whining on stderr isn't likely to be productive. + * + * A log message can be written while another wait event is already + * published, for instance by an extension that logs from inside its own + * wait region, or by quickdie() running in a signal handler. Wait events + * are single-slot and pgstat_report_wait_end() clears the field, which + * would leave the enclosing region without its event for as long as it + * lasts. The nested variants used here and at the other logging writes + * put the outer event back once the write is done. */ + outer_wait_event_info = + pgstat_report_wait_start_nested(WAIT_EVENT_STDERR_WRITE); rc = write(fileno(stderr), line, len); + pgstat_report_wait_end_nested(outer_wait_event_info); (void) rc; } @@ -3903,6 +3936,14 @@ send_message_to_server_log(ErrorData *edata) * that are no more than that length, and send one chunk per write() call. * The collector process knows how to reassemble the chunks. * + * The actual file write happens later in the syslogger process + * (write_syslogger_file()), which has no PGPROC and so never shows up in + * pg_stat_activity. A backend blocks here on the pipe write once the pipe + * fills, so this SysloggerWrite event on the backend side is where such a + * stall becomes visible. As with the other logging writes, the wait is + * reported only around the leaf write(), and any wait event that was already + * published is put back afterwards (see write_console()). + * * Because of the atomic write requirement, there are only two possible * results from write() here: -1 for failure, or the requested number of * bytes. There is not really anything we can do about a failure; retry would @@ -3918,6 +3959,7 @@ write_pipe_chunks(char *data, int len, int dest) PipeProtoChunk p; int fd = fileno(stderr); ssize_t rc; + uint32 outer_wait_event_info; Assert(len > 0); @@ -3937,7 +3979,10 @@ write_pipe_chunks(char *data, int len, int dest) /* no need to set PIPE_PROTO_IS_LAST yet */ p.proto.len = PIPE_MAX_PAYLOAD; memcpy(p.proto.data, data, PIPE_MAX_PAYLOAD); + outer_wait_event_info = + pgstat_report_wait_start_nested(WAIT_EVENT_SYSLOGGER_WRITE); rc = write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD); + pgstat_report_wait_end_nested(outer_wait_event_info); (void) rc; data += PIPE_MAX_PAYLOAD; len -= PIPE_MAX_PAYLOAD; @@ -3947,7 +3992,10 @@ write_pipe_chunks(char *data, int len, int dest) p.proto.flags |= PIPE_PROTO_IS_LAST; p.proto.len = len; memcpy(p.proto.data, data, len); + outer_wait_event_info = + pgstat_report_wait_start_nested(WAIT_EVENT_SYSLOGGER_WRITE); rc = write(fd, &p, PIPE_HEADER_SIZE + len); + pgstat_report_wait_end_nested(outer_wait_event_info); (void) rc; } diff --git a/src/include/utils/wait_event.h b/src/include/utils/wait_event.h index 86ee348220d..abd2ca20d65 100644 --- a/src/include/utils/wait_event.h +++ b/src/include/utils/wait_event.h @@ -17,6 +17,8 @@ extern const char *pgstat_get_wait_event(uint32 wait_event_info); extern const char *pgstat_get_wait_event_type(uint32 wait_event_info); static inline void pgstat_report_wait_start(uint32 wait_event_info); static inline void pgstat_report_wait_end(void); +static inline uint32 pgstat_report_wait_start_nested(uint32 wait_event_info); +static inline void pgstat_report_wait_end_nested(uint32 outer_wait_event_info); extern void pgstat_set_wait_event_storage(uint32 *wait_event_info); extern void pgstat_reset_wait_event_storage(void); @@ -86,5 +88,45 @@ pgstat_report_wait_end(void) *(volatile uint32 *) my_wait_event_info = 0; } +/* ---------- + * pgstat_report_wait_start_nested() - + * + * Like pgstat_report_wait_start(), for a wait that can occur while another + * wait event is already published, such as a write to the server log made + * from inside a wait region. Returns the wait event that was published + * before, for the caller to hand back to pgstat_report_wait_end_nested() + * once its own wait is over. + * ---------- + */ +static inline uint32 +pgstat_report_wait_start_nested(uint32 wait_event_info) +{ + uint32 outer_wait_event_info; + + /* see pgstat_report_wait_start() */ + outer_wait_event_info = *(volatile uint32 *) my_wait_event_info; + *(volatile uint32 *) my_wait_event_info = wait_event_info; + + return outer_wait_event_info; +} + +/* ---------- + * pgstat_report_wait_end_nested() - + * + * Called to report end of a wait started with + * pgstat_report_wait_start_nested(). Where pgstat_report_wait_end() would + * clear the wait event, this publishes the one that was current before the + * nested wait began, so that an enclosing wait region keeps its event. If + * there was none, outer_wait_event_info is 0 and the effect is the same as + * pgstat_report_wait_end(). + * ---------- + */ +static inline void +pgstat_report_wait_end_nested(uint32 outer_wait_event_info) +{ + /* see pgstat_report_wait_start() */ + *(volatile uint32 *) my_wait_event_info = outer_wait_event_info; +} + #endif /* WAIT_EVENT_H */ -- 2.50.1 (Apple Git-155)