Re: fix log_min_duration_statement logic error

OK, here is a patch that uses the zero value to print all queries:

LOG: duration: 0.310 msecs, select 1;
LOG: duration: 8.108 msecs, select * from pg_class;
LOG: duration: 1.992 msecs, select * from pg_class, pg_proc limit 1;
LOG: duration: 2.797 msecs, select * from pg_class, pg_proc order by pg_proc.oid limit 1;
LOG: duration: 16190.962 msecs, select * from pg_class, pg_proc order by pg_proc.oid;

Comments?

---------------------------------------------------------------------------

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us> 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
> 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

> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <87smuurif6(dot)fsf(at)stark(dot)dyndns(dot)tv>
> To: Greg Stark <gsstark(at)mit(dot)edu>
> Date: Wed, 12 Feb 2003 16:49:58 -0500 (EST)
> cc: pgsql-hackers(at)postgresql(dot)org
> 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 <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
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <GNELIHDDFBOCMGBFGEFOMEIGCFAA(dot)chriskl(at)familyhealth(dot)com(dot)au>
> To: Christopher Kings-Lynne <chriskl(at)familyhealth(dot)com(dot)au>
> Date: Wed, 12 Feb 2003 21:32:05 -0500 (EST)
> cc: Greg Stark <gsstark(at)mit(dot)edu>, pgsql-hackers(at)postgresql(dot)org
> 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
> 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
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <GNELIHDDFBOCMGBFGEFOGEIHCFAA(dot)chriskl(at)familyhealth(dot)com(dot)au>
> To: Christopher Kings-Lynne <chriskl(at)familyhealth(dot)com(dot)au>
> Date: Wed, 12 Feb 2003 22:07:04 -0500 (EST)
> cc: Greg Stark <gsstark(at)mit(dot)edu>, pgsql-hackers(at)postgresql(dot)org
> 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
> 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
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <10231(dot)1045109729(at)sss(dot)pgh(dot)pa(dot)us>
> To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
> Date: Wed, 12 Feb 2003 23:46:11 -0500 (EST)
> cc: Greg Stark <gsstark(at)mit(dot)edu>, pgsql-hackers(at)postgresql(dot)org
> 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 <pgman(at)candle(dot)pha(dot)pa(dot)us> 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
> 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
>
> >From pgman Fri Mar 14 09:01:29 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <200302130446(dot)h1D4kBF29082(at)candle(dot)pha(dot)pa(dot)us>
> To: Bruce Momjian <pgman(at)candle(dot)pha(dot)pa(dot)us>
> Date: Fri, 14 Mar 2003 14:27:38 -0500 (EST)
> cc: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>, Greg Stark <gsstark(at)mit(dot)edu>,
> pgsql-hackers(at)postgresql(dot)org
> 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 <pgman(at)candle(dot)pha(dot)pa(dot)us> 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
> > 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
> >
> > ---------------------------(end of broadcast)---------------------------
> > TIP 1: subscribe and unsubscribe commands go to majordomo(at)postgresql(dot)org
> >
>
> --
> 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
>

>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster

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