From db6b7a9f4f94f5513275518625f855e25f911981 Mon Sep 17 00:00:00 2001 From: Seongjun Shin Date: Fri, 13 Nov 2026 00:04:10 +0900 Subject: [PATCH v10 2/3] Add wait events for server logging destination writes Writing server log output can block: write(2) to the syslogger pipe once the pipe is full, write(2) to stderr when the output device is slow, and syslog(3) or openlog(3) when the system logger is slow. In all these cases pg_stat_activity showed wait_event as NULL. This adds three wait events for these calls: IO / SysloggerWrite - write(2) to the syslogger pipe. IO / StderrWrite - write(2) to stderr. IO / SyslogWrite - syslog(3) and openlog(3). A log message can be emitted while the caller has already set a wait event, so these use pgstat_report_wait_swap() to put the previous wait event back once the write is done, instead of clearing it. 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 --- src/backend/utils/activity/wait_event_names.txt | 3 +++ src/backend/utils/error/elog.c | 16 ++++++++++++++++ 2 files changed, 19 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 e215ed053ff..6c860403336 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() */ @@ -2833,13 +2834,16 @@ write_syslog(int level, const char *line) int len; const char *nlpos; + uint32 old_wait_event; /* Open syslog connection if not done yet */ if (!openlog_done) { + old_wait_event = pgstat_report_wait_swap(WAIT_EVENT_SYSLOG_WRITE); openlog(syslog_ident ? syslog_ident : "postgres", LOG_PID | LOG_NDELAY | LOG_NOWAIT, syslog_facility); + pgstat_report_wait_swap(old_wait_event); openlog_done = true; } @@ -2912,10 +2916,12 @@ write_syslog(int level, const char *line) chunk_nr++; + old_wait_event = pgstat_report_wait_swap(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_swap(old_wait_event); line += buflen; len -= buflen; @@ -2924,10 +2930,12 @@ write_syslog(int level, const char *line) else { /* message short enough */ + old_wait_event = pgstat_report_wait_swap(WAIT_EVENT_SYSLOG_WRITE); if (syslog_sequence_numbers) syslog(level, "[%lu] %s", seq, line); else syslog(level, "%s", line); + pgstat_report_wait_swap(old_wait_event); } } #endif /* HAVE_SYSLOG */ @@ -3050,6 +3058,7 @@ static void write_console(const char *line, int len) { ssize_t rc; + uint32 old_wait_event; #ifdef WIN32 @@ -3112,7 +3121,9 @@ 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. */ + old_wait_event = pgstat_report_wait_swap(WAIT_EVENT_STDERR_WRITE); rc = write(fileno(stderr), line, len); + pgstat_report_wait_swap(old_wait_event); (void) rc; } @@ -3940,6 +3951,7 @@ write_pipe_chunks(char *data, int len, int dest) PipeProtoChunk p; int fd = fileno(stderr); ssize_t rc; + uint32 old_wait_event; Assert(len > 0); @@ -3959,7 +3971,9 @@ 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); + old_wait_event = pgstat_report_wait_swap(WAIT_EVENT_SYSLOGGER_WRITE); rc = write(fd, &p, PIPE_HEADER_SIZE + PIPE_MAX_PAYLOAD); + pgstat_report_wait_swap(old_wait_event); (void) rc; data += PIPE_MAX_PAYLOAD; len -= PIPE_MAX_PAYLOAD; @@ -3969,7 +3983,9 @@ 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); + old_wait_event = pgstat_report_wait_swap(WAIT_EVENT_SYSLOGGER_WRITE); rc = write(fd, &p, PIPE_HEADER_SIZE + len); + pgstat_report_wait_swap(old_wait_event); (void) rc; } -- 2.50.1 (Apple Git-155)