Thread: 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

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

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

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

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
runsfor too long.
 
-- 
Jim Nasby, Data Architect, Blue Treble Consulting
Data in Trouble? Get it in Treble! http://BlueTreble.com