Log all statements from a sample of transactions

This is useful to obtain a view of the different transaction types in an
application, regardless of the durations of the statements each runs.

Author: Adrien Nayrat
Reviewed-by: Masahiko Sawada, Hayato Kuroda, Andres Freund

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2166b99fc4eeb23605da6b8e9c20406818b5771d..915296310ce30aed6f5b5dd146b33d806004f370 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5871,6 +5871,32 @@ local0.*    /var/log/postgresql
        </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>
+       <primary><varname>log_transaction_sample_rate</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+       <listitem>
+        <para>
+         Set the fraction of transactions whose statements are all logged,
+         in addition to statements logged for other reasons.  It applies to
+         each new transaction regardless of its statements' durations.
+         The default is <literal>0</literal>, meaning not to log statements
+         from any additional transaction.  Setting this to <literal>1</literal>
+         logs all statements for all transactions.
+         <varname>log_transaction_sample_rate</varname> is helpful to track a
+         sample of transaction.
+        </para>
+       <note>
+        <para>
+         Like all statement-logging options, this option can add significant
+         overhead.
+        </para>
+       </note>
+       </listitem>
+     </varlistentry>
+
      </variablelist>
 
     <para>

diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index e9ed92b70bb3eb91d8605709013b6b9a1a942913..b04fdb5d5ed6b6d5e14648223d5169b9605ea95c 100644 (file)
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -264,6 +264,9 @@ static char *prepareGID;
  */
 static bool forceSyncCommit = false;
 
+/* Flag for logging statements in a transaction. */
+bool           xact_is_sampled = false;
+
 /*
  * Private context for transaction-abort work --- we reserve space for this
  * at startup to ensure that AbortTransaction and AbortSubTransaction can work
@@ -1903,6 +1906,11 @@ StartTransaction(void)
        s->state = TRANS_START;
        s->fullTransactionId = InvalidFullTransactionId;        /* until assigned */
 
+       /* Determine if statements are logged in this transaction */
+       xact_is_sampled = log_xact_sample_rate != 0 &&
+               (log_xact_sample_rate == 1 ||
+                random() <= log_xact_sample_rate * MAX_RANDOM_VALUE);
+
        /*
         * initialize current transaction state fields
         *

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index f9ce3d8f22a35a69d558e332e84d1e7be27a6377..44a59e1d4fb6fb7ffdc67c24f6e77b0824549bfa 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2194,6 +2194,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.
+ *             We also check if this statement in this transaction must be logged
+ *             (regardless of its duration).
  *
  * Returns:
  *             0 if no logging is needed
@@ -2209,7 +2211,7 @@ check_log_statement(List *stmt_list)
 int
 check_log_duration(char *msec_str, bool was_logged)
 {
-       if (log_duration || log_min_duration_statement >= 0)
+       if (log_duration || log_min_duration_statement >= 0 || xact_is_sampled)
        {
                long            secs;
                int                     usecs;
@@ -2243,11 +2245,11 @@ 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)
+               if ((exceeded && in_sample) || log_duration || xact_is_sampled)
                {
                        snprintf(msec_str, 32, "%ld.%03d",
                                         secs * 1000 + msecs, usecs % 1000);
-                       if (exceeded && !was_logged)
+                       if ((exceeded || 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 cd5a65be75b58778aa6e53863501170e036a991e..83a9fc2b4c6968ae3955a38ec766874f89e7292d 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -510,6 +510,7 @@ int                 client_min_messages = NOTICE;
 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;
 
 int                    temp_file_limit = -1;
@@ -3386,6 +3387,18 @@ static struct config_real ConfigureNamesReal[] =
                NULL, NULL, NULL
        },
 
+       {
+               {"log_transaction_sample_rate", PGC_SUSET, LOGGING_WHEN,
+                       gettext_noop("Set the fraction of transactions to log for new transactions."),
+                       gettext_noop("Logs all statements from a fraction of transactions. "
+                                                "Use a value between 0.0 (never log) and 1.0 (log all "
+                                                "statements for all transactions).")
+               },
+               &log_xact_sample_rate,
+               0.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 9b15361403ebdf08cda98e8da9e72e6e5a0e5fc1..f31d419f79552ba36e9093d500cc6406a09313fa 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -495,6 +495,10 @@
                                        # log_min_duration_statement. 1.0 logs all statements,
                                        # 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.
+
 # - What to Log -
 
 #debug_print_parse = off

diff --git a/src/include/access/xact.h b/src/include/access/xact.h
index b550343c4db51ef4b0fbdb8658e866b318a10659..d787f929f7f8594d676a778440d916733c3d1e3e 100644 (file)
--- a/src/include/access/xact.h
+++ b/src/include/access/xact.h
@@ -55,6 +55,9 @@ extern PGDLLIMPORT int XactIsoLevel;
 extern bool DefaultXactReadOnly;
 extern bool XactReadOnly;
 
+/* flag for logging statements in this transaction */
+extern bool xact_is_sampled;
+
 /*
  * Xact is deferrable -- only meaningful (currently) for read only
  * SERIALIZABLE transactions

diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index 2712a774f7d9cdae8501b4b17faf1cee42b111c0..34cebd540dc2e2b7d501111ef3d90f6bbc67bc6e 100644 (file)
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -252,6 +252,7 @@ extern PGDLLIMPORT int client_min_messages;
 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;