Re: [HACKERS] TODO request: log_long_transaction
On 11/7/14, 1:19 PM, Michael Banck wrote: Am Montag, den 27.10.2014, 19:29 + schrieb Thom Brown: On 27 October 2014 19:21, Josh Berkusj...@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. FWIW, I've also wanted the equivalent of statement_timeout for transactions; the ability to abort a transaction if it runs for too long. -- Jim Nasby, Data Architect, Blue Treble Consulting Data in Trouble? Get it in Treble! http://BlueTreble.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] TODO request: log_long_transaction
Robert Haas robertmh...@gmail.com wrote: 3. Should long transactions which are rolled back be logged as well? Yes. +1 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. This is a potentially serious problem with this whole idea, and the idea in #2. You can log that it happened, but without some idea of what it did, it's probably not going to be too useful. The database currently lacks two things which I have seen used for this purpose in database access middleware: an application area (sort of like application name, but more fine-grained and expected to change within the lifetime of a connection) and a transaction class name. For a connection related to an In Court application, there might be an application area of Mass Traffic Dispo which has 10 or 20 transaction classes. Examples of transaction classes could be to enter a Default Judgment of Guilty (for all cases scheduled for that session where the defendant didn't appear), or to Grant Time to Pay to those found guilty who have not paid the citation in full. (It could often make sense for a given transaction class to be usable from more than one application area, and for the context to be valuable.) If we added GUCs for application area and transaction class, those could be included in the log message for a long-running transaction. That would make the messages useful -- at least for occurrences when either or both were set. The question is whether people would be willing to set these GUCs to make the logging useful -- Kevin Grittner EDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] TODO request: log_long_transaction
Hi,
Am Montag, den 27.10.2014, 19:29 + 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,
+
Re: [HACKERS] TODO request: log_long_transaction
You should add this patch here, so it doesn't get forgotten: https://commitfest.postgresql.org/action/commitfest_view/open On Fri, Nov 7, 2014 at 2:19 PM, Michael Banck michael.ba...@credativ.de wrote: 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. Either could be useful. I'm guessing Josh had the latter in mind. 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. I agree. You could implement this by setting a timeout when going idle in transaction. 3. Should long transactions which are rolled back be logged as well? Yes. 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. This is a potentially serious problem with this whole idea, and the idea in #2. You can log that it happened, but without some idea of what it did, it's probably not going to be too useful. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
[HACKERS] TODO request: log_long_transaction
Hackers, 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. -- Josh Berkus PostgreSQL Experts Inc. http://pgexperts.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] TODO request: log_long_transaction
On 27 October 2014 19:21, Josh Berkus j...@agliodbs.com wrote: Hackers, 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. Thom
