idea: log_statement_sample_rate - bottom limit for sampling

Started by Pavel Stehuleover 6 years ago28 messages
#1Pavel Stehule
pavel.stehule@gmail.com

Hi

I like the idea of sampling slow statements via log_statement_sample_rate.
But I miss some parameter that can ensure so every query executed over this
limit is logged.

Can we introduce new option

log_statement_sampling_limit

The query with execution time over this limit is logged every time.

What do you think about this?

Regards

Pavel

#2Gilles Darold
gilles@darold.net
In reply to: Pavel Stehule (#1)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Le 06/06/2019 à 10:38, Pavel Stehule a écrit :

Hi

I like the idea of sampling slow statements via 
log_statement_sample_rate. But I miss some parameter that can ensure
so every query executed over this limit is logged.

Can we introduce new option

log_statement_sampling_limit

The query with execution time over this limit is logged every time.

What do you think about this?

Regards

Pavel

+1, log_min_duration_statement is modulated by log_statement_sample_rate
that mean that there is no more way to log all statements over a certain
duration limit. log_statement_sampling_limit might probably always be
upper than log_min_duration_statement.

--
Gilles Darold
http://www.darold.net/

#3Pavel Stehule
pavel.stehule@gmail.com
In reply to: Gilles Darold (#2)
1 attachment(s)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Hi

čt 6. 6. 2019 v 10:48 odesílatel Gilles Darold <gilles@darold.net> napsal:

Le 06/06/2019 à 10:38, Pavel Stehule a écrit :

Hi

I like the idea of sampling slow statements via
log_statement_sample_rate. But I miss some parameter that can ensure
so every query executed over this limit is logged.

Can we introduce new option

log_statement_sampling_limit

The query with execution time over this limit is logged every time.

What do you think about this?

Regards

Pavel

+1, log_min_duration_statement is modulated by log_statement_sample_rate
that mean that there is no more way to log all statements over a certain
duration limit. log_statement_sampling_limit might probably always be
upper than log_min_duration_statement.

Here is a patch

Regards

Pavel

Show quoted text

--
Gilles Darold
http://www.darold.net/

Attachments:

log_statement_sample_limit.patchtext/x-patch; charset=US-ASCII; name=log_statement_sample_limit.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 84341a30e5..690f54f731 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5903,6 +5903,21 @@ local0.*    /var/log/postgresql
        </listitem>
       </varlistentry>
 
+     <varlistentry id="guc-log-statement-sample-limit" xreflabel="log_statement_sample_limit">
+      <term><varname>log_statement_sample_limit</varname> (<type>integer</type>)
+      <indexterm>
+       <primary><varname>log_statement_sample_limit</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+       <listitem>
+        <para>
+         Only if query duration is less than this value, the log sampling is active.
+         When <varname>log_statement_sample_limit</varname> is <literal>-1</literal>
+         then log sampling is without limit.
+        </para>
+       </listitem>
+      </varlistentry>
+
      <varlistentry id="guc-log-transaction-sample-rate" xreflabel="log_transaction_sample_rate">
       <term><varname>log_transaction_sample_rate</varname> (<type>real</type>)
       <indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1d4f..2d8cc7d411 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2193,7 +2193,9 @@ 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 and duration
+ *		is less than log_statement_sample_limit. log_statement_sample_limit
+ *		is used only if this value is different than -1.
  *		We also check if this statement in this transaction must be logged
  *		(regardless of its duration).
  *
@@ -2217,6 +2219,7 @@ check_log_duration(char *msec_str, bool was_logged)
 		int			usecs;
 		int			msecs;
 		bool		exceeded;
+		bool		every_time;
 		bool		in_sample;
 
 		TimestampDifference(GetCurrentStatementStartTimestamp(),
@@ -2234,6 +2237,15 @@ check_log_duration(char *msec_str, bool was_logged)
 					 (secs > log_min_duration_statement / 1000 ||
 					  secs * 1000 + msecs >= log_min_duration_statement)));
 
+		/*
+		 * When log_statement_sample_limit is exceeded, then query is
+		 * logged every time.
+		 */
+		every_time = (log_statement_sample_limit == 0 ||
+					  (log_statement_sample_limit > 0 &&
+					   (secs > log_statement_sample_limit / 1000 ||
+						secs * 1000 + msecs >= log_statement_sample_limit)));
+
 		/*
 		 * Do not log if log_statement_sample_rate = 0. Log a sample if
 		 * log_statement_sample_rate <= 1 and avoid unnecessary random() call
@@ -2245,7 +2257,7 @@ check_log_duration(char *msec_str, bool was_logged)
 			(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 || every_time)) || 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 1208eb9a68..b0c7d9df0e 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_statement_sample_limit = -1;
 int			log_temp_files = -1;
 double		log_statement_sample_rate = 1.0;
 double		log_xact_sample_rate = 0;
@@ -2715,6 +2716,19 @@ static struct config_int ConfigureNamesInt[] =
 		NULL, NULL, NULL
 	},
 
+	{
+		{"log_statement_sample_limit", PGC_SUSET, LOGGING_WHEN,
+			gettext_noop("Sets the maximum execution time for sampling "
+						 "logged statements."),
+			gettext_noop("Zero effective disables sampling. "
+						 "-1 use sampling every time (without limit)."),
+			GUC_UNIT_MS
+		},
+		&log_statement_sample_limit,
+		-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/include/utils/guc.h b/src/include/utils/guc.h
index e709177c37..8f0c2c59d4 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_statement_sample_limit;
 extern int	log_temp_files;
 extern double log_statement_sample_rate;
 extern double log_xact_sample_rate;
#4Pavel Stehule
pavel.stehule@gmail.com
In reply to: Pavel Stehule (#3)
1 attachment(s)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Hi

po 17. 6. 2019 v 22:40 odesílatel Pavel Stehule <pavel.stehule@gmail.com>
napsal:

Hi

čt 6. 6. 2019 v 10:48 odesílatel Gilles Darold <gilles@darold.net> napsal:

Le 06/06/2019 à 10:38, Pavel Stehule a écrit :

Hi

I like the idea of sampling slow statements via
log_statement_sample_rate. But I miss some parameter that can ensure
so every query executed over this limit is logged.

Can we introduce new option

log_statement_sampling_limit

The query with execution time over this limit is logged every time.

What do you think about this?

Regards

Pavel

+1, log_min_duration_statement is modulated by log_statement_sample_rate
that mean that there is no more way to log all statements over a certain
duration limit. log_statement_sampling_limit might probably always be
upper than log_min_duration_statement.

Here is a patch

I did error in logic - fixed

Show quoted text

Regards

Pavel

--
Gilles Darold
http://www.darold.net/

Attachments:

log_statement_sample_limit-2.patchtext/x-patch; charset=US-ASCII; name=log_statement_sample_limit-2.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 84341a30e5..690f54f731 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5903,6 +5903,21 @@ local0.*    /var/log/postgresql
        </listitem>
       </varlistentry>
 
+     <varlistentry id="guc-log-statement-sample-limit" xreflabel="log_statement_sample_limit">
+      <term><varname>log_statement_sample_limit</varname> (<type>integer</type>)
+      <indexterm>
+       <primary><varname>log_statement_sample_limit</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+       <listitem>
+        <para>
+         Only if query duration is less than this value, the log sampling is active.
+         When <varname>log_statement_sample_limit</varname> is <literal>-1</literal>
+         then log sampling is without limit.
+        </para>
+       </listitem>
+      </varlistentry>
+
      <varlistentry id="guc-log-transaction-sample-rate" xreflabel="log_transaction_sample_rate">
       <term><varname>log_transaction_sample_rate</varname> (<type>real</type>)
       <indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1d4f..11ad1dd012 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2193,7 +2193,9 @@ 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 and duration
+ *		is less than log_statement_sample_limit. log_statement_sample_limit
+ *		is used only if this value is different than -1.
  *		We also check if this statement in this transaction must be logged
  *		(regardless of its duration).
  *
@@ -2217,6 +2219,7 @@ check_log_duration(char *msec_str, bool was_logged)
 		int			usecs;
 		int			msecs;
 		bool		exceeded;
+		bool		every_time;
 		bool		in_sample;
 
 		TimestampDifference(GetCurrentStatementStartTimestamp(),
@@ -2234,6 +2237,14 @@ check_log_duration(char *msec_str, bool was_logged)
 					 (secs > log_min_duration_statement / 1000 ||
 					  secs * 1000 + msecs >= log_min_duration_statement)));
 
+		/*
+		 * When log_statement_sample_limit is exceeded, then query is
+		 * logged every time.
+		 */
+		every_time = (log_statement_sample_limit >= 0 &&
+					   (secs > log_statement_sample_limit / 1000 ||
+						secs * 1000 + msecs >= log_statement_sample_limit));
+
 		/*
 		 * Do not log if log_statement_sample_rate = 0. Log a sample if
 		 * log_statement_sample_rate <= 1 and avoid unnecessary random() call
@@ -2245,7 +2256,7 @@ check_log_duration(char *msec_str, bool was_logged)
 			(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 || every_time)) || 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 1208eb9a68..b0c7d9df0e 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_statement_sample_limit = -1;
 int			log_temp_files = -1;
 double		log_statement_sample_rate = 1.0;
 double		log_xact_sample_rate = 0;
@@ -2715,6 +2716,19 @@ static struct config_int ConfigureNamesInt[] =
 		NULL, NULL, NULL
 	},
 
+	{
+		{"log_statement_sample_limit", PGC_SUSET, LOGGING_WHEN,
+			gettext_noop("Sets the maximum execution time for sampling "
+						 "logged statements."),
+			gettext_noop("Zero effective disables sampling. "
+						 "-1 use sampling every time (without limit)."),
+			GUC_UNIT_MS
+		},
+		&log_statement_sample_limit,
+		-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/include/utils/guc.h b/src/include/utils/guc.h
index e709177c37..8f0c2c59d4 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_statement_sample_limit;
 extern int	log_temp_files;
 extern double log_statement_sample_rate;
 extern double log_xact_sample_rate;
#5Adrien Nayrat
adrien.nayrat@anayrat.info
In reply to: Pavel Stehule (#4)
1 attachment(s)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Hi,

I tried the patch, here my comment:

gettext_noop("Zero effective disables sampling. "
"-1 use sampling every time (without limit)."),

I do not agree with the zero case. In fact, sampling is disabled as soon as
setting is less than log_min_duration_statements. Furthermore, I think we should
provide a more straightforward description for users.

I changed few comments and documentation:

* As we added much more logic in this function with statement and transaction
sampling. And now with statement_sample_rate, it is not easy to understand the
logic on first look. I reword comment in check_log_duration, I hope it is more
straightforward.

* I am not sure if "every_time" is a good naming for the variable. In fact, if
duration exceeds limit we disable sampling. Maybe sampling_disabled is more clear?

* I propose to add some words in log_min_duration_statement and
log_statement_sample_rate documentation.

* Rephrased log_statement_sample_limit documentation, I hope it help
understanding.

Patch attached.

Regards,

--
Adrien

Attachments:

log_statement_sample_limit-3.patchtext/x-patch; name=log_statement_sample_limit-3.patchDownload
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 84341a30e5..ad965a084c 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5850,7 +5850,8 @@ 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>.
+         milliseconds, modulated by <varname>log_statement_sample_rate</varname>
+         and <varname>log_statement_sample_limit</varname>.
          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
@@ -5894,6 +5895,8 @@ local0.*    /var/log/postgresql
          <xref linkend="guc-log-min-duration-statement"/> to be logged.
          The default is <literal>1.0</literal>, meaning log all such
          statements.
+         <varname>log_statement_sample_limit</varname> allows to disable sampling
+         if duration exceeds the limit.
          Setting this to zero disables logging by duration, same as setting
          <varname>log_min_duration_statement</varname> to
          <literal>-1</literal>.
@@ -5903,6 +5906,26 @@ local0.*    /var/log/postgresql
        </listitem>
       </varlistentry>
 
+     <varlistentry id="guc-log-statement-sample-limit" xreflabel="log_statement_sample_limit">
+      <term><varname>log_statement_sample_limit</varname> (<type>integer</type>)
+      <indexterm>
+       <primary><varname>log_statement_sample_limit</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+       <listitem>
+        <para>
+         Disable effect of <varname>log_statement_sample_rate</varname> when
+         statements last longer than the specified limit in milliseconds.
+         Otherwise, statements that last longer than <varname>log_min_duration_statement</varname>
+         but less than <varname>log_statement_sample_limit</varname> are subject
+         to log sampling according to <varname>log_statement_sample_rate</varname>.
+         When <varname>log_statement_sample_limit</varname> is less or equal to
+         <varname>log_min_duration_statement</varname> then log sampling is
+         never applied.
+        </para>
+       </listitem>
+      </varlistentry>
+
      <varlistentry id="guc-log-transaction-sample-rate" xreflabel="log_transaction_sample_rate">
       <term><varname>log_transaction_sample_rate</varname> (<type>real</type>)
       <indexterm>
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1d4f..50b3f839da 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2192,10 +2192,15 @@ 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.
- *		We also check if this statement in this transaction must be logged
- *		(regardless of its duration).
+ *
+ * Determine whether current command's duration should be logged. There is also
+ * sampling mechanism following these rules:
+ *		- If log_statement_sample_rate < 1.0, log only a sample.
+ *		- If log_statement_sample_limit >= 0 and duration exceeds this limit,
+ *		  sampling is ignored, so the command is logged.
+ *
+ * If xact_is_sampled is true (due to log_transaction_sample_rate), it means
+ * the whole transaction is logged (regardless of its duration).
  *
  * Returns:
  *		0 if no logging is needed
@@ -2217,6 +2222,7 @@ check_log_duration(char *msec_str, bool was_logged)
 		int			usecs;
 		int			msecs;
 		bool		exceeded;
+		bool		every_time;
 		bool		in_sample;
 
 		TimestampDifference(GetCurrentStatementStartTimestamp(),
@@ -2234,6 +2240,14 @@ check_log_duration(char *msec_str, bool was_logged)
 					 (secs > log_min_duration_statement / 1000 ||
 					  secs * 1000 + msecs >= log_min_duration_statement)));
 
+		/*
+		 * When log_statement_sample_limit is exceeded, then query is
+		 * logged every time.
+		 */
+		every_time = (log_statement_sample_limit >= 0 &&
+					   (secs > log_statement_sample_limit / 1000 ||
+						secs * 1000 + msecs >= log_statement_sample_limit));
+
 		/*
 		 * Do not log if log_statement_sample_rate = 0. Log a sample if
 		 * log_statement_sample_rate <= 1 and avoid unnecessary random() call
@@ -2245,7 +2259,7 @@ check_log_duration(char *msec_str, bool was_logged)
 			(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 || every_time)) || 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 1208eb9a68..b0c7d9df0e 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_statement_sample_limit = -1;
 int			log_temp_files = -1;
 double		log_statement_sample_rate = 1.0;
 double		log_xact_sample_rate = 0;
@@ -2715,6 +2716,19 @@ static struct config_int ConfigureNamesInt[] =
 		NULL, NULL, NULL
 	},
 
+	{
+		{"log_statement_sample_limit", PGC_SUSET, LOGGING_WHEN,
+			gettext_noop("Sets the maximum execution time for sampling "
+						 "logged statements."),
+			gettext_noop("Zero effective disables sampling. "
+						 "-1 use sampling every time (without limit)."),
+			GUC_UNIT_MS
+		},
+		&log_statement_sample_limit,
+		-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/include/utils/guc.h b/src/include/utils/guc.h
index e709177c37..8f0c2c59d4 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_statement_sample_limit;
 extern int	log_temp_files;
 extern double log_statement_sample_rate;
 extern double log_xact_sample_rate;
#6Pavel Stehule
pavel.stehule@gmail.com
In reply to: Adrien Nayrat (#5)
Re: idea: log_statement_sample_rate - bottom limit for sampling

út 18. 6. 2019 v 14:03 odesílatel Adrien Nayrat <adrien.nayrat@anayrat.info>
napsal:

Hi,

I tried the patch, here my comment:

gettext_noop("Zero effective disables sampling. "
"-1 use sampling every time (without limit)."),

I do not agree with the zero case. In fact, sampling is disabled as soon as
setting is less than log_min_duration_statements. Furthermore, I think we
should
provide a more straightforward description for users.

You have true, but I have not a idea,how to describe it in one line. In
this case the zero is corner case, and sampling is disabled without
dependency on log_min_duration_statement.

I think so this design has only few useful values and ranges

a) higher than log_min_duration_statement .. sampling is active with limit
b) 0 .. for this case - other way how to effective disable sampling - no
dependency on other
c) -1 or negative value - sampling is allowed every time.

Sure, there is range (0..log_min_duration_statement), but for this range
this value has not sense. I think so this case cannot be mentioned in short
description. But it should be mentioned in documentation.

I changed few comments and documentation:

* As we added much more logic in this function with statement and
transaction
sampling. And now with statement_sample_rate, it is not easy to understand
the
logic on first look. I reword comment in check_log_duration, I hope it is
more
straightforward.

* I am not sure if "every_time" is a good naming for the variable. In
fact, if
duration exceeds limit we disable sampling. Maybe sampling_disabled is
more clear?

For me important is following line

(exceeded && (in_sample || every_time))

I think so "every_time" or "always" or "every" is in this context more
illustrative than "sampling_disabled". But my opinion is not strong in this
case, and I have not a problem accept common opinion.

Show quoted text

* I propose to add some words in log_min_duration_statement and
log_statement_sample_rate documentation.

* Rephrased log_statement_sample_limit documentation, I hope it help
understanding.

Patch attached.

Regards,

--
Adrien

#7Adrien Nayrat
adrien.nayrat@anayrat.info
In reply to: Pavel Stehule (#6)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On 6/18/19 8:29 PM, Pavel Stehule wrote:

út 18. 6. 2019 v 14:03 odesílatel Adrien Nayrat <adrien.nayrat@anayrat.info
<mailto:adrien.nayrat@anayrat.info>> napsal:

Hi,

I tried the patch, here my comment:

gettext_noop("Zero effective disables sampling. "
                          "-1 use sampling every time (without limit)."),

I do not agree with the zero case. In fact, sampling is disabled as soon as
setting is less than log_min_duration_statements. Furthermore, I think we should
provide a more straightforward description for users.

You have true, but I have not a idea,how to describe it in one line. In this
case the zero is corner case, and sampling is disabled without dependency on
log_min_duration_statement.
 
I think so this design has only few useful values and ranges

a) higher than log_min_duration_statement .. sampling is active with limit
b) 0 .. for this case - other way how to effective disable sampling - no
dependency on other
c) -1 or negative value - sampling is allowed every time.

Sure, there is range (0..log_min_duration_statement), but for this range this
value has not sense. I think so this case cannot be mentioned in short
description. But it should be mentioned in documentation.

Yes, it took me a while to understand :) I am ok to keep simple in GUC
description and give more information in documentation.

I changed few comments and documentation:

  * As we added much more logic in this function with statement and transaction
sampling. And now with statement_sample_rate, it is not easy to understand the
logic on first look. I reword comment in check_log_duration, I hope it is more
straightforward.

  * I am not sure if "every_time" is a good naming for the variable. In fact, if
duration exceeds limit we disable sampling. Maybe sampling_disabled is more
clear?

For me important is following line

(exceeded && (in_sample || every_time))

I think so "every_time" or "always" or "every" is in this context more
illustrative than "sampling_disabled". But my opinion is not strong in this
case, and I have not a problem accept common opinion.

Oh, yes, that's correct. I do not have a strong opinion too. Maybe someone else
will have better idea.

--
Adrien

#8Pavel Stehule
pavel.stehule@gmail.com
In reply to: Adrien Nayrat (#7)
Re: idea: log_statement_sample_rate - bottom limit for sampling

st 19. 6. 2019 v 10:49 odesílatel Adrien Nayrat <adrien.nayrat@anayrat.info>
napsal:

On 6/18/19 8:29 PM, Pavel Stehule wrote:

út 18. 6. 2019 v 14:03 odesílatel Adrien Nayrat <

adrien.nayrat@anayrat.info

<mailto:adrien.nayrat@anayrat.info>> napsal:

Hi,

I tried the patch, here my comment:

gettext_noop("Zero effective disables sampling. "
"-1 use sampling every time (without

limit)."),

I do not agree with the zero case. In fact, sampling is disabled as

soon as

setting is less than log_min_duration_statements. Furthermore, I

think we should

provide a more straightforward description for users.

You have true, but I have not a idea,how to describe it in one line. In

this

case the zero is corner case, and sampling is disabled without

dependency on

log_min_duration_statement.

I think so this design has only few useful values and ranges

a) higher than log_min_duration_statement .. sampling is active with

limit

b) 0 .. for this case - other way how to effective disable sampling - no
dependency on other
c) -1 or negative value - sampling is allowed every time.

Sure, there is range (0..log_min_duration_statement), but for this range

this

value has not sense. I think so this case cannot be mentioned in short
description. But it should be mentioned in documentation.

Yes, it took me a while to understand :) I am ok to keep simple in GUC
description and give more information in documentation.

Maybe some like. "The zero block sampling. Negative value forces sampling
without limit"

I changed few comments and documentation:

* As we added much more logic in this function with statement and

transaction

sampling. And now with statement_sample_rate, it is not easy to

understand the

logic on first look. I reword comment in check_log_duration, I hope

it is more

straightforward.

* I am not sure if "every_time" is a good naming for the variable.

In fact, if

duration exceeds limit we disable sampling. Maybe sampling_disabled

is more

clear?

For me important is following line

(exceeded && (in_sample || every_time))

I think so "every_time" or "always" or "every" is in this context more
illustrative than "sampling_disabled". But my opinion is not strong in

this

case, and I have not a problem accept common opinion.

Oh, yes, that's correct. I do not have a strong opinion too. Maybe someone
else
will have better idea.

the naming in this case is not hard issue, and comitter can decide.

Regards

Pavel

Show quoted text

--
Adrien

#9Adrien Nayrat
adrien.nayrat@gmail.com
In reply to: Pavel Stehule (#8)
Re: idea: log_statement_sample_rate - bottom limit for sampling

The following review has been posted through the commitfest application:
make installcheck-world: tested, failed
Implements feature: tested, failed
Spec compliant: tested, failed
Documentation: tested, failed

I test the latest patch attached to this thread (log_statement_sample_limit-3.patch). Everything looks good to me.

The new status of this patch is: Ready for Committer

#10Adrien Nayrat
adrien.nayrat@gmail.com
In reply to: Adrien Nayrat (#9)
Re: idea: log_statement_sample_rate - bottom limit for sampling

The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passed

Sorry, I forgot to tick "passed" boxes.

#11Pavel Stehule
pavel.stehule@gmail.com
In reply to: Adrien Nayrat (#10)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Hi

pá 12. 7. 2019 v 13:07 odesílatel Adrien Nayrat <adrien.nayrat@gmail.com>
napsal:

The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passed

Sorry, I forgot to tick "passed" boxes.

Thank you

Pavel

#12Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Pavel Stehule (#11)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Hi,

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.

The way the current patch works is that we have three GUCs:

log_min_duration_statement
log_statement_sample_limit
log_statement_sample_rate

and it essentially works like this:

- If the duration exceeds log_min_duration_statement, we start sampling
the commands with log_statement_sample rate.

- If the duration exceeds log_statement_sample_limit, we just log the
command every time (i.e. we disable sampling, using sample rate 1.0).

IMO that's bound to be confusing for users, because one threshold
behaves as minimum while the other behaves as maximum.

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.

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.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#13Tom Lane
tgl@sss.pgh.pa.us
In reply to: Tomas Vondra (#12)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Tomas Vondra <tomas.vondra@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.

regards, tom lane

#14Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Tom Lane (#13)
1 attachment(s)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Tue, Jul 30, 2019 at 03:43:58PM -0400, Tom Lane wrote:

Tomas Vondra <tomas.vondra@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

Attachments:

log-sample-rework.patchtext/plain; charset=us-asciiDownload
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;
#15Michael Paquier
michael@paquier.xyz
In reply to: Tom Lane (#13)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Tue, Jul 30, 2019 at 03:43:58PM -0400, Tom Lane wrote:

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.

With my RTM hat on, if we think that the current semantics of
log_statement_sample_rate are broken and need a redesign, then I would
take the safest path and just revert the original patch in v12, and
finally make sure that it brews correctly for v13. We are in beta2
and close to a beta3, so redesigning things at this stage on a stable
branch sounds wrong.
--
Michael

#16Adrien Nayrat
adrien.nayrat@anayrat.info
In reply to: Tomas Vondra (#12)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On 7/28/19 12:19 AM, Tomas Vondra wrote:

Hi,

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.

The way the current patch works is that we have three GUCs:

 log_min_duration_statement
 log_statement_sample_limit
 log_statement_sample_rate

and it essentially works like this:

- If the duration exceeds log_min_duration_statement, we start sampling
 the commands with log_statement_sample rate.

- If the duration exceeds log_statement_sample_limit, we just log the
 command every time (i.e. we disable sampling, using sample rate 1.0).

IMO that's bound to be confusing for users, because one threshold
behaves as minimum while the other behaves as maximum.

I agree, it took me a while to understand how it behave with the three GUC. That
why I tried to enrich documentation, but it may mean that the functionality is
not properly implemented.

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.

+1, I like this idea.

I don't really have an opinion if we have to revert the whole feature or try to
fix it for v12. But it is true it is a late to fix it.

Furthermore, users who really want this feature in v12 can use an extension for
that purpose [1].

1: I made this extension with same kind of features :
https://github.com/anayrat/pg_sampletolog

#17Adrien Nayrat
adrien.nayrat@anayrat.info
In reply to: Adrien Nayrat (#16)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Hi,

As we are at the end of this CF and there is still discussions about whether we
should revert log_statement_sample_limit and log_statement_sample_rate, or try
to fix it in v12.
I moved this patch to next commit fest and change status from "ready for
commiter" to "need review". I hope I didn't make a mistake.

Best regards,

#18Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Adrien Nayrat (#17)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Thu, Aug 01, 2019 at 11:47:46AM +0200, Adrien Nayrat wrote:

Hi,

As we are at the end of this CF and there is still discussions about whether we
should revert log_statement_sample_limit and log_statement_sample_rate, or try
to fix it in v12.
I moved this patch to next commit fest and change status from "ready for
commiter" to "need review". I hope I didn't make a mistake.

Thanks. The RFC status was clearly stale, so thanks for updating. I should
have done that after my review. I think the patch would be moved to the
next CF at the end, but I might be wrong. In any case, I don't think
you've done any mistake.

As for the sampling patch - I think we'll end up reverting the feature for
v12 - it's far too late to rework it at this point. Sorry about that, I
know it's not a warm feeling when you get something done, and then it gets
reverted on the last minute. :-(

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#19Adrien Nayrat
adrien.nayrat@anayrat.info
In reply to: Tomas Vondra (#18)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On 8/1/19 12:04 PM, Tomas Vondra wrote:

On Thu, Aug 01, 2019 at 11:47:46AM +0200, Adrien Nayrat wrote:

Hi,

As we are at the end of this CF and there is still discussions about whether we
should revert log_statement_sample_limit and log_statement_sample_rate, or try
to fix it in v12.
I moved this patch to next commit fest and change status from "ready for
commiter" to "need review". I hope I didn't make a mistake.

Thanks. The RFC status was clearly stale, so thanks for updating. I should
have done that after my review. I think the patch would be moved to the
next CF at the end, but I might be wrong. In any case, I don't think
you've done any mistake.

As for the sampling patch - I think we'll end up reverting the feature for
v12 - it's far too late to rework it at this point. Sorry about that, I
know it's not a warm feeling when you get something done, and then it gets
reverted on the last minute. :-(

Don't worry, I understand. It is better to add straigforward GUC in v13 than
confusionning in v12 we will regret.

#20Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Adrien Nayrat (#19)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Fri, Aug 02, 2019 at 09:53:40AM +0200, Adrien Nayrat wrote:

On 8/1/19 12:04 PM, Tomas Vondra wrote:

On Thu, Aug 01, 2019 at 11:47:46AM +0200, Adrien Nayrat wrote:

Hi,

As we are at the end of this CF and there is still discussions about whether we
should revert log_statement_sample_limit and log_statement_sample_rate, or try
to fix it in v12.
I moved this patch to next commit fest and change status from "ready for
commiter" to "need review". I hope I didn't make a mistake.

Thanks. The RFC status was clearly stale, so thanks for updating. I should
have done that after my review. I think the patch would be moved to the
next CF at the end, but I might be wrong. In any case, I don't think
you've done any mistake.

As for the sampling patch - I think we'll end up reverting the feature for
v12 - it's far too late to rework it at this point. Sorry about that, I
know it's not a warm feeling when you get something done, and then it gets
reverted on the last minute. :-(

Don't worry, I understand. It is better to add straigforward GUC in v13 than
confusionning in v12 we will regret.

OK, I have the revert ready. The one thing I'm wondering about is
whether we need to revert log_transaction_sample_rate too? I think it's
pretty much independent feature, so I think we can keep that. Opinions?

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#21Tom Lane
tgl@sss.pgh.pa.us
In reply to: Tomas Vondra (#20)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:

OK, I have the revert ready. The one thing I'm wondering about is
whether we need to revert log_transaction_sample_rate too? I think it's
pretty much independent feature, so I think we can keep that. Opinions?

Isn't the issue here the interaction between log_transaction_sample_rate
and log_min_duration_statement? Seems like we have that question
regardless of whether log_statement_sample_limit exists.

regards, tom lane

#22Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Tom Lane (#21)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Sun, Aug 04, 2019 at 03:16:12PM -0400, Tom Lane wrote:

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:

OK, I have the revert ready. The one thing I'm wondering about is
whether we need to revert log_transaction_sample_rate too? I think it's
pretty much independent feature, so I think we can keep that. Opinions?

Isn't the issue here the interaction between log_transaction_sample_rate
and log_min_duration_statement? Seems like we have that question
regardless of whether log_statement_sample_limit exists.

No, that interaction only affects statement-level sampling.

For transaction-level sampling we do the sampling independently of the
statement duration, i.e. we when starting a transaction we determine
whether the whole transaction will be sampled. It has nothing to do with
the proposed log_statement_sample_limit.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#23Tom Lane
tgl@sss.pgh.pa.us
In reply to: Tomas Vondra (#22)
Re: idea: log_statement_sample_rate - bottom limit for sampling

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:

On Sun, Aug 04, 2019 at 03:16:12PM -0400, Tom Lane wrote:

Isn't the issue here the interaction between log_transaction_sample_rate
and log_min_duration_statement?

No, that interaction only affects statement-level sampling.

OK, I was confusing the features.

For transaction-level sampling we do the sampling independently of the
statement duration, i.e. we when starting a transaction we determine
whether the whole transaction will be sampled. It has nothing to do with
the proposed log_statement_sample_limit.

So, to clarify: our plan is that a given statement will be logged
if any of these various partial-logging features says to do so?

(And the knock on HEAD's behavior is exactly that it breaks that
independence for log_min_duration_statement.)

regards, tom lane

#24Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Tom Lane (#23)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Sun, Aug 04, 2019 at 04:25:12PM -0400, Tom Lane wrote:

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:

On Sun, Aug 04, 2019 at 03:16:12PM -0400, Tom Lane wrote:

Isn't the issue here the interaction between log_transaction_sample_rate
and log_min_duration_statement?

No, that interaction only affects statement-level sampling.

OK, I was confusing the features.

For transaction-level sampling we do the sampling independently of the
statement duration, i.e. we when starting a transaction we determine
whether the whole transaction will be sampled. It has nothing to do with
the proposed log_statement_sample_limit.

So, to clarify: our plan is that a given statement will be logged
if any of these various partial-logging features says to do so?

Yes, I think that's the expected behavior.

- did it exceed log_min_duration_statement? -> log it
- is it part of sampled xact? -> log it
- maybe sample the statement (to be reverted / reimplemented)

(And the knock on HEAD's behavior is exactly that it breaks that
independence for log_min_duration_statement.)

Yeah. There's no way to use sampling, while ensure logging of all
queries longer than some limit.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#25Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Tomas Vondra (#24)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Sun, Aug 04, 2019 at 10:48:48PM +0200, Tomas Vondra wrote:

On Sun, Aug 04, 2019 at 04:25:12PM -0400, Tom Lane wrote:

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:

On Sun, Aug 04, 2019 at 03:16:12PM -0400, Tom Lane wrote:

Isn't the issue here the interaction between log_transaction_sample_rate
and log_min_duration_statement?

No, that interaction only affects statement-level sampling.

OK, I was confusing the features.

For transaction-level sampling we do the sampling independently of the
statement duration, i.e. we when starting a transaction we determine
whether the whole transaction will be sampled. It has nothing to do with
the proposed log_statement_sample_limit.

So, to clarify: our plan is that a given statement will be logged
if any of these various partial-logging features says to do so?

Yes, I think that's the expected behavior.

- did it exceed log_min_duration_statement? -> log it
- is it part of sampled xact? -> log it
- maybe sample the statement (to be reverted / reimplemented)

(And the knock on HEAD's behavior is exactly that it breaks that
independence for log_min_duration_statement.)

Yeah. There's no way to use sampling, while ensure logging of all
queries longer than some limit.

FWIW I've reverted the log_statement_sample_rate (both from master and
REL_12_STABLE). May the buildfarm be merciful to me.

I've left the log_transaction_sample_rate in, as that seems unaffected
by this discussion.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#26Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Tomas Vondra (#25)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Sun, Aug 04, 2019 at 11:41:54PM +0200, Tomas Vondra wrote:

On Sun, Aug 04, 2019 at 10:48:48PM +0200, Tomas Vondra wrote:

On Sun, Aug 04, 2019 at 04:25:12PM -0400, Tom Lane wrote:

Tomas Vondra <tomas.vondra@2ndquadrant.com> writes:

On Sun, Aug 04, 2019 at 03:16:12PM -0400, Tom Lane wrote:

Isn't the issue here the interaction between log_transaction_sample_rate
and log_min_duration_statement?

No, that interaction only affects statement-level sampling.

OK, I was confusing the features.

For transaction-level sampling we do the sampling independently of the
statement duration, i.e. we when starting a transaction we determine
whether the whole transaction will be sampled. It has nothing to do with
the proposed log_statement_sample_limit.

So, to clarify: our plan is that a given statement will be logged
if any of these various partial-logging features says to do so?

Yes, I think that's the expected behavior.

- did it exceed log_min_duration_statement? -> log it
- is it part of sampled xact? -> log it
- maybe sample the statement (to be reverted / reimplemented)

(And the knock on HEAD's behavior is exactly that it breaks that
independence for log_min_duration_statement.)

Yeah. There's no way to use sampling, while ensure logging of all
queries longer than some limit.

FWIW I've reverted the log_statement_sample_rate (both from master and
REL_12_STABLE). May the buildfarm be merciful to me.

I've left the log_transaction_sample_rate in, as that seems unaffected
by this discussion.

I've pushed the reworked version of log_statement_sample_rate patch [1].
If I understand correctly, that makes this patch unnecessary, and we
should mark it as rejected. Or do we still need it?

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

#27Adrien Nayrat
adrien.nayrat@anayrat.info
In reply to: Tomas Vondra (#26)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On 11/6/19 7:21 PM, Tomas Vondra wrote:

I've pushed the reworked version of log_statement_sample_rate patch [1].
If I understand correctly, that makes this patch unnecessary, and we
should mark it as rejected. Or do we still need it?

Yes, the goal of this patch was to disable sampling and log all queries whose
duration exceed log_statement_sample_limit.

For now it is possible just with log_min_duration_statement which log all
queries whose duration exceed it.

--
Adrien

#28Tomas Vondra
tomas.vondra@2ndquadrant.com
In reply to: Adrien Nayrat (#27)
Re: idea: log_statement_sample_rate - bottom limit for sampling

On Wed, Nov 06, 2019 at 08:00:57PM +0100, Adrien Nayrat wrote:

On 11/6/19 7:21 PM, Tomas Vondra wrote:

I've pushed the reworked version of log_statement_sample_rate patch [1].
If I understand correctly, that makes this patch unnecessary, and we
should mark it as rejected. Or do we still need it?

Yes, the goal of this patch was to disable sampling and log all queries whose
duration exceed log_statement_sample_limit.

For now it is possible just with log_min_duration_statement which log all
queries whose duration exceed it.

OK, I've marked it as rejected. If someone thinks we should still have
something like it, please submit a patch implementing it.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services