Tom Lane wrote:
> Bruce Momjian <[EMAIL PROTECTED]> writes:
> > Tom Lane wrote:
> >> I would prefer to see the log entries look like
> >>
> >> LOG: query: select * from pg_class;
> >> LOG: duration: nn.nnn msec
>
> > The problem with two lines is that another log message could get between
> > them.
>
> That was true already with log_statement and log_duration as separate
> operations. People use log_pid to deal with it.
Attached are some emails I sent while we were discussing this feature in
March.
The idea was for the parameter to show query and duration --- a
combination that is asked for frequently and easily grep'ed, unlike
joining on pid, which because of pid wrap-around, isn't even fool-proof.
One thing that isn't implemented in current CVS is to allow 0 to always
print the duration and query (-1 disables it and is the default). I can
see that being _very_ valuable, and used enough to warrant the fact that
it isn't orthoginal (we already have log_statement). The reason we
needed to do it this way was so we could print the statement _after_ it
completes so we could include the duration.
--
Bruce Momjian | http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
>From pgman Wed Feb 12 15:03:03 2003
Subject: Re: [HACKERS] log_duration
In-Reply-To: <[EMAIL PROTECTED]>
To: Greg Stark <[EMAIL PROTECTED]>
Date: Wed, 12 Feb 2003 16:49:58 -0500 (EST)
cc: [EMAIL PROTECTED]
X-Mailer: ELM [version 2.4ME+ PL99 (25)]
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset=US-ASCII
Content-Length: 3288
Status: OR
Greg Stark wrote:
> Tom Lane <[EMAIL PROTECTED]> writes:
>
> > "Christopher Kings-Lynne" <[EMAIL PROTECTED]> 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
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
>From pgman Wed Feb 12 15:03:03 2003
Subject: Re: [HACKERS] log_duration
In-Reply-To: <[EMAIL PROTECTED]>
To: Christopher Kings-Lynne <[EMAIL PROTECTED]>
Date: Wed, 12 Feb 2003 21:32:05 -0500 (EST)
cc: Greg Stark <[EMAIL PROTECTED]>, [EMAIL PROTECTED]
X-Mailer: ELM [version 2.4ME+ PL99 (25)]
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset=US-ASCII
Content-Length: 1245
Status: OR
Christopher Kings-Lynne wrote:
> > 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
>
> OK, while I'm doing all this benchmarking and stuff - is there any sort of
> option where I can see it logged when a sort doesn't have enought sort
> memory and hence hits the disk? eg. an elog(LOG) is emitted?
Someone asked about this at FOSDEM. The only way I know to do it is look
in the pgsql_temp directory, but they disappear pretty quickly. Folks,
do we need something to report sort file usage?
--
Bruce Momjian | http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
>From pgman Wed Feb 12 15:03:03 2003
Subject: Re: [HACKERS] log_duration
In-Reply-To: <[EMAIL PROTECTED]>
To: Christopher Kings-Lynne <[EMAIL PROTECTED]>
Date: Wed, 12 Feb 2003 22:07:04 -0500 (EST)
cc: Greg Stark <[EMAIL PROTECTED]>, [EMAIL PROTECTED]
X-Mailer: ELM [version 2.4ME+ PL99 (25)]
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset=US-ASCII
Content-Length: 1366
Status: OR
Well, part of the issue here is that it isn't always bad to use sort
file; certainly it is better to use them than to swap.
We have a checkpoint_warning in 7.4 that will warn about excessive
checkpointing. What would our criteria be for warning about sort_mem?
Seems we would have to know how much free memory there is available, and
in fact, if there is lots of free memory, the sort files will just sit
in the kernel disk cache anyway.
I am not saying this is a bad idea --- we just need to define it clearer.
---------------------------------------------------------------------------
Christopher Kings-Lynne wrote:
> > Someone asked about this at FOSDEM. The only way I know to do it is look
> > in the pgsql_temp directory, but they disappear pretty quickly. Folks,
> > do we need something to report sort file usage?
>
> How about a new GUC variable: log_sort_tempfiles
>
> And in the code that creates the temp file, if the GUC variable is true,
> then do:
>
> elog(LOG, "Sort needed temp file. Sort required 2456K. Try increasing
> sort_mem.");
>
> Or something?
>
> Chris
>
>
--
Bruce Momjian | http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
>From pgman Wed Feb 12 15:03:03 2003
Subject: Re: [HACKERS] log_duration
In-Reply-To: <[EMAIL PROTECTED]>
To: Tom Lane <[EMAIL PROTECTED]>
Date: Wed, 12 Feb 2003 23:46:11 -0500 (EST)
cc: Greg Stark <[EMAIL PROTECTED]>, [EMAIL PROTECTED]
X-Mailer: ELM [version 2.4ME+ PL99 (25)]
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset=US-ASCII
Content-Length: 1792
Status: OR
Tom Lane wrote:
> Bruce Momjian <[EMAIL PROTECTED]> writes:
> > 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.
>
> Actually, I was wondering if we shouldn't *replace* the current
> log_duration with a combined form (that specifies a minimum interesting
> duration). I can't quite see the need for orthogonality here. The
> only reason you'd care about query duration is that you're looking for
> the slow ones, no? So why bother logging the fast ones? Besides, you
> can specify min-duration zero if you really want 'em all.
We did talk about this a while ago, and folks wanted the query printed
_before_ it was executed, so they could see the query in the logs at the
time it was issued, both for monitoring and for showing the time the
query started when log_timestamp is enabled.
Seems the clearest option would be for log_duration to print the query
string too, and convert it to an integer field. I can see zero meaning
print all queries and durations. What value do we use to turn it off?
-1?
This would give us log_statement that prints at query start, and
log_duration that prints query and duration at query end. How is that?
Maybe we should rename them as log_statement_start and
log_statement_duration.
--
Bruce Momjian | http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
>From pgman Fri Mar 14 09:01:29 2003
Subject: Re: [HACKERS] log_duration
In-Reply-To: <[EMAIL PROTECTED]>
To: Bruce Momjian <[EMAIL PROTECTED]>
Date: Fri, 14 Mar 2003 14:27:38 -0500 (EST)
cc: Tom Lane <[EMAIL PROTECTED]>, Greg Stark <[EMAIL PROTECTED]>,
[EMAIL PROTECTED]
X-Mailer: ELM [version 2.4ME+ PL99 (25)]
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset=US-ASCII
Content-Length: 2472
Status: OR
Added to TODO:
* Add GUC log_statement_duration to print statement and >= min duration
---------------------------------------------------------------------------
Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <[EMAIL PROTECTED]> writes:
> > > 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.
> >
> > Actually, I was wondering if we shouldn't *replace* the current
> > log_duration with a combined form (that specifies a minimum interesting
> > duration). I can't quite see the need for orthogonality here. The
> > only reason you'd care about query duration is that you're looking for
> > the slow ones, no? So why bother logging the fast ones? Besides, you
> > can specify min-duration zero if you really want 'em all.
>
> We did talk about this a while ago, and folks wanted the query printed
> _before_ it was executed, so they could see the query in the logs at the
> time it was issued, both for monitoring and for showing the time the
> query started when log_timestamp is enabled.
>
> Seems the clearest option would be for log_duration to print the query
> string too, and convert it to an integer field. I can see zero meaning
> print all queries and durations. What value do we use to turn it off?
> -1?
>
> This would give us log_statement that prints at query start, and
> log_duration that prints query and duration at query end. How is that?
>
> Maybe we should rename them as log_statement_start and
> log_statement_duration.
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
>
> ---------------------------(end of broadcast)---------------------------
> TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
>
--
Bruce Momjian | http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster
