Re: log_duration

Greg Stark wrote:
> Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> writes:
>
> > "Christopher Kings-Lynne" <chriskl(at)familyhealth(dot)com(dot)au> writes:
> > > Looking at the log_duration postgresql.conf option. How about adding an
> > > option log_duration_min which is a value in milliseconds that is the minimum
> > > time a query must run for before being logged.
> >
> > Fine with me --- but you'll need to add more logic than that. Right
> > now, log_duration *only* causes the query duration to be printed out;
> > if you ain't got log_statement on, you're in the dark as to what the
> > query itself was. You'll need to add some code to print the query
> > (the log_min_error_statement logic might be a useful source of
> > inspiration). Not sure how this should interact with the case where
> > log_duration is set and the min-duration isn't. But maybe that case
> > is silly, and we should just redefine log_duration as a minimum runtime
> > that causes the query *and* its runtime to be printed to the log.

Tom is right here. log_duration _just_ prints the duration, so we would
need to basically create a merged param that does log_duration and
log_statement and have it activate only if the statement takes more than
X milliseconds, something like log_long_statement, or something like
that.

Here are the log_* params we have:

log_connections = false
log_hostname = false
log_source_port = false
log_pid = false
log_statement = false
log_duration = false
log_timestamp = false

Basically, log_pid pulls them all together. Without that, you don't
have any way to pull together individual lines in the log, and with pid
wraparound, you can't even do that 100%. I wonder if we should put a
number before the pid and increment it on every pid wraparound.

One nice thing is that each element is orthoginal. But, for the
functionality desired, we have to merge log_statement and log_duration
and have it print for statements taking over X milliseconds. I have no
problem adding it, but it has to be clear it isn't orthoginal but is a
conditional combination of two other parameters.

> Is it even guaranteed to be properly ordered on a busy server with multiple
> processors anyways?
>
> One option is to have log_query output an identifier with the query such as a
> hash of the query or the pointer value for the plan, suppressing duplicates.
> Then log_duration prints the identifier with the duration.
>
> This means on a busy server running lots of prepared queries you would see a
> whole bunch of queries on startup, then hopefully no durations. Any durations
> printed could cause alarms to go off. To find the query you grep the logs for
> the identifier in the duration message.

Actually, log_pid is the proper way to do this. You can then add log
connections, and get a full snapshot of what is happening for that
session.

> This only really works if you're using prepared queries everywhere. But in the
> long run that will be the case for OLTP systems, which is where log_duration
> is really useful.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073