Hello, This patch propose a new way to sample statement to logs.
As a reminder, this feature was committed in PG12[1] then reverted[2] after the proposition of log_statement_sample_limit[3] The first implementation added a new GUC to sample statement logged by log_min_duration_statement. Then, we wanted to add the ability to log all statement whose duration exceed log_statement_sample_limit. This was confusing because log_min_duration behaves as a minimum to enable sampling. While log_statement_sample_limit behave as maximum to disable it.[4] Tomas Vondra proposed to use two minimum thresholds: > 1) log_min_duration_sample - enables sampling of commands, using the > existing GUC log_statement_sample_rate > > 2) log_min_duration_statement - logs all commands exceeding this This patch implement this idea. PS: I notice I forgot to mention "Only superusers can change this setting" in the log_transaction_sample_rate documentation. It attached a second patch to fix this. Regards, 1: https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=799e220346f1387e823a4dbdc3b1c8c3cdc5c3e0 2: https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=75506195da81d75597a4025b72f8367e6c45f60d 3: https://www.postgresql.org/message-id/CAFj8pRDS8tQ3Wviw9%3DAvODyUciPSrGeMhJi_WPE%2BEB8%2B4gLL-Q%40mail.gmail.com 4: https://www.postgresql.org/message-id/20190727221948.irg6sfqh57dynoc7%40development -- Adrien NAYRAT
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index f69b04db05..ef25cf1e96 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5985,6 +5985,7 @@ local0.* /var/log/postgresql
logs all statements for all transactions.
<varname>log_transaction_sample_rate</varname> is helpful to track a
sample of transaction.
+ Only superusers can change this setting.
</para>
<note>
<para>
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 886632ff43..f69b04db05 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5855,6 +5855,49 @@ local0.* /var/log/postgresql
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-min-duration-sample" xreflabel="log_min_duration_sample">
+ <term><varname>log_min_duration_sample</varname> (<type>integer</type>)
+ <indexterm>
+ <primary><varname>log_min_duration_sample</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Allows to sample the logging of the duration of each completed
+ statement if the statement ran for at least the specified duration
+ (default in milliseconds). Setting this to zero sample all statement
+ durations. Minus-one (the default) disables sampling statement durations.
+ Sampling is controlled by <xref linkend="guc-log-statement-sample-rate"/>.
+ For example, if you set it to <literal>250ms</literal>
+ then all SQL statements that run 250ms or longer will be
+ sampled to logs. Enabling this parameter can be helpful when the traffic
+ is too high to log all queries.
+ Only superusers can change this setting.
+ </para>
+
+ <para>
+ For clients using extended query protocol, durations of the Parse,
+ Bind, and Execute steps are logged independently.
+ </para>
+
+ <note>
+ <para>
+ When using this option together with
+ <xref linkend="guc-log-statement"/>,
+ the text of statements that are logged because of
+ <varname>log_statement</varname> will not be repeated in the
+ duration log message.
+ If you are not using <application>syslog</application>, it is recommended
+ that you log the PID or session ID using
+ <xref linkend="guc-log-line-prefix"/>
+ so that you can link the statement message to the later
+ duration message using the process ID or session ID.
+ </para>
+ </note>
+ </listitem>
+ </varlistentry>
+
+
<varlistentry id="guc-log-min-duration-statement" xreflabel="log_min_duration_statement">
<term><varname>log_min_duration_statement</varname> (<type>integer</type>)
<indexterm>
@@ -5894,7 +5937,37 @@ local0.* /var/log/postgresql
</para>
</note>
</listitem>
- </varlistentry>
+ </varlistentry>
+
+ <varlistentry id="guc-log-statement-sample-rate" xreflabel="log_statement_sample_rate">
+ <term><varname>log_statement_sample_rate</varname> (<type>real</type>)
+ <indexterm>
+ <primary><varname>log_statement_sample_rate</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Determines the fraction of statements that exceed
+ <xref linkend="guc-log-min-duration-sample"/> to be logged.
+ This is a statistical parameter, for example <literal>0.5</literal>
+ means there is statiscally one in two chances to log the statement.
+ The default is <literal>1.0</literal>, meaning log all such
+ statements.
+ Setting this to zero disables sample logging, same as setting
+ <varname>log_min_duration_sample</varname> to
+ <literal>-1</literal>.
+ <varname>log_statement_sample_rate</varname> is helpful when the
+ traffic is too high to log all queries.
+ Only superusers can change this setting.
+ </para>
+ <note>
+ <para>
+ Like all statement-logging options, this option can add significant
+ overhead.
+ </para>
+ </note>
+ </listitem>
+ </varlistentry>
<varlistentry id="guc-log-transaction-sample-rate" xreflabel="log_transaction_sample_rate">
<term><varname>log_transaction_sample_rate</varname> (<type>real</type>)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index e8d8e6f828..6cdc4f3349 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2230,12 +2230,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(),
@@ -2243,20 +2246,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;
signature.asc
Description: OpenPGP digital signature
