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
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); --