Hello,
On 2/15/19 3:24 PM, Adrien NAYRAT wrote:
On 2/14/19 9:14 PM, Andres Freund wrote:
I wonder if this doesn't need a warning, explaining that using this when
there are large transactions could lead to slowdowns.
Yes, I will add some wording
Warning added.
It seems pretty weird to have this in postgres.c, given you declared it
in xact.h?
Yes, I have to revise my C. I will move it to
src/backend/access/transam/xact.c
Fixed
Why are both of these checked? ISTM once xact_is_sampled is set, we
ought not to respect a different value of log_xact_sample_rate for the
rest of that transaction.
I added theses checks to allow to disable logging during a sampled
transaction, per suggestion of Masahiko Sawada:
https://www.postgresql.org/message-id/CAD21AoD4t%2BhTV6XfK5Yz%3DEocB8oMyJSYFfjAryCDYtqfib2GrA%40mail.gmail.com
I added a comment to explain why transaction logging is rechecked.
As far as I can tell xact_is_sampled is not properly reset in case of
errors?
I am not sure if I should disable logging in case of errors. Actually we
have:
postgres=# set log_transaction_sample_rate to 1;
SET
postgres=# set client_min_messages to 'LOG';
LOG: duration: 0.392 ms statement: set client_min_messages to 'LOG';
SET
postgres=# begin;
LOG: duration: 0.345 ms statement: begin;
BEGIN
postgres=# select 1;
LOG: duration: 0.479 ms statement: select 1;
?column?
----------
1
(1 row)
postgres=# select * from missingtable;
ERROR: relation "missingtable" does not exist
LINE 1: select * from missingtable;
^
postgres=# select 1;
ERROR: current transaction is aborted, commands ignored until end of
transaction block
postgres=# rollback;
LOG: duration: 11390.295 ms statement: rollback;
ROLLBACK
If I reset xact_is_sampled (after the first error inside
AbortTransaction if I am right), "rollback" statement will not be
logged. I wonder if this "statement" should be logged?
If the answer is no, I will reset xact_is_sampled in AbortTransaction.
Patch attached with fix mentioned above, but without xact_is_sampled reset.
Cheers,
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 6d42b7afe7..dbf5b81243 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5819,6 +5819,32 @@ local0.* /var/log/postgresql
</listitem>
</varlistentry>
+ <varlistentry id="guc-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 logged. It applies
+ to each new transaction regardless of their duration. The default is
+ <literal>0</literal>, meaning do not log statements from this transaction.
+ Setting this to <literal>1</literal> logs all statements for all transactions.
+ Logging can be disabled inside a transaction by setting this to 0.
+ <varname>log_transaction_sample_rate</varname> is helpful to track a
+ sample of transaction.
+ </para>
+ <note>
+ <para>
+ This option can add overhead when transactions are large (many short queries).
+ Or, when the workload is high and <varname>log_transaction_sample_rate</varname>
+ is closed to 1.
+ </para>
+ </note>
+ </listitem>
+ </varlistentry>
+
</variablelist>
<para>
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index e93262975d..2a301b88ea 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -244,6 +244,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
@@ -1822,6 +1825,9 @@ StartTransaction(void)
s->state = TRANS_START;
s->transactionId = InvalidTransactionId; /* until assigned */
+ /* Determine if statements are logged in this transaction */
+ xact_is_sampled = 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 8b4d94c9a1..76f7f8a912 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2203,6 +2203,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
@@ -2218,7 +2220,8 @@ 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 && log_xact_sample_rate > 0))
{
long secs;
int usecs;
@@ -2252,11 +2255,17 @@ 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 && log_xact_sample_rate > 0))
{
snprintf(msec_str, 32, "%ld.%03d",
secs * 1000 + msecs, usecs % 1000);
- if (exceeded && !was_logged)
+
+ /*
+ * Recheck if transaction is sampled to allow to disable logging
+ * within a transaction.
+ */
+ 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 156d147c85..cf77d3b2ee 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -509,6 +509,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;
@@ -3362,13 +3363,25 @@ static struct config_real ConfigureNamesReal[] =
{"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) and 1 (always log).")
},
&log_statement_sample_rate,
1.0, 0.0, 1.0,
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 (never log) and 1 (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 bd6ea65d0c..2e7e679660 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -493,6 +493,10 @@
# log_min_duration_statement. 1.0 logs all statements,
# 0 never logs.
+#log_transaction_sample_rate = 0 # Fraction of transactions whose statements
+ # are logged regardless of their duration. 1.0 logs all
+ # statements from all transactions, 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 426e77846f..ee3d97c3fe 100644
--- a/src/include/access/xact.h
+++ b/src/include/access/xact.h
@@ -54,6 +54,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 c07e7b945e..cb67fbd907 100644
--- 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;
