On 3/27/19 10:22 AM, Adrien NAYRAT wrote:
Hello,
On 3/27/19 7:05 AM, Masahiko Sawada wrote:
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.
Umm, I'm inclined to think that we should not disable logging within
the transaction. If we allow that, since users can disable the logging
within the transaction by setting it to 0 they may think that we can
change the rate during the transaction, which is wrong. If we want
this behavior we should document it but we can make user not being
able to change the rate during the transaction to avoid confusion. And
the latter looks more understandable and straightforward. This is
different comment what I did before, I'm sorry for confusing you.
Don't worry, I will change that.
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.
FWIW, I'd prefer to log "rollback" as well so as user can recognize
the end of transaction.
Ok.
+ /* Determine if statements are logged in this transaction */
+ xact_is_sampled = random() <= log_xact_sample_rate *
MAX_RANDOM_VALUE;
If log_xact_sample_rate is 1 we always log all statement in the
transaction regardless of value of random(). Similarly if it's 0, we
never log. I think we can avoid unnecessary random() call in both case
like log_statement_sample_rate does.
I agree, I will change that.
{"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
},
This change is not relevant with log_transaction_sample_rate feature
but why do we need this change? In postgresql.conf.sample the
description of both log_statement_sample_rate and
log_transaction_sample_rate use 1.0 instead of 1, like "1.0 logs all
statements from all transactions, 0 never logs". If we need this
change I think it should be a separate patch.
Sorry, I changed that, someone suggest using either "0" and "1", or
"0.0" and "1.0" but not mixing both. I will remove this change.
Thanks for your review.
Patch attached with all changes requested.
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d383de2512..99e38b32d1 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -5836,6 +5836,31 @@ 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.
+ <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 c3214d4f4d..9fb9658a12 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -245,6 +245,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
@@ -1823,6 +1826,10 @@ StartTransaction(void)
s->state = TRANS_START;
s->transactionId = InvalidTransactionId; /* 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 f9ce3d8f22..44a59e1d4f 100644
--- 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 aa564d153a..7821aa9694 100644
--- 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;
@@ -3366,6 +3367,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 (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 cccb5f145a..cfe0ccb5fc 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 e8579dcd47..dcdd80ff21 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 2712a774f7..34cebd540d 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;
