log-sample-rework.patch

text/plain

Filename: log-sample-rework.patch
Type: text/plain
Part: 0
Message: Re: idea: log_statement_sample_rate - bottom limit for sampling

Patch

Same data as JSON: GET /api/v1/attachments/:id/patch the parsed metadata as JSON — format, series position, per-file stats; never the diff bytes. API reference →
Format: unified
File+
doc/src/sgml/config.sgml 43 2
src/backend/tcop/postgres.c 15 4
src/backend/utils/misc/guc.c 15 2
src/backend/utils/misc/postgresql.conf.sample 7 3
src/include/utils/guc.h 1 0
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;