Send duration output to separate log files
Please find attached a patch to allow for durations to optionally be sent
to separate log files. In other words, rather than cluttering up our
postgres202007.log file with tons of output from
log_min_duration_statement, duration lines are sent instead to the file
postgres202007.duration.
Over the years, durations have been the number one cause of very large log
files, in which the more "important" items get buried in the noise. Also,
programs that are scanning for durations typically do not care about the
normal, non-duration output. Some people have a policy of logging
everything, which in effect means setting log_min_duration_statement to 0,
which in turn makes your log files nearly worthless for spotting
non-duration items. This feature will also be very useful for those who
need to temporarily turn on log_min_duration_statement, for some quick
auditing of exactly what is being run on their database. When done, you can
move or remove the duration file without messing up your existing log
stream.
This only covers the case when both the duration and statement are set on
the same line. In other words, log_min_duration_statement output, but not
log_duration (which is best avoided anyway). It also requires
logging_collector to be on, obviously.
Details:
The edata structure is expanded to have a new message_type, with a matching
function errmessagetype() created.
[include/utils/elog.h]
[backend/utils/elog.c]
Any errors that have both a duration and a statement are marked via
errmessagetype()
[backend/tcop/postgres.c]
A new GUC named "log_duration_destination" is created, which supports any
combination of stderr, csvlog, and jsonlog. It does not need to match
log_destination, in order to support different use cases. For example, the
user wants durations sent to a CSV file for processing by some other tool,
but still wants everything else going to a normal text log file.
Code: [include/utils/guc_hooks.h] [backend/utils/misc/guc_tables.c]
Docs: [sgml/config.sgml] [backend/utils/misc/postgresql.conf.sample]
Create a new flag called PIPE_PROTO_DEST_DURATION
[include/postmaster/syslogger.h]
Create new flags:
LOG_DESTINATION_DURATION,
LOG_DESTINATION_DURATION_CSV,
LOG_DESTINATION_DURATION_JSON
[include/utils/elog.h]
Routing and mapping LOG_DESTINATION to PIPE_PROTO
[backend/utils/error/elog.c]
Minor rerouting when using alternate forms
[backend/utils/error/csvlog.c]
[backend/utils/error/jsonlog.c]
Create new filehandles, do log rotation, map PIPE_PROTO to LOG_DESTINATION.
Rotation and entry into the "current_logfiles" file are the same as
existing log files. The new names/suffixes are duration, duration.csv, and
duration.json.
[backend/postmaster/syslogger.c]
Testing to ensure combinations of log_destination and
log_duration_destination work as intended
[bin/pg_ctl/meson.build]
[bin/pg_ctl/t/005_log_duration_destination.pl]
Questions I've asked along the way, and perhaps other might as well:
What about logging other things? Why just duration?
Duration logging is a very unique event in our logs. There is nothing quite
like it - it's always client-driven, yet automatically generated. And it
can be extraordinarily verbose. Removing it from the existing logging
stream has no particular downsides. Almost any other class of log message
would likely meet resistance as far as moving it to a separate log file,
with good reason.
Why not build a more generic log filtering case?
I looked into this, but it would be a large undertaking, given the way our
logging system works. And as per above, I don't think the pain would be
worth it, as duration covers 99% of the use cases for separate logs.
Certainly, nothing else other than a recurring ERROR from the client can
cause massive bloat in the size of the files. (There is a nearby patch to
exclude certain errors from the log file as a way to mitigate the error
spam - I don't like that idea, but should mention it here as another effort
to keep the log files a manageable size)
Why not use an extension for this?
I did start this as an extension, but it only goes so far. We can use
emit_log_hook, but it requires careful coordination of open filehandles,
has to do inefficient regex of every log message, and cannot do things like
log rotation.
Why not bitmap PIPE_PROTO *and* LOG_DESTINATION?
I tried to do both as simple bitmaps (i.e. duration+csv = duration.csv),
and not have to use e.g. LOG_DESTIATION_DURATION_CSV, but size_rotation_for
ruined it for me. Since our PIPE always sends one thing at a time, a single
new flag enables it to stay as a clean bits8 type.
What about Windows?
Untested. I don't have access to a Windows build, but I think in theory it
should work fine.
Cheers,
Greg
Attachments:
0001-Add-new-parameter-log_duration_destination.patchapplication/x-patch; name=0001-Add-new-parameter-log_duration_destination.patchDownload
From c6d19d07cfa7eac51e5ead79f1c1b230b5b2d364 Mon Sep 17 00:00:00 2001
From: Greg Sabino Mullane <greg@turnstep.com>
Date: Tue, 2 Jul 2024 15:13:44 -0400
Subject: [PATCH] Add new parameter log_duration_destination
This allows writing of items from log_min_duration_statement to be sent to separate log files.
---
doc/src/sgml/config.sgml | 46 +++
src/backend/postmaster/syslogger.c | 225 +++++++++++--
src/backend/tcop/postgres.c | 6 +-
src/backend/utils/error/csvlog.c | 2 +
src/backend/utils/error/elog.c | 139 ++++++++-
src/backend/utils/error/jsonlog.c | 2 +
src/backend/utils/misc/guc_tables.c | 12 +
src/backend/utils/misc/postgresql.conf.sample | 5 +
src/bin/pg_ctl/meson.build | 1 +
.../pg_ctl/t/005_log_duration_destination.pl | 295 ++++++++++++++++++
src/include/postmaster/syslogger.h | 1 +
src/include/utils/elog.h | 12 +
src/include/utils/guc_hooks.h | 3 +
13 files changed, 717 insertions(+), 32 deletions(-)
create mode 100644 src/bin/pg_ctl/t/005_log_duration_destination.pl
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 17d84bd321..378e3563d5 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6480,6 +6480,29 @@ local0.* /var/log/postgresql
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-duration-destination" xreflabel="log_duration_destination">
+ <term><varname>log_duration_destination</varname> (<type>string</type>)
+ <indexterm>
+ <primary><varname>log_duration_destination</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Log messages that include both a duration and statement (i.e. those generated by
+ use of the <xref linkend="guc-log-min-duration-statement"/> parameter)
+ can be written to separate log files. Set this parameter to a list of desired
+ log destinations separated by commas. The current list of destination values are
+ <systemitem>stderr</systemitem>, <systemitem>csvlog</systemitem>,
+ and <systemitem>jsonlog</systemitem>. This list does not need to match the items
+ in <xref linkend="guc-log-destination"/>.
+ This parameter can only be set in the <filename>postgresql.conf</filename>
+ file or on the server command line.
+ <xref linkend="guc-logging-collector"/> must be enabled for this
+ parameter to work.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-logging-collector" xreflabel="logging_collector">
<term><varname>logging_collector</varname> (<type>boolean</type>)
<indexterm>
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index 7951599fa8..f9f9d61d0a 100644
--- a/src/backend/postmaster/syslogger.c
+++ b/src/backend/postmaster/syslogger.c
@@ -84,10 +84,16 @@ static bool rotation_disabled = false;
static FILE *syslogFile = NULL;
static FILE *csvlogFile = NULL;
static FILE *jsonlogFile = NULL;
+static FILE *durationFile = NULL;
+static FILE *durationcsvFile = NULL;
+static FILE *durationjsonFile = NULL;
NON_EXEC_STATIC pg_time_t first_syslogger_file_time = 0;
static char *last_sys_file_name = NULL;
static char *last_csv_file_name = NULL;
static char *last_json_file_name = NULL;
+static char *last_duration_file_name = NULL;
+static char *last_duration_csv_file_name = NULL;
+static char *last_duration_json_file_name = NULL;
/*
* Buffers for saving partial messages from different backends.
@@ -155,6 +161,9 @@ typedef struct
int syslogFile;
int csvlogFile;
int jsonlogFile;
+ int durationFile;
+ int durationcsvFile;
+ int durationjsonFile;
} SysloggerStartupData;
/*
@@ -189,6 +198,9 @@ SysLoggerMain(char *startup_data, size_t startup_data_len)
syslogFile = syslogger_fdopen(slsdata->syslogFile);
csvlogFile = syslogger_fdopen(slsdata->csvlogFile);
jsonlogFile = syslogger_fdopen(slsdata->jsonlogFile);
+ durationFile = syslogger_fdopen(slsdata->durationFile);
+ durationcsvFile = syslogger_fdopen(slsdata->durationcsvFile);
+ durationjsonFile = syslogger_fdopen(slsdata->durationjsonFile);
}
#else
Assert(startup_data_len == 0);
@@ -311,6 +323,12 @@ SysLoggerMain(char *startup_data, size_t startup_data_len)
last_csv_file_name = logfile_getname(first_syslogger_file_time, ".csv");
if (jsonlogFile != NULL)
last_json_file_name = logfile_getname(first_syslogger_file_time, ".json");
+ if (durationFile != NULL)
+ last_duration_file_name = logfile_getname(first_syslogger_file_time, ".duration");
+ if (durationcsvFile != NULL)
+ last_duration_csv_file_name = logfile_getname(first_syslogger_file_time, ".duration.csv");
+ if (durationjsonFile != NULL)
+ last_duration_json_file_name = logfile_getname(first_syslogger_file_time, ".duration.json");
/* remember active logfile parameters */
currentLogDir = pstrdup(Log_directory);
@@ -390,20 +408,18 @@ SysLoggerMain(char *startup_data, size_t startup_data_len)
}
/*
- * Force a rotation if CSVLOG output was just turned on or off and
- * we need to open or close csvlogFile accordingly.
+ * Force a rotation if any of the alternate outputs were turned on
+ * or off and we need to open or close their filehandles
+ * accordingly.
*/
- if (((Log_destination & LOG_DESTINATION_CSVLOG) != 0) !=
- (csvlogFile != NULL))
- rotation_requested = true;
-
- /*
- * Force a rotation if JSONLOG output was just turned on or off
- * and we need to open or close jsonlogFile accordingly.
- */
- if (((Log_destination & LOG_DESTINATION_JSONLOG) != 0) !=
- (jsonlogFile != NULL))
+ if ((((Log_destination & LOG_DESTINATION_CSVLOG) != 0) != (csvlogFile != NULL)) ||
+ (((Log_destination & LOG_DESTINATION_JSONLOG) != 0) != (jsonlogFile != NULL)) ||
+ (((Log_duration_destination & LOG_DESTINATION_STDERR) != 0) != (durationFile != NULL)) ||
+ (((Log_duration_destination & LOG_DESTINATION_CSVLOG) != 0) != (durationcsvFile != NULL)) ||
+ (((Log_duration_destination & LOG_DESTINATION_JSONLOG) != 0) != (durationjsonFile != NULL)))
+ {
rotation_requested = true;
+ }
/*
* If rotation time parameter changed, reset next rotation time,
@@ -461,6 +477,24 @@ SysLoggerMain(char *startup_data, size_t startup_data_len)
rotation_requested = true;
size_rotation_for |= LOG_DESTINATION_JSONLOG;
}
+ if (durationFile != NULL &&
+ ftell(durationFile) >= Log_RotationSize * 1024L)
+ {
+ rotation_requested = true;
+ size_rotation_for |= LOG_DESTINATION_DURATION;
+ }
+ if (durationcsvFile != NULL &&
+ ftell(durationcsvFile) >= Log_RotationSize * 1024L)
+ {
+ rotation_requested = true;
+ size_rotation_for |= LOG_DESTINATION_DURATION_CSV;
+ }
+ if (durationjsonFile != NULL &&
+ ftell(durationjsonFile) >= Log_RotationSize * 1024L)
+ {
+ rotation_requested = true;
+ size_rotation_for |= LOG_DESTINATION_DURATION_JSON;
+ }
}
if (rotation_requested)
@@ -472,7 +506,10 @@ SysLoggerMain(char *startup_data, size_t startup_data_len)
if (!time_based_rotation && size_rotation_for == 0)
size_rotation_for = LOG_DESTINATION_STDERR |
LOG_DESTINATION_CSVLOG |
- LOG_DESTINATION_JSONLOG;
+ LOG_DESTINATION_JSONLOG |
+ LOG_DESTINATION_DURATION |
+ LOG_DESTINATION_DURATION_CSV |
+ LOG_DESTINATION_DURATION_JSON;
logfile_rotate(time_based_rotation, size_rotation_for);
}
@@ -695,10 +732,35 @@ SysLogger_Start(void)
pfree(filename);
}
+ /*
+ * Likewise for the initial duration log files, if enabled.
+ */
+ if (Log_duration_destination & LOG_DESTINATION_STDERR)
+ {
+ filename = logfile_getname(first_syslogger_file_time, ".duration");
+ durationFile = logfile_open(filename, "a", false);
+ pfree(filename);
+ }
+ if (Log_duration_destination & LOG_DESTINATION_CSVLOG)
+ {
+ filename = logfile_getname(first_syslogger_file_time, ".duration.csv");
+ durationcsvFile = logfile_open(filename, "a", false);
+ pfree(filename);
+ }
+ if (Log_duration_destination & LOG_DESTINATION_JSONLOG)
+ {
+ filename = logfile_getname(first_syslogger_file_time, ".duration.json");
+ durationjsonFile = logfile_open(filename, "a", false);
+ pfree(filename);
+ }
+
#ifdef EXEC_BACKEND
startup_data.syslogFile = syslogger_fdget(syslogFile);
startup_data.csvlogFile = syslogger_fdget(csvlogFile);
startup_data.jsonlogFile = syslogger_fdget(jsonlogFile);
+ startup_data.durationFile = syslogger_fdget(durationFile);
+ startup_data.durationcsvFile = syslogger_fdget(durationcsvFile);
+ startup_data.durationjsonFile = syslogger_fdget(durationjsonFile);
sysloggerPid = postmaster_child_launch(B_LOGGER, (char *) &startup_data, sizeof(startup_data), NULL);
#else
sysloggerPid = postmaster_child_launch(B_LOGGER, NULL, 0, NULL);
@@ -784,6 +846,21 @@ SysLogger_Start(void)
fclose(jsonlogFile);
jsonlogFile = NULL;
}
+ if (durationFile != NULL)
+ {
+ fclose(durationFile);
+ durationFile = NULL;
+ }
+ if (durationcsvFile != NULL)
+ {
+ fclose(durationcsvFile);
+ durationcsvFile = NULL;
+ }
+ if (durationjsonFile != NULL)
+ {
+ fclose(durationjsonFile);
+ durationjsonFile = NULL;
+ }
return (int) sysloggerPid;
}
@@ -886,17 +963,17 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
{
PipeProtoHeader p;
int chunklen;
- bits8 dest_flags;
/* Do we have a valid header? */
memcpy(&p, cursor, offsetof(PipeProtoHeader, data));
- dest_flags = p.flags & (PIPE_PROTO_DEST_STDERR |
- PIPE_PROTO_DEST_CSVLOG |
- PIPE_PROTO_DEST_JSONLOG);
+
if (p.nuls[0] == '\0' && p.nuls[1] == '\0' &&
p.len > 0 && p.len <= PIPE_MAX_PAYLOAD &&
p.pid != 0 &&
- pg_number_of_ones[dest_flags] == 1)
+ p.flags & (PIPE_PROTO_DEST_STDERR |
+ PIPE_PROTO_DEST_CSVLOG |
+ PIPE_PROTO_DEST_JSONLOG |
+ PIPE_PROTO_DEST_DURATION))
{
List *buffer_list;
ListCell *cell;
@@ -910,11 +987,21 @@ process_pipe_input(char *logbuffer, int *bytes_in_logbuffer)
if (count < chunklen)
break;
- if ((p.flags & PIPE_PROTO_DEST_STDERR) != 0)
+ /* Duration is checked first as it has multiple flags */
+ if (p.flags & PIPE_PROTO_DEST_DURATION)
+ {
+ if (p.flags & PIPE_PROTO_DEST_CSVLOG)
+ dest = LOG_DESTINATION_DURATION_CSV;
+ else if (p.flags & PIPE_PROTO_DEST_JSONLOG)
+ dest = LOG_DESTINATION_DURATION_JSON;
+ else
+ dest = LOG_DESTINATION_DURATION;
+ }
+ else if (p.flags & PIPE_PROTO_DEST_STDERR)
dest = LOG_DESTINATION_STDERR;
- else if ((p.flags & PIPE_PROTO_DEST_CSVLOG) != 0)
+ else if (p.flags & PIPE_PROTO_DEST_CSVLOG)
dest = LOG_DESTINATION_CSVLOG;
- else if ((p.flags & PIPE_PROTO_DEST_JSONLOG) != 0)
+ else if (p.flags & PIPE_PROTO_DEST_JSONLOG)
dest = LOG_DESTINATION_JSONLOG;
else
{
@@ -1107,10 +1194,17 @@ write_syslogger_file(const char *buffer, int count, int destination)
* Think not to improve this by trying to open logFile on-the-fly. Any
* failure in that would lead to recursion.
*/
+
if ((destination & LOG_DESTINATION_CSVLOG) && csvlogFile != NULL)
logfile = csvlogFile;
else if ((destination & LOG_DESTINATION_JSONLOG) && jsonlogFile != NULL)
logfile = jsonlogFile;
+ else if ((destination & LOG_DESTINATION_DURATION) && durationFile != NULL)
+ logfile = durationFile;
+ else if ((destination & LOG_DESTINATION_DURATION_CSV) && durationcsvFile != NULL)
+ logfile = durationcsvFile;
+ else if ((destination & LOG_DESTINATION_DURATION_JSON) && durationjsonFile != NULL)
+ logfile = durationjsonFile;
else
logfile = syslogFile;
@@ -1184,7 +1278,10 @@ pipeThread(void *arg)
{
if (ftell(syslogFile) >= Log_RotationSize * 1024L ||
(csvlogFile != NULL && ftell(csvlogFile) >= Log_RotationSize * 1024L) ||
- (jsonlogFile != NULL && ftell(jsonlogFile) >= Log_RotationSize * 1024L))
+ (jsonlogFile != NULL && ftell(jsonlogFile) >= Log_RotationSize * 1024L) ||
+ (durationFile != NULL && ftell(durationFile) >= Log_RotationSize * 1024L) ||
+ (durationcsvFile != NULL && ftell(durationcsvFile) >= Log_RotationSize * 1024L) ||
+ (durationjsonFile != NULL && ftell(durationjsonFile) >= Log_RotationSize * 1024L))
SetLatch(MyLatch);
}
LeaveCriticalSection(&sysloggerSection);
@@ -1272,8 +1369,16 @@ logfile_rotate_dest(bool time_based_rotation, int size_rotation_for,
* is assumed to be always opened even if stderr is disabled in
* log_destination.
*/
- if ((Log_destination & target_dest) == 0 &&
- target_dest != LOG_DESTINATION_STDERR)
+ if (
+ (target_dest != LOG_DESTINATION_STDERR) /* never close stderr */
+ && (
+ /* Close if it has been removed from Log_destination */
+ ((target_dest < LOG_DESTINATION_DURATION) &&
+ ((Log_destination & target_dest) == 0))
+ ||
+ /* Close if it has been removed from Log_duration_destination */
+ ((target_dest >= LOG_DESTINATION_DURATION) &&
+ ((Log_duration_destination & target_dest) <= LOG_DESTINATION_DURATION))))
{
if (*logFile != NULL)
fclose(*logFile);
@@ -1285,9 +1390,10 @@ logfile_rotate_dest(bool time_based_rotation, int size_rotation_for,
}
/*
- * Leave if it is not time for a rotation or if the target destination has
- * no need to do a rotation based on the size of its file.
+ * Leave if it is not time for a rotation and if the target destination
+ * has no need to do a rotation based on the size of its file.
*/
+
if (!time_based_rotation && (size_rotation_for & target_dest) == 0)
return true;
@@ -1298,6 +1404,12 @@ logfile_rotate_dest(bool time_based_rotation, int size_rotation_for,
logFileExt = ".csv";
else if (target_dest == LOG_DESTINATION_JSONLOG)
logFileExt = ".json";
+ else if (target_dest == LOG_DESTINATION_DURATION)
+ logFileExt = ".duration";
+ else if (target_dest == LOG_DESTINATION_DURATION_CSV)
+ logFileExt = ".duration.csv";
+ else if (target_dest == LOG_DESTINATION_DURATION_JSON)
+ logFileExt = ".duration.json";
else
{
/* cannot happen */
@@ -1391,6 +1503,22 @@ logfile_rotate(bool time_based_rotation, int size_rotation_for)
&jsonlogFile))
return;
+ /* file rotation for durations */
+ if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
+ LOG_DESTINATION_DURATION, &last_duration_file_name,
+ &durationFile))
+ return;
+
+ if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
+ LOG_DESTINATION_DURATION_CSV,
+ &last_duration_csv_file_name, &durationcsvFile))
+ return;
+
+ if (!logfile_rotate_dest(time_based_rotation, size_rotation_for, fntime,
+ LOG_DESTINATION_DURATION_JSON,
+ &last_duration_json_file_name, &durationjsonFile))
+ return;
+
update_metainfo_datafile();
set_next_rotation_time();
@@ -1478,7 +1606,10 @@ update_metainfo_datafile(void)
if (!(Log_destination & LOG_DESTINATION_STDERR) &&
!(Log_destination & LOG_DESTINATION_CSVLOG) &&
- !(Log_destination & LOG_DESTINATION_JSONLOG))
+ !(Log_destination & LOG_DESTINATION_JSONLOG) &&
+ !(Log_duration_destination & LOG_DESTINATION_STDERR) &&
+ !(Log_duration_destination & LOG_DESTINATION_CSVLOG) &&
+ !(Log_duration_destination & LOG_DESTINATION_JSONLOG))
{
if (unlink(LOG_METAINFO_DATAFILE) < 0 && errno != ENOENT)
ereport(LOG,
@@ -1549,6 +1680,46 @@ update_metainfo_datafile(void)
return;
}
}
+
+ if (last_duration_file_name && (Log_duration_destination & LOG_DESTINATION_STDERR))
+ {
+ if (fprintf(fh, "duration %s\n", last_duration_file_name) < 0)
+ {
+ ereport(LOG,
+ (errcode_for_file_access(),
+ errmsg("could not write file \"%s\": %m",
+ LOG_METAINFO_DATAFILE_TMP)));
+ fclose(fh);
+ return;
+ }
+ }
+
+ if (last_duration_csv_file_name && (Log_duration_destination & LOG_DESTINATION_CSVLOG))
+ {
+ if (fprintf(fh, "duration.csv %s\n", last_duration_csv_file_name) < 0)
+ {
+ ereport(LOG,
+ (errcode_for_file_access(),
+ errmsg("could not write file \"%s\": %m",
+ LOG_METAINFO_DATAFILE_TMP)));
+ fclose(fh);
+ return;
+ }
+ }
+
+ if (last_duration_json_file_name && (Log_duration_destination & LOG_DESTINATION_JSONLOG))
+ {
+ if (fprintf(fh, "duration.json %s\n", last_duration_json_file_name) < 0)
+ {
+ ereport(LOG,
+ (errcode_for_file_access(),
+ errmsg("could not write file \"%s\": %m",
+ LOG_METAINFO_DATAFILE_TMP)));
+ fclose(fh);
+ return;
+ }
+ }
+
fclose(fh);
if (rename(LOG_METAINFO_DATAFILE_TMP, LOG_METAINFO_DATAFILE) != 0)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index e39c6804a7..b0a0442376 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1370,6 +1370,7 @@ exec_simple_query(const char *query_string)
(errmsg("duration: %s ms statement: %s",
msec_str, query_string),
errhidestmt(true),
+ errmessagetype(LOG_MESSAGE_TYPE_DURATION),
errdetail_execute(parsetree_list)));
break;
}
@@ -1607,7 +1608,8 @@ exec_parse_message(const char *query_string, /* string to execute */
msec_str,
*stmt_name ? stmt_name : "<unnamed>",
query_string),
- errhidestmt(true)));
+ errhidestmt(true),
+ errmessagetype(LOG_MESSAGE_TYPE_DURATION)));
break;
}
@@ -2064,6 +2066,7 @@ exec_bind_message(StringInfo input_message)
*portal_name ? portal_name : "",
psrc->query_string),
errhidestmt(true),
+ errmessagetype(LOG_MESSAGE_TYPE_DURATION),
errdetail_params(params)));
break;
}
@@ -2317,6 +2320,7 @@ exec_execute_message(const char *portal_name, long max_rows)
*portal_name ? portal_name : "",
sourceText),
errhidestmt(true),
+ errmessagetype(LOG_MESSAGE_TYPE_DURATION),
errdetail_params(portalParams)));
break;
}
diff --git a/src/backend/utils/error/csvlog.c b/src/backend/utils/error/csvlog.c
index 855e130a97..3a9ccf1045 100644
--- a/src/backend/utils/error/csvlog.c
+++ b/src/backend/utils/error/csvlog.c
@@ -255,6 +255,8 @@ write_csvlog(ErrorData *edata)
/* If in the syslogger process, try to write messages direct to file */
if (MyBackendType == B_LOGGER)
write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_CSVLOG);
+ else if (edata->message_type == LOG_MESSAGE_TYPE_DURATION)
+ write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_DURATION_CSV);
else
write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_CSVLOG);
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 3e42f5754f..d68311a974 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -108,7 +108,9 @@ emit_log_hook_type emit_log_hook = NULL;
int Log_error_verbosity = PGERROR_DEFAULT;
char *Log_line_prefix = NULL; /* format for extra log line info */
int Log_destination = LOG_DESTINATION_STDERR;
+int Log_duration_destination = 0;
char *Log_destination_string = NULL;
+char *Log_duration_destination_string = NULL;
bool syslog_sequence_numbers = true;
bool syslog_split_messages = true;
@@ -443,6 +445,7 @@ errstart(int elevel, const char *domain)
/* Initialize data for this error frame */
edata = get_error_stack_entry();
edata->elevel = elevel;
+ edata->message_type = LOG_MESSAGE_TYPE_DEFAULT;
edata->output_to_server = output_to_server;
edata->output_to_client = output_to_client;
set_stack_entry_domain(edata, domain);
@@ -1453,6 +1456,24 @@ errposition(int cursorpos)
return 0; /* return value does not matter */
}
+/*
+ * errmessagetype --- set type for possible future filtering
+ */
+int
+errmessagetype(int type)
+{
+ ErrorData *edata = &errordata[errordata_stack_depth];
+
+ /* we don't bother incrementing recursion_depth */
+ CHECK_STACK_DEPTH();
+
+ Assert(type >= 0);
+
+ edata->message_type = type;
+
+ return 0; /* return value does not matter */
+}
+
/*
* internalerrposition --- add internal cursor position to the current error
*/
@@ -2277,6 +2298,69 @@ assign_log_destination(const char *newval, void *extra)
Log_destination = *((int *) extra);
}
+/*
+ * GUC check_hook for log_duration_destination
+ */
+bool
+check_log_duration_destination(char **newval, void **extra, GucSource source)
+{
+ char *rawstring;
+ List *elemlist;
+ ListCell *l;
+ int newlogdest = 0;
+ int *myextra;
+
+ /* Need a modifiable copy of string */
+ rawstring = pstrdup(*newval);
+
+ /* Parse string into list of identifiers */
+ if (!SplitIdentifierString(rawstring, ',', &elemlist))
+ {
+ /* syntax error in list */
+ GUC_check_errdetail("List syntax is invalid.");
+ pfree(rawstring);
+ list_free(elemlist);
+ return false;
+ }
+
+ foreach(l, elemlist)
+ {
+ char *tok = (char *) lfirst(l);
+
+ if (pg_strcasecmp(tok, "stderr") == 0)
+ newlogdest |= LOG_DESTINATION_STDERR;
+ else if (pg_strcasecmp(tok, "csvlog") == 0)
+ newlogdest |= LOG_DESTINATION_CSVLOG;
+ else if (pg_strcasecmp(tok, "jsonlog") == 0)
+ newlogdest |= LOG_DESTINATION_JSONLOG;
+ else
+ {
+ GUC_check_errdetail("Unrecognized key word: \"%s\".", tok);
+ pfree(rawstring);
+ list_free(elemlist);
+ return false;
+ }
+ }
+
+ pfree(rawstring);
+ list_free(elemlist);
+
+ myextra = (int *) guc_malloc(ERROR, sizeof(int));
+ *myextra = newlogdest;
+ *extra = (void *) myextra;
+
+ return true;
+}
+
+/*
+ * GUC assign_hook for log_duration_destination
+ */
+void
+assign_log_duration_destination(const char *newval, void *extra)
+{
+ Log_duration_destination = *((int *) extra);
+}
+
/*
* GUC assign_hook for syslog_ident
*/
@@ -3314,8 +3398,17 @@ send_message_to_server_log(ErrorData *edata)
}
#endif /* WIN32 */
- /* Write to csvlog, if enabled */
- if (Log_destination & LOG_DESTINATION_CSVLOG)
+ /*
+ * Write to csvlog, if enabled. If this is a duration, only send if csv is
+ * a duration destination, or if the duration destination is not set at
+ * all.
+ */
+ if ((((edata->message_type != LOG_MESSAGE_TYPE_DURATION) ||
+ (Log_duration_destination == 0)) &&
+ (Log_destination & LOG_DESTINATION_CSVLOG))
+ ||
+ ((edata->message_type == LOG_MESSAGE_TYPE_DURATION) &&
+ (Log_duration_destination & LOG_DESTINATION_CSVLOG)))
{
/*
* Send CSV data if it's safe to do so (syslogger doesn't need the
@@ -3329,7 +3422,12 @@ send_message_to_server_log(ErrorData *edata)
}
/* Write to JSON log, if enabled */
- if (Log_destination & LOG_DESTINATION_JSONLOG)
+ if ((((edata->message_type != LOG_MESSAGE_TYPE_DURATION) ||
+ (Log_duration_destination == 0)) &&
+ (Log_destination & LOG_DESTINATION_JSONLOG))
+ ||
+ ((edata->message_type == LOG_MESSAGE_TYPE_DURATION) &&
+ (Log_duration_destination & LOG_DESTINATION_JSONLOG)))
{
/*
* Send JSON data if it's safe to do so (syslogger doesn't need the
@@ -3344,6 +3442,15 @@ send_message_to_server_log(ErrorData *edata)
fallback_to_stderr = true;
}
+
+ /* If this is a duration, make sure it goes somewhere */
+ if ((edata->message_type == LOG_MESSAGE_TYPE_DURATION) &&
+ !(Log_duration_destination & LOG_DESTINATION_CSVLOG) &&
+ !(Log_duration_destination & LOG_DESTINATION_JSONLOG))
+ {
+ fallback_to_stderr = true;
+ }
+
/*
* Write to stderr, if enabled or if required because of a previous
* limitation.
@@ -3358,7 +3465,24 @@ send_message_to_server_log(ErrorData *edata)
* Otherwise, just do a vanilla write to stderr.
*/
if (redirection_done && MyBackendType != B_LOGGER)
- write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_STDERR);
+ {
+ /* Write to the duration file if explicitly asked to */
+ if ((edata->message_type == LOG_MESSAGE_TYPE_DURATION) &&
+ (Log_duration_destination & LOG_DESTINATION_STDERR))
+ write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_DURATION);
+
+ /*
+ * If this is a duration and we have already written it above, do
+ * nothing
+ */
+ else if ((edata->message_type == LOG_MESSAGE_TYPE_DURATION) &&
+ ((Log_duration_destination & LOG_DESTINATION_CSVLOG) ||
+ (Log_duration_destination & LOG_DESTINATION_JSONLOG)))
+ ;
+ /* Otherwise, fall back to stderr */
+ else
+ write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_STDERR);
+ }
#ifdef WIN32
/*
@@ -3415,12 +3539,19 @@ write_pipe_chunks(char *data, int len, int dest)
p.proto.nuls[0] = p.proto.nuls[1] = '\0';
p.proto.pid = MyProcPid;
p.proto.flags = 0;
+
if (dest == LOG_DESTINATION_STDERR)
p.proto.flags |= PIPE_PROTO_DEST_STDERR;
else if (dest == LOG_DESTINATION_CSVLOG)
p.proto.flags |= PIPE_PROTO_DEST_CSVLOG;
else if (dest == LOG_DESTINATION_JSONLOG)
p.proto.flags |= PIPE_PROTO_DEST_JSONLOG;
+ else if (dest == LOG_DESTINATION_DURATION)
+ p.proto.flags |= PIPE_PROTO_DEST_DURATION;
+ else if (dest == LOG_DESTINATION_DURATION_CSV)
+ p.proto.flags |= (PIPE_PROTO_DEST_DURATION | PIPE_PROTO_DEST_CSVLOG);
+ else if (dest == LOG_DESTINATION_DURATION_JSON)
+ p.proto.flags |= (PIPE_PROTO_DEST_DURATION | PIPE_PROTO_DEST_JSONLOG);
/* write all but the last chunk */
while (len > PIPE_MAX_PAYLOAD)
diff --git a/src/backend/utils/error/jsonlog.c b/src/backend/utils/error/jsonlog.c
index bd0124869d..1a9cbdb256 100644
--- a/src/backend/utils/error/jsonlog.c
+++ b/src/backend/utils/error/jsonlog.c
@@ -294,6 +294,8 @@ write_jsonlog(ErrorData *edata)
/* If in the syslogger process, try to write messages direct to file */
if (MyBackendType == B_LOGGER)
write_syslogger_file(buf.data, buf.len, LOG_DESTINATION_JSONLOG);
+ else if (edata->message_type == LOG_MESSAGE_TYPE_DURATION)
+ write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_DURATION_JSON);
else
write_pipe_chunks(buf.data, buf.len, LOG_DESTINATION_JSONLOG);
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index d28b0bcb40..ea00325848 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -4355,6 +4355,18 @@ struct config_string ConfigureNamesString[] =
NULL, NULL, NULL
},
+ {
+ {"log_duration_destination", PGC_SIGHUP, LOGGING_WHERE,
+ gettext_noop("Sets the destination for duration log entries."),
+ gettext_noop("Valid values are combinations of \"stderr\", "
+ "\"csvlog\", and \"jsonlog\"."),
+ GUC_LIST_INPUT
+ },
+ &Log_duration_destination_string,
+ "",
+ check_log_duration_destination, assign_log_duration_destination, NULL
+ },
+
{
{"syslog_ident", PGC_SIGHUP, LOGGING_WHERE,
gettext_noop("Sets the program name used to identify PostgreSQL "
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 9ec9f97e92..ad4f86f638 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -479,6 +479,11 @@
# (change requires restart)
# These are only used if logging_collector is on:
+# log_duration_destination = '' # Put items from log_min_duration_statement
+ # into separate files. Valid values are
+ # combinations of stderr, csvlog, and
+ # jsonlog.
+
#log_directory = 'log' # directory where log files are written,
# can be absolute or relative to PGDATA
#log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern,
diff --git a/src/bin/pg_ctl/meson.build b/src/bin/pg_ctl/meson.build
index da05bd8a8d..08e3c20f12 100644
--- a/src/bin/pg_ctl/meson.build
+++ b/src/bin/pg_ctl/meson.build
@@ -27,6 +27,7 @@ tests += {
't/002_status.pl',
't/003_promote.pl',
't/004_logrotate.pl',
+ 't/005_log_duration_destination.pl',
],
},
}
diff --git a/src/bin/pg_ctl/t/005_log_duration_destination.pl b/src/bin/pg_ctl/t/005_log_duration_destination.pl
new file mode 100644
index 0000000000..57431ea47c
--- /dev/null
+++ b/src/bin/pg_ctl/t/005_log_duration_destination.pl
@@ -0,0 +1,295 @@
+# Copyright (c) 2024, PostgreSQL Global Development Group
+
+# Tests for the log_duration_destination parameter
+
+use strict;
+use warnings FATAL => 'all';
+
+use PostgreSQL::Test::Cluster;
+use PostgreSQL::Test::Utils;
+use Test::More;
+use Time::HiRes qw(usleep);
+use File::Spec::Functions;
+
+# Start up Postgres with duration logging
+my $node = PostgreSQL::Test::Cluster->new('primary');
+$node->init();
+$node->append_conf(
+ 'postgresql.conf', qq(
+logging_collector = on
+log_destination = 'stderr, csvlog, jsonlog'
+log_duration_destination = 'stderr'
+log_statement = none
+log_min_duration_statement = 0
+log_rotation_age = 0
+log_rotation_size = 0
+lc_messages = 'C'
+));
+$node->start();
+
+# Send a normal duration-causing statement, then an error
+$node->psql('postgres', 'SELECT 1111');
+$node->psql('postgres', 'SELECT E1E1');
+
+# Read in the current_logfiles file once it appears
+my $current_logfiles;
+my $attempts = 2 * $PostgreSQL::Test::Utils::timeout_default;
+while ($attempts--)
+{
+ eval {
+ $current_logfiles =
+ slurp_file(catfile($node->data_dir, 'current_logfiles'));
+ };
+ last unless $@;
+ usleep(100_000);
+}
+die $@ if $@;
+
+my $test = "File 'current_logfiles' in the data directory looks correct";
+my $expected = 'stderr log/postgresql-.*\.log
+csvlog log/postgresql-.*\.csv
+jsonlog log/postgresql-.*\.json
+duration log/postgresql-.*\.duration';
+like($current_logfiles, qr{^$expected$}, $test);
+
+# Verify the error is here the slow way, then we can check quickly
+$test = 'Log file for stderr has most recent error';
+check_log_pattern('stderr', $current_logfiles, 'SELECT E1E1', $node);
+
+## Gather the text of all open log files and put into a hash
+my $logtext = slurp_logfiles();
+
+$test = 'Duration statements are written to the duration stderr log file';
+like($logtext->{duration}, qr/duration.*SELECT 1111/, $test);
+
+$test =
+ 'Duration statements do NOT get written to the normal stderr log file';
+unlike($logtext->{stderr}, qr/SELECT 1111/, $test);
+
+$test = 'Duration statements do NOT get written to the normal CSV log file';
+unlike($logtext->{csvlog}, qr/SELECT 1111/, $test);
+
+$test = 'Duration statements do NOT get written to the normal JSON log file';
+unlike($logtext->{jsonlog}, qr/SELECT 1111/, $test);
+
+$test = 'Error statements do NOT get written to the duration stderr log file';
+unlike($logtext->{duration}, qr/SELECT E1E1/, $test);
+
+$test = 'Errors statements are written to the normal stderr log file';
+like($logtext->{stderr}, qr/SELECT E1E1/, $test);
+
+$test = 'Errors statements are written to the normal CSV log file';
+like($logtext->{csvlog}, qr/SELECT E1E1/, $test);
+
+$test = 'Errors statements are written to the normal JSON log file';
+like($logtext->{jsonlog}, qr/SELECT E1E1/, $test);
+
+## Test CSV
+$test = 'Duration CSV log file gets added to list on reload';
+$node->psql('postgres', "ALTER SYSTEM SET log_duration_destination='csvlog'");
+$node->psql('postgres', 'SELECT pg_reload_conf()');
+$node->psql('postgres', 'SELECT 2222');
+$node->psql('postgres', 'SELECT E2E2');
+
+# Again, we do the slow way once
+$current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+check_log_pattern('stderr', $current_logfiles, 'SELECT E2E2', $node);
+
+$logtext = slurp_logfiles();
+ok(exists $logtext->{'duration.csv'}, $test);
+
+$test = 'Duration stderr log file gets removed from list on reload';
+ok(!exists $logtext->{'duration'}, $test);
+
+$test = 'Duration statements are written to the duration CSV log file';
+like($logtext->{'duration.csv'}, qr/SELECT 2222/, $test);
+
+$test =
+ 'Duration statements do NOT get written to the normal stderr log file';
+unlike($logtext->{stderr}, qr/SELECT 2222/, $test);
+
+$test = 'Error statements do NOT get written to the duration CSV log file';
+unlike($logtext->{'duration.csv'}, qr/SELECT E2E2/, $test);
+
+## Test JSON
+$test = 'Duration JSON log file gets added to list on reload';
+$node->psql('postgres',
+ "ALTER SYSTEM SET log_duration_destination='csvlog, jsonlog'");
+$node->psql('postgres', 'SELECT pg_reload_conf()');
+$node->psql('postgres', 'SELECT 3333');
+$node->psql('postgres', 'SELECT E3E3');
+
+# Wait for the error to appear
+$current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+check_log_pattern('stderr', $current_logfiles, 'SELECT E3E3', $node);
+
+$logtext = slurp_logfiles();
+ok(exists $logtext->{'duration.json'}, $test);
+
+$test = 'Duration statements are written to the duration JSON log file';
+like($logtext->{'duration.json'}, qr/SELECT 3333/, $test);
+
+$test =
+ 'Duration statements do NOT get written to the normal stderr log file';
+unlike($logtext->{stderr}, qr/SELECT 3333/, $test);
+
+$test = 'Error statements do NOT get written to the duration JSON log file';
+unlike($logtext->{'duration.json'}, qr/SELECT E3E3/, $test);
+
+## Test all three at once
+$test = 'Duration stderr log file gets added to list on reload';
+$node->psql('postgres',
+ "ALTER SYSTEM SET log_duration_destination='csvlog, stderr, jsonlog'");
+$node->psql('postgres', 'SELECT pg_reload_conf()');
+$node->psql('postgres', 'SELECT 4444');
+$node->psql('postgres', 'SELECT E4E4');
+
+# Wait for the error to appear
+$current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+check_log_pattern('stderr', $current_logfiles, 'SELECT E4E4', $node);
+
+$logtext = slurp_logfiles();
+ok(exists $logtext->{'duration'}, $test);
+
+$test = 'Duration CSV log file gets added to list on reload';
+ok(exists $logtext->{'duration.csv'}, $test);
+
+$test = 'Duration JSON log file gets added to list on reload';
+ok(exists $logtext->{'duration.json'}, $test);
+
+$test = 'Duration statements are written to the duration stderr log file';
+like($logtext->{'duration'}, qr/SELECT 4444/, $test);
+
+$test = 'Duration statements are written to the duration CSV log file';
+like($logtext->{'duration.csv'}, qr/SELECT 4444/, $test);
+
+$test = 'Duration statements are written to the duration JSON log file';
+like($logtext->{'duration.json'}, qr/SELECT 4444/, $test);
+
+$test =
+ 'Duration statements do NOT get written to the normal stderr log file';
+unlike($logtext->{stderr}, qr/SELECT 4444/, $test);
+
+$test = 'Error statements do NOT get written to the duration stderr log file';
+unlike($logtext->{'duration.json'}, qr/SELECT E4E4/, $test);
+
+$test = 'Error statements do NOT get written to the duration CSV log file';
+unlike($logtext->{'duration.csv'}, qr/SELECT E4E4/, $test);
+
+$test = 'Error statements do NOT get written to the duration JSON log file';
+unlike($logtext->{'duration.json'}, qr/SELECT E4E4/, $test);
+
+## Test log rotation
+my %oldname;
+while ($current_logfiles =~ /^(\S+) (.+?)$/gsm)
+{
+ $oldname{$1} = $2;
+}
+sleep 2;
+$node->psql('postgres', "SELECT pg_rotate_logfile()");
+$current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+
+my %newname;
+while ($current_logfiles =~ /^(\S+) (.+?)$/gsm)
+{
+ $newname{$1} = $2;
+}
+
+$test = "Log file has rotated to a new name";
+for my $type (sort keys %oldname)
+{
+ my $old = $oldname{$type};
+ my $new = $newname{$type};
+ isnt($old, $new, "$test (type=$type)");
+}
+
+## Test no duration files at all
+$test = 'Duration stderr gets removed from list on reload';
+$node->psql('postgres', "ALTER SYSTEM SET log_duration_destination=''");
+$node->psql('postgres', 'SELECT pg_reload_conf()');
+$node->psql('postgres', 'SELECT 5555');
+$node->psql('postgres', 'SELECT E5E5');
+
+# Wait for the error to appear
+$current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+check_log_pattern('stderr', $current_logfiles, 'SELECT E5E5', $node);
+
+$logtext = slurp_logfiles();
+ok(!exists $logtext->{'duration'}, $test);
+
+$test = 'Duration CSV gets removed from list on reload';
+ok(!exists $logtext->{'duration.csv'}, $test);
+
+$test = 'Duration JSON gets removed from list on reload';
+ok(!exists $logtext->{'duration.json'}, $test);
+
+$test = 'Duration statements are written to the normal stderr log file';
+like($logtext->{'stderr'}, qr/SELECT 5555/, $test);
+
+
+done_testing();
+
+exit;
+
+
+sub slurp_logfiles
+{
+
+ # Reload the current_logfiles file from the data_directory
+ $current_logfiles = slurp_file($node->data_dir . '/current_logfiles');
+
+ # Grab each one, and extract its contents into the hash
+ my %logtext;
+ while ($current_logfiles =~ /^(\S+) (.+?)$/gsm)
+ {
+ my ($type, $name) = ($1, $2);
+ my $path = catfile($node->data_dir, $name);
+ $logtext{$type} = slurp_file($path);
+ }
+ return \%logtext;
+}
+
+# Check for a pattern in the logs associated to one format.
+sub check_log_pattern
+{
+ local $Test::Builder::Level = $Test::Builder::Level + 1;
+
+ my $format = shift;
+ my $logfiles = shift;
+ my $pattern = shift;
+ my $node = shift;
+ my $lfname = fetch_file_name($logfiles, $format);
+
+ my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
+
+ my $logcontents;
+ for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
+ {
+ $logcontents = slurp_file($node->data_dir . '/' . $lfname);
+ last if $logcontents =~ m/$pattern/;
+ usleep(100_000);
+ }
+
+ like($logcontents, qr/$pattern/,
+ "found expected log file content for $format");
+
+ return;
+}
+
+# Extract the file name of a $format from the contents of current_logfiles.
+sub fetch_file_name
+{
+ my $logfiles = shift;
+ my $format = shift;
+ my @lines = split(/\n/, $logfiles);
+ my $filename = undef;
+ foreach my $line (@lines)
+ {
+ if ($line =~ /$format (.*)$/gm)
+ {
+ $filename = $1;
+ }
+ }
+
+ return $filename;
+}
diff --git a/src/include/postmaster/syslogger.h b/src/include/postmaster/syslogger.h
index 0f28ebcba5..efed8423ea 100644
--- a/src/include/postmaster/syslogger.h
+++ b/src/include/postmaster/syslogger.h
@@ -65,6 +65,7 @@ typedef union
#define PIPE_PROTO_DEST_STDERR 0x10
#define PIPE_PROTO_DEST_CSVLOG 0x20
#define PIPE_PROTO_DEST_JSONLOG 0x40
+#define PIPE_PROTO_DEST_DURATION 0x80
/* GUC options */
extern PGDLLIMPORT bool Logging_collector;
diff --git a/src/include/utils/elog.h b/src/include/utils/elog.h
index 054dd2bf62..77c3ce0615 100644
--- a/src/include/utils/elog.h
+++ b/src/include/utils/elog.h
@@ -220,6 +220,8 @@ extern int errbacktrace(void);
extern int errposition(int cursorpos);
+extern int errmessagetype(int type);
+
extern int internalerrposition(int cursorpos);
extern int internalerrquery(const char *query);
@@ -466,6 +468,7 @@ typedef struct ErrorData
int internalpos; /* cursor index into internalquery */
char *internalquery; /* text of internally-generated query */
int saved_errno; /* errno at entry */
+ int message_type; /* type of message for potential routing */
/* context containing associated non-constant strings */
struct MemoryContextData *assoc_context;
@@ -498,7 +501,9 @@ typedef enum
extern PGDLLIMPORT int Log_error_verbosity;
extern PGDLLIMPORT char *Log_line_prefix;
extern PGDLLIMPORT int Log_destination;
+extern PGDLLIMPORT int Log_duration_destination;
extern PGDLLIMPORT char *Log_destination_string;
+extern PGDLLIMPORT char *Log_duration_destination_string;
extern PGDLLIMPORT bool syslog_sequence_numbers;
extern PGDLLIMPORT bool syslog_split_messages;
@@ -508,6 +513,13 @@ extern PGDLLIMPORT bool syslog_split_messages;
#define LOG_DESTINATION_EVENTLOG 4
#define LOG_DESTINATION_CSVLOG 8
#define LOG_DESTINATION_JSONLOG 16
+#define LOG_DESTINATION_DURATION 32
+#define LOG_DESTINATION_DURATION_CSV 64
+#define LOG_DESTINATION_DURATION_JSON 128
+
+/* Log message type */
+#define LOG_MESSAGE_TYPE_DEFAULT 0
+#define LOG_MESSAGE_TYPE_DURATION 1
/* Other exported functions */
extern void log_status_format(StringInfo buf, const char *format,
diff --git a/src/include/utils/guc_hooks.h b/src/include/utils/guc_hooks.h
index 070d3f2a1a..baa7de6899 100644
--- a/src/include/utils/guc_hooks.h
+++ b/src/include/utils/guc_hooks.h
@@ -76,6 +76,9 @@ extern void assign_locale_time(const char *newval, void *extra);
extern bool check_log_destination(char **newval, void **extra,
GucSource source);
extern void assign_log_destination(const char *newval, void *extra);
+extern bool check_log_duration_destination(char **newval, void **extra,
+ GucSource source);
+extern void assign_log_duration_destination(const char *newval, void *extra);
extern const char *show_log_file_mode(void);
extern bool check_log_stats(bool *newval, void **extra, GucSource source);
extern bool check_log_timezone(char **newval, void **extra, GucSource source);
--
On Wed, 10 Jul 2024 at 16:58, Greg Sabino Mullane <htamfids@gmail.com>
wrote:
--snip--
Why not build a more generic log filtering case?
I looked into this, but it would be a large undertaking, given the way our
logging system works. And as per above, I don't think the pain would be
worth it, as duration covers 99% of the use cases for separate logs.
The other category of logging which would benefit from a separate file is
audit. It also can create massive volumes of log content. Splitting audit
information off into a separate file for use by a separate team or function
is also a request I have heard from some financial institutions adopting
Postgres. With audit being provided by an extension, this would become
quite an intrusive change.
Why not use an extension for this?
I did start this as an extension, but it only goes so far. We can use
emit_log_hook, but it requires careful coordination of open filehandles,
has to do inefficient regex of every log message, and cannot do things like
log rotation.
Would an extension be able to safely modify the message_type field you have
added using emit_log_hook? If so, the field becomes more of a log
destination label than a type marker. If an extension could hook into the
log file creation/rotation process, that would be a nice basis for enabling
extensions (I'm particularly thinking of pgAudit) to manage separate
logging destinations.
On Thu, Jul 11, 2024 at 6:47 AM Alastair Turner <minion@decodable.me> wrote:
The other category of logging which would benefit from a separate file is
audit. It also can create massive volumes of log content. Splitting audit
information off into a separate file for use by a separate team or function
is also a request I have heard from some financial institutions adopting
Postgres. With audit being provided by an extension, this would become
quite an intrusive change.
Thanks for the feedback. I agree pgaudit is another thing that can create
massive log files, and should be solved at some point. However, I wanted
to keep this patch self-contained to in-core stuff. And pgaudit is already
an odd duck, in that it puts CSV into your stderr stream (and into your
json!). Ideally it would put a single CSV stream into a separate csv file.
Perhaps even something that did not necessarily live in log_directory.
Would an extension be able to safely modify the message_type field you have
added using emit_log_hook? If so, the field becomes more of a log
destination label than a type marker. If an extension could hook into the
log file creation/rotation process, that would be a nice basis for enabling
extensions (I'm particularly thinking of pgAudit) to manage separate
logging destinations.
Yes, I had more than duration in mind when I created errmessagetype. A hook
to set it would be the obvious next step, and then some sort of way of
mapping that to arbitrary log files. But I see that as mostly orthagonal to
this patch (and certainly a much larger endeavor).
(wades in anyways). I'm not sure about hooking into the log rotation
process so much as registering something on startup, then letting Postgres
handle all the log files in the queue. Although as I alluded to above,
sometimes having large log files NOT live in the data directory (or more
specifically, not hang out with the log_directory crowd), could be a plus
for space, efficiency, and security reasons. That makes log rotation
harder, however. And do we / should we put extension-driven logfiles into
current_logfiles? Do we still fall back to stderr even for extension logs?
Lots to ponder. :)
Cheers,
Greg
On Fri, 12 Jul 2024 at 15:58, Greg Sabino Mullane <htamfids@gmail.com>
wrote:
On Thu, Jul 11, 2024 at 6:47 AM Alastair Turner <minion@decodable.me>
wrote:The other category of logging which would benefit from a separate file
is audit. It also can create massive volumes of log content. Splitting
audit information off into a separate file for use by a separate team or
function is also a request I have heard from some financial institutions
adopting Postgres. With audit being provided by an extension, this would
become quite an intrusive change.Thanks for the feedback. I agree pgaudit is another thing that can create
massive log files, and should be solved at some point. However, I wanted
to keep this patch self-contained to in-core stuff. And pgaudit is already
an odd duck, in that it puts CSV into your stderr stream (and into your
json!). Ideally it would put a single CSV stream into a separate csv file.
Perhaps even something that did not necessarily live in log_directory.Would an extension be able to safely modify the message_type field you
have added using emit_log_hook? If so, the field becomes more of a log
destination label than a type marker. If an extension could hook into the
log file creation/rotation process, that would be a nice basis for enabling
extensions (I'm particularly thinking of pgAudit) to manage separate
logging destinations.Yes, I had more than duration in mind when I created errmessagetype. A
hook to set it would be the obvious next step, and then some sort of way of
mapping that to arbitrary log files. But I see that as mostly orthagonal to
this patch (and certainly a much larger endeavor).
Ok. This facility to separate out the logging of the duration messages is
useful on its own and I can see the reasoning for using the core
functionality for log rotation to manage these separate logs rather than
redoing all the file handling work in an extension. A broader framework for
mapping messages to arbitrary log files is a far larger set of changes
which can be tackled later if desired.
I've had a look at the patch. The test cases look comprehensive. The patch
applies cleanly. The newly supplied tests (13 of the 40) and the
test_misc/003_check_guc (1 - no parameters missing from
postgresql.conf.sample) fail.
To leave some runway for this idea to be extended on without disrupting the
user experience could the GUC name be feature qualified as
duration_log.log_destination? This would provide a clear naming structure
for the most obvious follow-on patch to this one - allowing users to set
log_directory separately for these duration logs - as well as any further
separate logging efforts. I know that these dot-separated GUC names are
generally associated with extensions, but I can't find a hard rule on the
issue anywhere, and it feels like a reasonable way to group up the purpose
(in this case logging duration messages) for which there are specific
values of a number of GUCs (log_destination, log_directory, even
log_filename, ...).
Cheers
Alastair
Show quoted text
Hi
st 10. 7. 2024 v 17:58 odesílatel Greg Sabino Mullane <htamfids@gmail.com>
napsal:
Please find attached a patch to allow for durations to optionally be sent
to separate log files. In other words, rather than cluttering up our
postgres202007.log file with tons of output from
log_min_duration_statement, duration lines are sent instead to the file
postgres202007.duration.Over the years, durations have been the number one cause of very large log
files, in which the more "important" items get buried in the noise. Also,
programs that are scanning for durations typically do not care about the
normal, non-duration output. Some people have a policy of logging
everything, which in effect means setting log_min_duration_statement to 0,
which in turn makes your log files nearly worthless for spotting
non-duration items. This feature will also be very useful for those who
need to temporarily turn on log_min_duration_statement, for some quick
auditing of exactly what is being run on their database. When done, you can
move or remove the duration file without messing up your existing log
stream.This only covers the case when both the duration and statement are set on
the same line. In other words, log_min_duration_statement output, but not
log_duration (which is best avoided anyway). It also requires
logging_collector to be on, obviously.Details:
The edata structure is expanded to have a new message_type, with a
matching function errmessagetype() created.
[include/utils/elog.h]
[backend/utils/elog.c]Any errors that have both a duration and a statement are marked via
errmessagetype()
[backend/tcop/postgres.c]A new GUC named "log_duration_destination" is created, which supports any
combination of stderr, csvlog, and jsonlog. It does not need to match
log_destination, in order to support different use cases. For example, the
user wants durations sent to a CSV file for processing by some other tool,
but still wants everything else going to a normal text log file.Code: [include/utils/guc_hooks.h] [backend/utils/misc/guc_tables.c]
Docs: [sgml/config.sgml] [backend/utils/misc/postgresql.conf.sample]Create a new flag called PIPE_PROTO_DEST_DURATION
[include/postmaster/syslogger.h]Create new flags:
LOG_DESTINATION_DURATION,
LOG_DESTINATION_DURATION_CSV,
LOG_DESTINATION_DURATION_JSON
[include/utils/elog.h]Routing and mapping LOG_DESTINATION to PIPE_PROTO
[backend/utils/error/elog.c]Minor rerouting when using alternate forms
[backend/utils/error/csvlog.c]
[backend/utils/error/jsonlog.c]Create new filehandles, do log rotation, map PIPE_PROTO to
LOG_DESTINATION. Rotation and entry into the "current_logfiles" file are
the same as existing log files. The new names/suffixes are duration,
duration.csv, and duration.json.
[backend/postmaster/syslogger.c]Testing to ensure combinations of log_destination and
log_duration_destination work as intended
[bin/pg_ctl/meson.build]
[bin/pg_ctl/t/005_log_duration_destination.pl]Questions I've asked along the way, and perhaps other might as well:
What about logging other things? Why just duration?
Duration logging is a very unique event in our logs. There is nothing
quite like it - it's always client-driven, yet automatically generated. And
it can be extraordinarily verbose. Removing it from the existing logging
stream has no particular downsides. Almost any other class of log message
would likely meet resistance as far as moving it to a separate log file,
with good reason.Why not build a more generic log filtering case?
I looked into this, but it would be a large undertaking, given the way our
logging system works. And as per above, I don't think the pain would be
worth it, as duration covers 99% of the use cases for separate logs.
Certainly, nothing else other than a recurring ERROR from the client can
cause massive bloat in the size of the files. (There is a nearby patch to
exclude certain errors from the log file as a way to mitigate the error
spam - I don't like that idea, but should mention it here as another effort
to keep the log files a manageable size)Why not use an extension for this?
I did start this as an extension, but it only goes so far. We can use
emit_log_hook, but it requires careful coordination of open filehandles,
has to do inefficient regex of every log message, and cannot do things like
log rotation.Why not bitmap PIPE_PROTO *and* LOG_DESTINATION?
I tried to do both as simple bitmaps (i.e. duration+csv = duration.csv),
and not have to use e.g. LOG_DESTIATION_DURATION_CSV, but size_rotation_for
ruined it for me. Since our PIPE always sends one thing at a time, a single
new flag enables it to stay as a clean bits8 type.What about Windows?
Untested. I don't have access to a Windows build, but I think in theory it
should work fine.
I like the proposed feature, but I miss two points.
1. possibility to support auto_explain
2. possibility to support rsyslog by setting different or some syslog
related redirection by setting different facility.
Regards
Pavel
Show quoted text
Cheers,
Greg
Thanks for the feedback on this, everyone. I think, given the lack of
committer enthusiasm, I may have to go the route of redesigning the logging
system completely. At any rate, I cannot circle back to this for a while.
2. possibility to support rsyslog by setting different or some syslog
related redirection by setting different facility.
Yes, that would be nice. Perhaps I'll push just the message_type bit, which
seems to be a common precursor to many of these ideas.
Cheers,
Greg