Re: TODO request: log_long_transaction

Hi,

Am Montag, den 27.10.2014, 19:29 +0000 schrieb Thom Brown:
> On 27 October 2014 19:21, Josh Berkus <josh(at)agliodbs(dot)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(dot)banck(at)credativ(dot)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