From ca4a8b558742f247e3c9e5d388dacd4ef918e154 Mon Sep 17 00:00:00 2001 From: Tomas Vondra Date: Mon, 4 Nov 2019 01:57:45 +0100 Subject: [PATCH 2/2] log_min_duration_sample rework --- doc/src/sgml/config.sgml | 85 +++++++++++++++++++ src/backend/tcop/postgres.c | 40 ++++++--- src/backend/utils/misc/guc.c | 27 +++++- src/backend/utils/misc/postgresql.conf.sample | 11 +++ src/include/utils/guc.h | 2 + 5 files changed, 153 insertions(+), 12 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 48d7939d2d..e5372d933c 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -5930,6 +5930,55 @@ local0.* /var/log/postgresql + + log_min_duration_sample (integer) + + log_min_duration_sample configuration parameter + + + + + Allows to sample the logging of the duration of each completed + statement if the statement ran for at least the specified amount of + time. If this value is specified without units, it is taken as milliseconds. + Setting this to zero samples all statement durations. + Minus-one (the default) disables sampling statement durations. + For example, if you set it to 250ms + then all SQL statements that run 250ms or longer will be considered + for sampling, with sample rate is controlled by . + Enabling this parameter can be helpful when the traffic too high to + sample all queries. + Only superusers can change this setting. + + + + This option has lower priority than , + which means setting this to a value higher than + means the sample rate is ignored and all queries will be logged. + + + + For clients using extended query protocol, durations of the Parse, + Bind, and Execute steps are logged independently. + + + + + When using this option together with + , + the text of statements that are logged because of + log_statement will not be repeated in the + duration log message. + If you are not using syslog, it is recommended + that you log the PID or session ID using + + so that you can link the statement message to the later + duration message using the process ID or session ID. + + + + + log_min_duration_statement (integer) @@ -5950,6 +5999,12 @@ local0.* /var/log/postgresql Only superusers can change this setting. + + This overrides , + meaning that queries with duration exceeding this setting are not + subject to sampling and are always logged. + + For clients using extended query protocol, durations of the Parse, Bind, and Execute steps are logged independently. @@ -5972,6 +6027,36 @@ local0.* /var/log/postgresql + + log_statement_sample_rate (real) + + log_statement_sample_rate configuration parameter + + + + + Determines the fraction of statements exceeding + to be logged. + This is a statistical parameter, for example 0.5 + means there is statiscally one in two chances to log the statement. + The default is 1.0, meaning log all such + statements. + Setting this to zero disables sampling logging, same as setting + log_min_duration_sample to + -1. + log_statement_sample_rate is helpful when the + traffic is too high to log all queries. + Only superusers can change this setting. + + + + Like all statement-logging options, this option can add significant + overhead. + + + + + log_transaction_sample_rate (real) diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 4bec40aa28..82894eadc6 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -2235,12 +2235,15 @@ check_log_statement(List *stmt_list) int check_log_duration(char *msec_str, bool was_logged) { - if (log_duration || log_min_duration_statement >= 0 || xact_is_sampled) + if (log_duration || log_min_duration_sample >= 0 || + log_min_duration_statement >= 0 || xact_is_sampled) { long secs; int usecs; int msecs; - bool exceeded; + bool exceeded_duration; + bool exceeded_sample_duration; + bool in_sample = false; TimestampDifference(GetCurrentStatementStartTimestamp(), GetCurrentTimestamp(), @@ -2248,20 +2251,35 @@ check_log_duration(char *msec_str, bool was_logged) msecs = usecs / 1000; /* - * This odd-looking test for log_min_duration_statement being exceeded - * is designed to avoid integer overflow with very long durations: - * don't compute secs * 1000 until we've verified it will fit in int. + * This odd-looking test for log_min_duration_* being exceeded is + * designed to avoid integer overflow with very long durations: don't + * compute secs * 1000 until we've verified it will fit in int. */ - exceeded = (log_min_duration_statement == 0 || - (log_min_duration_statement > 0 && - (secs > log_min_duration_statement / 1000 || - secs * 1000 + msecs >= log_min_duration_statement))); + exceeded_duration = (log_min_duration_statement == 0 || + (log_min_duration_statement > 0 && + (secs > log_min_duration_statement / 1000 || + secs * 1000 + msecs >= log_min_duration_statement))); - if (exceeded || log_duration || xact_is_sampled) + exceeded_sample_duration = (log_min_duration_sample == 0 || + (log_min_duration_sample > 0 && + (secs > log_min_duration_sample / 1000 || + secs * 1000 + msecs >= log_min_duration_sample))); + + /* + * Do not log if log_statement_sample_rate = 0. Log a sample if + * log_statement_sample_rate <= 1 and avoid unecessary random() call + * if log_statement_sample_rate = 1. + */ + if (exceeded_sample_duration) + in_sample = log_statement_sample_rate != 0 && + (log_statement_sample_rate == 1 || + random() <= log_statement_sample_rate * MAX_RANDOM_VALUE); + + if (exceeded_duration || in_sample || log_duration || xact_is_sampled) { snprintf(msec_str, 32, "%ld.%03d", secs * 1000 + msecs, usecs % 1000); - if ((exceeded || xact_is_sampled) && !was_logged) + if ((exceeded_duration || in_sample || xact_is_sampled) && !was_logged) return 2; else return 1; diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index 31a5ef0474..e84c8cc4cf 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -509,8 +509,10 @@ bool session_auth_is_superuser; int log_min_error_statement = ERROR; int log_min_messages = WARNING; int client_min_messages = NOTICE; +int log_min_duration_sample = -1; int log_min_duration_statement = -1; int log_temp_files = -1; +double log_statement_sample_rate = 1.0; double log_xact_sample_rate = 0; int trace_recovery_messages = LOG; @@ -2700,10 +2702,23 @@ static struct config_int ConfigureNamesInt[] = NULL, NULL, NULL }, + { + {"log_min_duration_sample", PGC_SUSET, LOGGING_WHEN, + gettext_noop("Sets the minimum execution time above which " + "a sample of statements will be logged." + " Sampling is determined by log_statement_sample_rate."), + gettext_noop("Zero log a sample of all queries. -1 turns this feature off."), + GUC_UNIT_MS + }, + &log_min_duration_sample, + -1, -1, INT_MAX, + NULL, NULL, NULL + }, + { {"log_min_duration_statement", PGC_SUSET, LOGGING_WHEN, gettext_noop("Sets the minimum execution time above which " - "statements will be logged."), + "all statements will be logged."), gettext_noop("Zero prints all queries. -1 turns this feature off."), GUC_UNIT_MS }, @@ -3430,6 +3445,16 @@ static struct config_real ConfigureNamesReal[] = NULL, NULL, NULL }, + { + {"log_statement_sample_rate", PGC_SUSET, LOGGING_WHEN, + gettext_noop("Fraction of statements exceeding log_min_duration_sample to be logged."), + gettext_noop("Use a value between 0.0 (never log) and 1.0 (always log).") + }, + &log_statement_sample_rate, + 1.0, 0.0, 1.0, + NULL, NULL, NULL + }, + { {"log_transaction_sample_rate", PGC_SUSET, LOGGING_WHEN, gettext_noop("Set the fraction of transactions to log for new transactions."), diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index 0fc23e3a61..be02a76d9d 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -493,6 +493,17 @@ # statements running at least this number # of milliseconds +#log_min_duration_sample = -1 # -1 is disabled, 0 logs a sample of statements + # and their durations, > 0 logs only a sample of + # statements running at least this number + # of milliseconds + # Sample fraction is determined by log_statement_sample_rate + +#log_statement_sample_rate = 1.0 # Fraction of logged statements exceeding + # log_min_duration_sample to be logged. + # 1.0 logs all such statements, 0.0 never logs. + + #log_transaction_sample_rate = 0.0 # Fraction of transactions whose statements # are logged regardless of their duration. 1.0 logs all # statements from all transactions, 0.0 never logs. diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h index 6791e0cbc2..9aa3d02596 100644 --- a/src/include/utils/guc.h +++ b/src/include/utils/guc.h @@ -251,8 +251,10 @@ extern bool session_auth_is_superuser; extern int log_min_error_statement; extern PGDLLIMPORT int log_min_messages; extern PGDLLIMPORT int client_min_messages; +extern int log_min_duration_sample; extern int log_min_duration_statement; extern int log_temp_files; +extern double log_statement_sample_rate; extern double log_xact_sample_rate; extern int temp_file_limit; -- 2.21.0