Hi,
Am Montag, den 27.10.2014, 19:29 +0000 schrieb Thom Brown:
> On 27 October 2014 19:21, Josh Berkus <j...@agliodbs.com> wrote:
> > I just realized that there is one thing we can't log currently:
> > transactions which last more than #ms. This is valuable diagnostic
> > information when looking for issues like causes of bloat and deadlocks.
> >
> > I'd like it to be on the TODO list because it seems like part of a good
> > GSOC project or first-time contribution.
>
>
> So effectively, log_min_duration_transaction? Sounds useful.
Questions are:
1. Should this log when the duration is exceeded (like log_lock_waits),
or on commit? I guess the latter, cause log_lock_waits is kinda an
offshoot from the deadlock detector, and other things don't work in a
similar fashion and/or this might be quite tricky and a non-starter.
2. It would be quite nice to log long-running idle-in-transaction (i.e.
transactions which have been idle for a long time, not necessarily long
transactions which are idle every now and then), but see 1.
3. Should long transactions which are rolled back be logged as well?
4. We log the statement when exceeding log_min_duration_statement, but
for transactions, that does not make a lot of sense, or should the last
statement be logged? I don't think that would be particularly useful.
So if you just want to log transactions which took longer than
log_min_duration_transaction on commit (but not rollback), that's rather
easy and I've attached a PoC patch against master for that.
I took the logic from check_log_duration(), so it is pretty trivial. In
general, one could argue that tcop/postgres.c might be the better place,
and check_log_duration() should be refactored to support both
log_min_duration_statement and log_min_duration_transaction, but (i) I
decided to include the xid in the log message to have at least some
information (even though that might duplicate information in
log_line_prefix) which I don't think is easily accesible from tcop and
(ii) when I hooked it into finish_xact_command(), it did not work well,
e.g. it logged on psql statements like \d.
Thoughts?
Michael
--
Michael Banck
Projektleiter / Berater
Tel.: +49 (2161) 4643-171
Fax: +49 (2161) 4643-100
Email: michael.ba...@credativ.de
credativ GmbH, HRB Mönchengladbach 12080
USt-ID-Nummer: DE204566209
Hohenzollernstr. 133, 41061 Mönchengladbach
Geschäftsführung: Dr. Michael Meskes, Jörg Folz, Sascha Heuer
diff --git a/src/backend/access/transam/xact.c b/src/backend/access/transam/xact.c
index 6f92bad..da08c46 100644
--- a/src/backend/access/transam/xact.c
+++ b/src/backend/access/transam/xact.c
@@ -794,6 +794,46 @@ TransactionStartedDuringRecovery(void)
}
/*
+ * CheckCurrentTransactionDuration
+ *
+ * Returns true if the current transaction's duration is longer than
+ * log_min_duration_transaction.
+ */
+bool
+CheckCurrentTransactionDuration(char *msec_str)
+{
+ long secs;
+ int usecs;
+ int msecs;
+ bool exceeded;
+
+ TimestampDifference(xactStartTimestamp,
+ xactStopTimestamp,
+ &secs,
+ &usecs);
+ msecs = usecs / 1000;
+
+ /*
+ * This odd-looking test for log_min_duration_transaction being exceeded
+ * is designed to avoid integer overflow with very long durations:
+ * don't compute secs * 1000 until we've verified it will fit in int.
+ */
+ exceeded = (log_min_duration_transaction == 0 ||
+ (log_min_duration_transaction > 0 &&
+ (secs > log_min_duration_transaction / 1000 ||
+ secs * 1000 + msecs >= log_min_duration_transaction)));
+
+ if (exceeded)
+ {
+ snprintf(msec_str, 32, "%ld.%03d",
+ secs * 1000 + msecs, usecs % 1000);
+ return true;
+ }
+ return false;
+}
+
+
+/*
* CommandCounterIncrement
*/
void
@@ -1007,6 +1047,7 @@ RecordTransactionCommit(void)
SharedInvalidationMessage *invalMessages = NULL;
bool RelcacheInitFileInval = false;
bool wrote_xlog;
+ char msec_str[32];
/* Get data needed for commit record */
nrels = smgrGetPendingDeletes(true, &rels);
@@ -1235,6 +1276,12 @@ RecordTransactionCommit(void)
END_CRIT_SECTION();
}
+ /* Check whether to log the duration of the transaction */
+ if (CheckCurrentTransactionDuration(msec_str))
+ ereport(LOG,
+ (errmsg("transaction %u duration: %s ms", xid, msec_str),
+ errhidestmt(true)));
+
/* Compute latestXid while we have the child XIDs handy */
latestXid = TransactionIdLatest(xid, nchildren, children);
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index aca4243..6e8cc43 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -451,6 +451,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_transaction = -1;
int log_temp_files = -1;
int trace_recovery_messages = LOG;
@@ -2211,6 +2212,18 @@ static struct config_int ConfigureNamesInt[] =
},
{
+ {"log_min_duration_transaction", PGC_SUSET, LOGGING_WHEN,
+ gettext_noop("Sets the minimum duration time above which "
+ "transactions will be logged."),
+ gettext_noop("Zero logs all transactions. -1 turns this feature off."),
+ GUC_UNIT_MS
+ },
+ &log_min_duration_transaction,
+ -1, -1, INT_MAX,
+ NULL, NULL, NULL
+ },
+
+ {
{"log_autovacuum_min_duration", PGC_SIGHUP, LOGGING_WHAT,
gettext_noop("Sets the minimum execution time above which "
"autovacuum actions will be logged."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index dac6776..b6ee362 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -397,6 +397,11 @@
# statements running at least this number
# of milliseconds
+#log_min_duration_transaction = -1 # -1 is disabled, 0 logs all transactions
+ # and their durations, > 0 logs only
+ # transactions running at least this number
+ # of milliseconds
+
# - What to Log -
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index 60f7532..3a9a7b5 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -77,7 +77,7 @@ extern void PostgresMain(int argc, char *argv[],
extern long get_stack_depth_rlimit(void);
extern void ResetUsage(void);
extern void ShowUsage(const char *title);
-extern int check_log_duration(char *msec_str, bool was_logged);
+extern int check_log_duration(char *msec_str, bool was_logged, bool is_statement);
extern void set_debug_options(int debug_flag,
GucContext context, GucSource source);
extern bool set_plan_disabling_options(const char *arg,
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index 66b5cd3..fe58a2e 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -222,6 +222,7 @@ extern int log_min_error_statement;
extern int log_min_messages;
extern int client_min_messages;
extern int log_min_duration_statement;
+extern int log_min_duration_transaction;
extern int log_temp_files;
extern int temp_file_limit;
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
