Re: log_duration - Mailing list pgsql-hackers

Greg Stark wrote:
> Tom Lane <tgl@sss.pgh.pa.us> writes:
> 
> > "Christopher Kings-Lynne" <chriskl@familyhealth.com.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 = falselog_hostname = falselog_source_port = falselog_pid =
falselog_statement= falselog_duration = falselog_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@candle.pha.pa.us               |  (610)
359-1001+  If your life is a hard drive,     |  13 Roberts Road +  Christ can be your backup.        |  Newtown Square,
Pennsylvania19073