On Tue, Jul 30, 2019 at 03:43:58PM -0400, Tom Lane wrote:
Tomas Vondra <tomas.von...@2ndquadrant.com> writes:
I've started reviewing this patch, thinking that maybe I could get it
committed as it's marked as RFC. In general I agree with having this
fuature, but I think we need to rethink the GUC because the current
approach is just confusing.
...
What I think we should do instead is 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
I think this is going to be much easier for users to understand.
I agree with Tomas' idea.
The one difference between those approaches is in how they work with
existing current settings. That is, let's say you have
log_min_duration_statement = 1000
log_statement_sample_rate = 0.01
then no queries below 1000ms will be logged, and 1% of longer queries
will be sampled. And with the original config (as proposed in v3 of the
patch), this would still work the same way.
With the new approach (two min thresholds) it'd behave differently,
because we'd log *all* queries longer than 1000ms (not just 1%). And
whether we'd sample any queries (using log_statement_sample_rate) would
depend on how we'd pick the default value for the other threshold.
Well, we do not need to have a backwards-compatibility problem
here, because we have yet to release a version containing
log_statement_sample_rate. I do not think it's too late to decide
that v12's semantics for that are broken, and either revert that
patch in v12, or back-patch a fix to make it match this idea.
I'm willing to try fixing this to salvage the feature for v12. The
question is how would that fix look like - IMO we'd need to introduce
the new threshold GUC, essentially implementing what this thread is
about. It's not a complex patch, but it kinda flies in the face of
feature freeze. OTOH if we call it a fix ...
The patch itself is not that complicated - attached is a WIP version,
(particularly) the docs need more work.
regards
--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c91e3e1550..8cb695044b 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5850,8 +5850,7 @@ local0.* /var/log/postgresql
<para>
Causes the duration of each completed statement to be logged
if the statement ran for at least the specified number of
- milliseconds, modulated by
<varname>log_statement_sample_rate</varname>.
- Setting this to zero prints all statement durations.
+ milliseconds. Setting this to zero prints all statement durations.
<literal>-1</literal> (the default) disables logging statements due to
exceeding duration threshold; for example, if you set it to
<literal>250ms</literal>, then all SQL statements that run 250ms or
@@ -5882,6 +5881,48 @@ 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>
+ Causes the duration of each completed statement to be logged
+ if the statement ran for at least the specified number of
+ milliseconds, modulated by
<varname>log_statement_sample_rate</varname>.
+ Setting this to zero samples all statement durations.
+ <literal>-1</literal> (the default) disables sampling of statements;
+ for example, if you set it to <literal>250ms</literal>, then all
+ SQL statements that run 250ms or longer will be sampled for
+ logging. Statements with duration exceeding
+ <varname>log_min_duration_statement</varname> are not subject to
+ sampling and are logged every time.
+ </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-statement-sample-rate"
xreflabel="log_statement_sample_rate">
<term><varname>log_statement_sample_rate</varname> (<type>real</type>)
<indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index a6505c7335..ae1def0f37 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2213,7 +2213,8 @@ check_log_statement(List *stmt_list)
/*
* check_log_duration
* Determine whether current command's duration should be logged.
- * If log_statement_sample_rate < 1.0, log only a sample.
+ * If log_statement_sample_rate < 1.0, log only a sample of queries
+ * between log_min_duration_sample and log_min_duration_statement.
* We also check if this statement in this transaction must be
logged
* (regardless of its duration).
*
@@ -2231,12 +2232,14 @@ 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_statement >= 0 ||
+ log_min_duration_sample || xact_is_sampled)
{
long secs;
int usecs;
int msecs;
bool exceeded;
+ bool exceeded_sample;
bool in_sample;
TimestampDifference(GetCurrentStatementStartTimestamp(),
@@ -2254,18 +2257,26 @@ check_log_duration(char *msec_str, bool was_logged)
(secs > log_min_duration_statement /
1000 ||
secs * 1000 + msecs >=
log_min_duration_statement)));
+ /*
+ * Use the same odd-looking test for log_min_duration_sample.
+ */
+ exceeded_sample = (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 unnecessary
random() call
* if log_statement_sample_rate = 1. But don't compute any of
this
* unless needed.
*/
- in_sample = exceeded &&
+ in_sample = exceeded_sample &&
log_statement_sample_rate != 0 &&
(log_statement_sample_rate == 1 ||
random() <= log_statement_sample_rate *
MAX_RANDOM_VALUE);
- if ((exceeded && in_sample) || log_duration || xact_is_sampled)
+ if ((exceeded || in_sample) || log_duration || xact_is_sampled)
{
snprintf(msec_str, 32, "%ld.%03d",
secs * 1000 + msecs, usecs % 1000);
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index fc463601ff..b3d687b1a7 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -510,6 +510,7 @@ int log_min_error_statement = ERROR;
int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_statement = -1;
+int log_min_duration_sample = -1;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@@ -2705,8 +2706,7 @@ static struct config_int ConfigureNamesInt[] =
{"log_min_duration_statement", PGC_SUSET, LOGGING_WHEN,
gettext_noop("Sets the minimum execution time above
which "
"statements will be logged."),
- gettext_noop("Zero prints all queries, subject to
log_statement_sample_rate. "
- "-1 turns this feature off."),
+ gettext_noop("Zero prints all queries, -1 turns this
feature off."),
GUC_UNIT_MS
},
&log_min_duration_statement,
@@ -2714,6 +2714,19 @@ 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 "
+ "statements will be sampled
for logging."),
+ gettext_noop("Zero samples all queries, subject to
log_statement_sample_rate. "
+ "-1 turns this feature off."),
+ GUC_UNIT_MS
+ },
+ &log_min_duration_sample,
+ -1, -1, INT_MAX,
+ NULL, NULL, NULL
+ },
+
{
{"log_autovacuum_min_duration", PGC_SIGHUP, LOGGING_WHAT,
gettext_noop("Sets the minimum execution time above
which "
diff --git a/src/backend/utils/misc/postgresql.conf.sample
b/src/backend/utils/misc/postgresql.conf.sample
index cfad86c02a..2fa2871137 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -488,10 +488,14 @@
# fatal
# panic (effectively off)
-#log_min_duration_statement = -1 # logs statements and their durations
+#log_min_duration_statement = -1 # logs statements and their durations.
+ # -1 is disabled, 0 logs all
statements, > 0 logs only
+ # statements running at least this
number of milliseconds.
+
+#log_min_duration_sample = -1 # logs statements and their durations
# according to
log_statement_sample_rate. -1 is disabled,
- # 0 logs all statements, > 0 logs only
statements running
- # at least this number of milliseconds.
+ # 0 samples all statements, > 0 samples
only statements
+ # running at least this number of
milliseconds.
#log_statement_sample_rate = 1.0 # Fraction of logged statements
exceeding
# log_min_duration_statement to be
logged.
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index e709177c37..544a33fcd5 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -252,6 +252,7 @@ extern int log_min_error_statement;
extern PGDLLIMPORT int log_min_messages;
extern PGDLLIMPORT int client_min_messages;
extern int log_min_duration_statement;
+extern int log_min_duration_sample;
extern int log_temp_files;
extern double log_statement_sample_rate;
extern double log_xact_sample_rate;
