Add log_statement_sample_rate parameter

This allows to set a lower log_min_duration_statement value without
incurring excessive log traffic (which reduces performance).  This can
be useful to analyze workloads with lots of short queries.

Author: Adrien Nayrat
Reviewed-by: David Rowley, Vik Fearing
Discussion: https://postgr.es/m/c30ee535-ee1e-db9f-fa97-146b9f62caed@anayrat.info

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 1e6e13c91c24f26cebf7f2a2fbb72b03efad2cd7..2e5a5cd331ba059765de8f68eba2fef4fca7ece1 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5721,11 +5721,11 @@ 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.  Setting this to zero prints all statement durations.
-         Minus-one (the default) disables logging statement durations.
-         For example, if you set it to <literal>250ms</literal>
-         then all SQL statements that run 250ms or longer will be
-         logged.  Enabling this parameter can be helpful in tracking down
+         milliseconds, modulated by <varname>log_statement_sample_rate</varname>.
+         Setting this to zero prints all statement durations. Minus-one (the default)
+         disables logging statement durations. For example, if you set it to
+         <literal>250ms</literal> then all SQL statements that run 250ms or longer
+         will be logged. Enabling this parameter can be helpful in tracking down
          unoptimized queries in your applications.
          Only superusers can change this setting.
         </para>
@@ -5752,6 +5752,26 @@ local0.*    /var/log/postgresql
        </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>
+       <primary><varname>log_statement_sample_rate</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+       <listitem>
+        <para>
+         Determines the fraction of the statements that exceed
+         <xref linkend="guc-log-min-duration-statement"/> which to log.
+         The default is <literal>1</literal>, meaning log to all such
+         statements.
+         Setting this to zero disables logging, same as setting
+         <varname>log_min_duration_statement</varname>
+         to minus-one. <varname>log_statement_sample_rate</varname>
+         is helpful when the traffic is too high to log all queries.
+        </para>
+       </listitem>
+      </varlistentry>
+
      </variablelist>
 
     <para>

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index a3b9757565e7b3a01abc560307dcf5d62ae8681f..9a948f825df789e62c9350f4a27018097f5ccf4c 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2201,7 +2201,8 @@ check_log_statement(List *stmt_list)
 
 /*
  * check_log_duration
- *             Determine whether current command's duration should be logged
+ *             Determine whether current command's duration should be logged.
+ *             If log_statement_sample_rate < 1.0, log only a sample.
  *
  * Returns:
  *             0 if no logging is needed
@@ -2223,6 +2224,7 @@ check_log_duration(char *msec_str, bool was_logged)
                int                     usecs;
                int                     msecs;
                bool            exceeded;
+               bool            in_sample;
 
                TimestampDifference(GetCurrentStatementStartTimestamp(),
                                                        GetCurrentTimestamp(),
@@ -2239,7 +2241,17 @@ check_log_duration(char *msec_str, bool was_logged)
                                         (secs > log_min_duration_statement / 1000 ||
                                          secs * 1000 + msecs >= log_min_duration_statement)));
 
-               if (exceeded || log_duration)
+               /*
+                * 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)
+                       in_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)
                {
                        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 d469de73e97403db74f362c154e9af15df8b540d..03594e77feec57cbf44ff50ffd9b948faa96bbb4 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -486,6 +486,7 @@ int                 log_min_messages = WARNING;
 int                    client_min_messages = NOTICE;
 int                    log_min_duration_statement = -1;
 int                    log_temp_files = -1;
+double         log_statement_sample_rate = 1.0;
 int                    trace_recovery_messages = LOG;
 
 int                    temp_file_limit = -1;
@@ -2642,7 +2643,8 @@ 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. -1 turns this feature off."),
+                       gettext_noop("Zero prints all queries, subject to log_statement_sample_rate. "
+                                                "-1 turns this feature off."),
                        GUC_UNIT_MS
                },
                &log_min_duration_statement,
@@ -3319,6 +3321,17 @@ static struct config_real ConfigureNamesReal[] =
                NULL, NULL, NULL
        },
 
+       {
+               {"log_statement_sample_rate", PGC_SUSET, LOGGING_WHEN,
+                       gettext_noop("Fraction of statements over log_min_duration_statement to log."),
+                       gettext_noop("If you only want a sample, use a value between 0 (never "
+                                                "log) and 1.0 (always log).")
+               },
+               &log_statement_sample_rate,
+               1.0, 0.0, 1.0,
+               NULL, NULL, NULL
+       },
+
        /* End-of-list marker */
        {
                {NULL, 0, 0, NULL, NULL}, NULL, 0.0, 0.0, 0.0, NULL, NULL, NULL

diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index ee9ec6a12003418b0342bf23c31c7682ff1c97d8..1fa02d2c938129fb68dcb59208b7530d52026dda 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -483,11 +483,14 @@
                                        #   fatal
                                        #   panic (effectively off)
 
-#log_min_duration_statement = -1       # -1 is disabled, 0 logs all statements
-                                       # and their durations, > 0 logs only
-                                       # statements running at least this number
-                                       # of milliseconds
-
+#log_min_duration_statement = -1       # logs statements and their durations
+                                       # according to log_statement_sample_rate. -1 is disabled,
+                                       # 0 logs all statement, > 0 logs only statements running at
+                                       # least this number of milliseconds.
+
+#log_statement_sample_rate = 1 # Fraction of logged statements over
+                                       # log_min_duration_statement. 1.0 logs all statements,
+                                       # 0 never logs.
 
 # - What to Log -
 

diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index df2e556b0219a31be5363f34b20c9dd9c8738f43..64457c792a8012e7a85e0b7a7ec0a27423e31595 100644 (file)
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -251,6 +251,7 @@ extern PGDLLIMPORT int log_min_messages;
 extern PGDLLIMPORT int client_min_messages;
 extern int     log_min_duration_statement;
 extern int     log_temp_files;
+extern double log_statement_sample_rate;
 
 extern int     temp_file_limit;