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
On 27 October 2014 19:21, Josh Berkus <josh@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
Hi,
Am Montag, den 27.10.2014, 19:29 +0000 schrieb Thom Brown:
On 27 October 2014 19:21, Josh Berkus <josh@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.banck@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
Attachments:
log_min_duration_transaction_v0.patchtext/x-patch; charset=UTF-8; name=log_min_duration_transaction_v0.patchDownload
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;
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.banck@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
Robert Haas <robertmhaas@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
On 11/7/14, 1:19 PM, Michael Banck wrote:
Am Montag, den 27.10.2014, 19:29 +0000 schrieb Thom Brown:
On 27 October 2014 19:21, Josh Berkus<josh@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