Thread: fix log_min_duration_statement logic error
This patch fixes an obvious bug in the "should I print the duration of this query?" logic in postgres.c I also don't particularly like the format of the log message (for one thing, the "duration_statement" prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. -Neil
Attachment
Neil Conway <neilc@samurai.com> writes:
> I also don't particularly like the format of the log message (for one
> thing, the "duration_statement" prefix in the log message shouldn't
> include an underscore, it's not a variable or anything -- and the case
> can be made that if we printed the duration because log_duration is set,
> we don't need to print it again if the duration of the query exceeded
> log_min_duration_statement), but I haven't changed it.
I think there should be just one "duration: nnn" log entry, printed if
either condition holds.
regards, tom lane
Tom Lane wrote: >Neil Conway <neilc@samurai.com> writes: > > >>I also don't particularly like the format of the log message (for one >>thing, the "duration_statement" prefix in the log message shouldn't >>include an underscore, it's not a variable or anything -- and the case >>can be made that if we printed the duration because log_duration is set, >>we don't need to print it again if the duration of the query exceeded >>log_min_duration_statement), but I haven't changed it. >> >> > >I think there should be just one "duration: nnn" log entry, printed if >either condition holds. > > > I think that would be consistent with my session-end log patch. cheers andrew
Tom Lane writes: > Neil Conway <neilc@samurai.com> writes: > > I also don't particularly like the format of the log message (for one > > thing, the "duration_statement" prefix in the log message shouldn't > > include an underscore, it's not a variable or anything -- and the case > > can be made that if we printed the duration because log_duration is set, > > we don't need to print it again if the duration of the query exceeded > > log_min_duration_statement), but I haven't changed it. > > I think there should be just one "duration: nnn" log entry, printed if > either condition holds. Is anyone going to take care of this? -- Peter Eisentraut peter_e@gmx.net
Yes, I will. --------------------------------------------------------------------------- Peter Eisentraut wrote: > Tom Lane writes: > > > Neil Conway <neilc@samurai.com> writes: > > > I also don't particularly like the format of the log message (for one > > > thing, the "duration_statement" prefix in the log message shouldn't > > > include an underscore, it's not a variable or anything -- and the case > > > can be made that if we printed the duration because log_duration is set, > > > we don't need to print it again if the duration of the query exceeded > > > log_min_duration_statement), but I haven't changed it. > > > > I think there should be just one "duration: nnn" log entry, printed if > > either condition holds. > > Is anyone going to take care of this? > > -- > Peter Eisentraut peter_e@gmx.net > > > ---------------------------(end of broadcast)--------------------------- > TIP 1: subscribe and unsubscribe commands go to majordomo@postgresql.org > -- 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, Pennsylvania 19073
Your patch has been added to the PostgreSQL unapplied patches list at:
http://momjian.postgresql.org/cgi-bin/pgpatches
I will try to apply it within the next 48 hours.
---------------------------------------------------------------------------
Neil Conway wrote:
> This patch fixes an obvious bug in the "should I print the duration of
> this query?" logic in postgres.c
>
> I also don't particularly like the format of the log message (for one
> thing, the "duration_statement" prefix in the log message shouldn't
> include an underscore, it's not a variable or anything -- and the case
> can be made that if we printed the duration because log_duration is set,
> we don't need to print it again if the duration of the query exceeded
> log_min_duration_statement), but I haven't changed it.
>
> -Neil
>
[ Attachment, skipping... ]
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster
--
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, Pennsylvania 19073
> I think there should be just one "duration: nnn" log entry, printed if
> either condition holds.
Your patch has been added to the PostgreSQL unapplied patches list at:
http://momjian.postgresql.org/cgi-bin/pgpatches
I will try to apply it within the next 48 hours.
---------------------------------------------------------------------------
Tom Lane wrote:
> Neil Conway <neilc@samurai.com> writes:
> > I also don't particularly like the format of the log message (for one
> > thing, the "duration_statement" prefix in the log message shouldn't
> > include an underscore, it's not a variable or anything -- and the case
> > can be made that if we printed the duration because log_duration is set,
> > we don't need to print it again if the duration of the query exceeded
> > log_min_duration_statement), but I haven't changed it.
>
> I think there should be just one "duration: nnn" log entry, printed if
> either condition holds.
>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 3: if posting/reading through Usenet, please send an appropriate
> subscribe-nomail command to majordomo@postgresql.org so that your
> message can get through to the mailing list cleanly
>
--
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, Pennsylvania 19073
Patch applied. Thanks. I also marged this test into log_duration and use the same log tag for both, as suggested. --------------------------------------------------------------------------- Neil Conway wrote: > This patch fixes an obvious bug in the "should I print the duration of > this query?" logic in postgres.c > > I also don't particularly like the format of the log message (for one > thing, the "duration_statement" prefix in the log message shouldn't > include an underscore, it's not a variable or anything -- and the case > can be made that if we printed the duration because log_duration is set, > we don't need to print it again if the duration of the query exceeded > log_min_duration_statement), but I haven't changed it. > > -Neil > [ Attachment, skipping... ] > > ---------------------------(end of broadcast)--------------------------- > TIP 4: Don't 'kill -9' the postmaster -- 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, Pennsylvania 19073 Index: src/backend/tcop/postgres.c =================================================================== RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v retrieving revision 1.367 diff -c -c -r1.367 postgres.c *** src/backend/tcop/postgres.c 29 Sep 2003 00:05:25 -0000 1.367 --- src/backend/tcop/postgres.c 29 Sep 2003 18:28:27 -0000 *************** *** 955,979 **** usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec); /* ! * Output a duration_query to the log if the query has exceeded ! * the min duration. */ ! if (usecs >= save_log_min_duration_statement * 1000) ereport(LOG, ! (errmsg("duration_statement: %ld.%06ld %s", (long) (stop_t.tv_sec - start_t.tv_sec), (long) (stop_t.tv_usec - start_t.tv_usec), query_string))); - - /* - * If the user is requesting logging of all durations, then log - * that as well. - */ - if (save_log_duration) - ereport(LOG, - (errmsg("duration: %ld.%06ld sec", - (long) (stop_t.tv_sec - start_t.tv_sec), - (long) (stop_t.tv_usec - start_t.tv_usec)))); } if (save_log_statement_stats) --- 955,971 ---- usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec); /* ! * Output a duration_statement to the log if the query has exceeded ! * the min duration, or if we are to print all durations. */ ! if (save_log_duration || ! (save_log_min_duration_statement > 0 && ! usecs >= save_log_min_duration_statement * 1000)) ereport(LOG, ! (errmsg("duration: %ld.%06ld %s", (long) (stop_t.tv_sec - start_t.tv_sec), (long) (stop_t.tv_usec - start_t.tv_usec), query_string))); } if (save_log_statement_stats)
Tom Lane wrote: > Neil Conway <neilc@samurai.com> writes: > > I also don't particularly like the format of the log message (for one > > thing, the "duration_statement" prefix in the log message shouldn't > > include an underscore, it's not a variable or anything -- and the case > > can be made that if we printed the duration because log_duration is set, > > we don't need to print it again if the duration of the query exceeded > > log_min_duration_statement), but I haven't changed it. > > I think there should be just one "duration: nnn" log entry, printed if > either condition holds. Done. -- 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, Pennsylvania 19073
Bruce Momjian writes: > > I think there should be just one "duration: nnn" log entry, printed if > > either condition holds. > > Done. Now, if I have log_statement and log_duration on, it logs each statement twice. The documentation says this: log_duration (boolean) Causes the duration of every completed statement to be logged. To use this option, enable log_statement and log_pid so you can link the statement to the duration using the process ID. This needs more thought. Also, please put units on all numbers. -- Peter Eisentraut peter_e@gmx.net
Thanks Peter. Patch attached. I added "(secs)" to the ouput:
LOG: duration(secs): 0.000257
LOG: duration(secs): 0.000754
LOG: duration(secs): 0.008115 select * from pg_class;
---------------------------------------------------------------------------
Peter Eisentraut wrote:
> Bruce Momjian writes:
>
> > > I think there should be just one "duration: nnn" log entry, printed if
> > > either condition holds.
> >
> > Done.
>
> Now, if I have log_statement and log_duration on, it logs each statement
> twice. The documentation says this:
>
> log_duration (boolean)
>
> Causes the duration of every completed statement to be logged. To use
> this option, enable log_statement and log_pid so you can link the
> statement to the duration using the process ID.
>
> This needs more thought.
>
> Also, please put units on all numbers.
>
> --
> Peter Eisentraut peter_e@gmx.net
>
--
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, Pennsylvania 19073
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.369
diff -c -c -r1.369 postgres.c
*** src/backend/tcop/postgres.c 2 Oct 2003 06:34:04 -0000 1.369
--- src/backend/tcop/postgres.c 4 Oct 2003 02:45:50 -0000
***************
*** 943,948 ****
--- 943,949 ----
if (save_log_duration || save_log_min_duration_statement > 0)
{
long usecs;
+ bool print_statement;
gettimeofday(&stop_t, NULL);
if (stop_t.tv_usec < start_t.tv_usec)
***************
*** 956,969 ****
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! if (save_log_duration ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000))
ereport(LOG,
! (errmsg("duration: %ld.%06ld %s",
(long) (stop_t.tv_sec - start_t.tv_sec),
(long) (stop_t.tv_usec - start_t.tv_usec),
! query_string)));
}
if (save_log_statement_stats)
--- 957,972 ----
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000);
!
! if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration(secs): %ld.%06ld%s%s",
(long) (stop_t.tv_sec - start_t.tv_sec),
(long) (stop_t.tv_usec - start_t.tv_usec),
! print_statement ? " " : "",
! print_statement ? query_string : "")));
}
if (save_log_statement_stats)
Bruce Momjian writes: > Thanks Peter. Patch attached. I added "(secs)" to the ouput: > > LOG: duration(secs): 0.000257 > LOG: duration(secs): 0.000754 > LOG: duration(secs): 0.008115 select * from pg_class; I think the units typically go after the number. -- Peter Eisentraut peter_e@gmx.net
Peter Eisentraut <peter_e@gmx.net> writes:
> Bruce Momjian writes:
>> LOG: duration(secs): 0.000257
>> LOG: duration(secs): 0.000754
>> LOG: duration(secs): 0.008115 select * from pg_class;
> I think the units typically go after the number.
In any case, this is unnecessarily incompatible with everything else.
EXPLAIN and psql's \timing show query durations in milliseconds. And
isn't log_min_duration_statement itself measured in milliseconds?
I would prefer to see the log entries look like
LOG: query: select * from pg_class;
LOG: duration: nn.nnn msec
in all cases, rather than moving information around depending on which
combination of switches happens to have caused the log entries to be
generated. Am willing to fix the code to make this happen.
regards, tom lane
Tom Lane wrote:
> Peter Eisentraut <peter_e@gmx.net> writes:
> > Bruce Momjian writes:
> >> LOG: duration(secs): 0.000257
> >> LOG: duration(secs): 0.000754
> >> LOG: duration(secs): 0.008115 select * from pg_class;
>
> > I think the units typically go after the number.
>
> In any case, this is unnecessarily incompatible with everything else.
> EXPLAIN and psql's \timing show query durations in milliseconds. And
> isn't log_min_duration_statement itself measured in milliseconds?
>
> I would prefer to see the log entries look like
>
> LOG: query: select * from pg_class;
> LOG: duration: nn.nnn msec
>
> in all cases, rather than moving information around depending on which
> combination of switches happens to have caused the log entries to be
> generated. Am willing to fix the code to make this happen.
The problem with two lines is that another log message could get between
them. I agree milliseconds makes more sense for output.
Maybe:
LOG: duration: nn.nnn msec, select * from pg_class;
--
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, Pennsylvania 19073
Bruce Momjian <pgman@candle.pha.pa.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.
regards, tom lane
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.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@candle.pha.pa.us | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania 19073
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@candle.pha.pa.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@candle.pha.pa.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.fsf@stark.dyndns.tv> > To: Greg Stark <gsstark@mit.edu> > Date: Wed, 12 Feb 2003 16:49:58 -0500 (EST) > cc: pgsql-hackers@postgresql.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@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 = 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@candle.pha.pa.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.chriskl@familyhealth.com.au> > To: Christopher Kings-Lynne <chriskl@familyhealth.com.au> > Date: Wed, 12 Feb 2003 21:32:05 -0500 (EST) > cc: Greg Stark <gsstark@mit.edu>, pgsql-hackers@postgresql.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@candle.pha.pa.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.chriskl@familyhealth.com.au> > To: Christopher Kings-Lynne <chriskl@familyhealth.com.au> > Date: Wed, 12 Feb 2003 22:07:04 -0500 (EST) > cc: Greg Stark <gsstark@mit.edu>, pgsql-hackers@postgresql.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@candle.pha.pa.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.1045109729@sss.pgh.pa.us> > To: Tom Lane <tgl@sss.pgh.pa.us> > Date: Wed, 12 Feb 2003 23:46:11 -0500 (EST) > cc: Greg Stark <gsstark@mit.edu>, pgsql-hackers@postgresql.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@candle.pha.pa.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@candle.pha.pa.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.h1D4kBF29082@candle.pha.pa.us> > To: Bruce Momjian <pgman@candle.pha.pa.us> > Date: Fri, 14 Mar 2003 14:27:38 -0500 (EST) > cc: Tom Lane <tgl@sss.pgh.pa.us>, Greg Stark <gsstark@mit.edu>, > pgsql-hackers@postgresql.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@candle.pha.pa.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@candle.pha.pa.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@postgresql.org > > > > -- > 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, Pennsylvania 19073 > > > ---------------------------(end of broadcast)--------------------------- > TIP 4: Don't 'kill -9' the postmaster -- 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, Pennsylvania 19073 Index: doc/src/sgml/runtime.sgml =================================================================== RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v retrieving revision 1.210 diff -c -c -r1.210 runtime.sgml *** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 -0000 1.210 --- doc/src/sgml/runtime.sgml 5 Oct 2003 03:10:51 -0000 *************** *** 1691,1702 **** Sets a minimum statement execution time (in milliseconds) above which a statement will be logged. All SQL statements that run longer than the time specified will be logged together ! with their actual duration. Setting this to zero (the default) ! disables time-based logging. For example, if you set it to <literal>250</literal> then all SQL statements that run longer ! than 250ms will be logged. Enabling this ! option can be useful in tracking down unoptimized queries in ! your applications. Only superusers can increase this or set it to zero if this option is set to non-zero by the administrator. </para> --- 1691,1702 ---- Sets a minimum statement execution time (in milliseconds) above which a statement will be logged. All SQL statements that run longer than the time specified will be logged together ! with their actual duration. Setting this to zero will print ! all queries with their durations. Minus-one (the default) ! disables time-based logging. For example, if you set it to <literal>250</literal> then all SQL statements that run longer ! than 250ms will be logged. Enabling this option can be useful ! in tracking down unoptimized queries in your applications. Only superusers can increase this or set it to zero if this option is set to non-zero by the administrator. </para> Index: src/backend/tcop/postgres.c =================================================================== RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v retrieving revision 1.370 diff -c -c -r1.370 postgres.c *** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 -0000 1.370 --- src/backend/tcop/postgres.c 5 Oct 2003 03:10:54 -0000 *************** *** 694,700 **** * because gettimeofday() wasn't called. Similarly, * log_statement_stats has to be captured once. */ ! if (save_log_duration || save_log_min_duration_statement > 0) gettimeofday(&start_t, NULL); if (save_log_statement_stats) --- 694,700 ---- * because gettimeofday() wasn't called. Similarly, * log_statement_stats has to be captured once. */ ! if (save_log_duration || save_log_min_duration_statement != -1) gettimeofday(&start_t, NULL); if (save_log_statement_stats) *************** *** 940,946 **** * Combine processing here as we need to calculate the query duration * in both instances. */ ! if (save_log_duration || save_log_min_duration_statement > 0) { long usecs; bool print_statement; --- 940,946 ---- * Combine processing here as we need to calculate the query duration * in both instances. */ ! if (save_log_duration || save_log_min_duration_statement != -1) { long usecs; bool print_statement; *************** *** 957,970 **** * Output a duration_statement to the log if the query has exceeded * the min duration, or if we are to print all durations. */ ! print_statement = (save_log_min_duration_statement > 0 && ! usecs >= save_log_min_duration_statement * 1000); if (save_log_duration || print_statement) ereport(LOG, ! (errmsg("duration(secs): %ld.%06ld%s%s", ! (long) (stop_t.tv_sec - start_t.tv_sec), ! (long) (stop_t.tv_usec - start_t.tv_usec), print_statement ? " " : "", print_statement ? query_string : ""))); } --- 957,972 ---- * Output a duration_statement to the log if the query has exceeded * the min duration, or if we are to print all durations. */ ! print_statement = (save_log_min_duration_statement == 0 || ! (save_log_min_duration_statement > 0 && ! usecs >= save_log_min_duration_statement * 1000)); if (save_log_duration || print_statement) ereport(LOG, ! (errmsg("duration: %ld.%03ld msecs, %s%s", ! (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 + ! (stop_t.tv_usec - start_t.tv_usec) / 1000), ! (long) (stop_t.tv_usec - start_t.tv_usec) % 1000, print_statement ? " " : "", print_statement ? query_string : ""))); } Index: src/backend/utils/misc/guc.c =================================================================== RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v retrieving revision 1.162 diff -c -c -r1.162 guc.c *** src/backend/utils/misc/guc.c 3 Oct 2003 19:26:49 -0000 1.162 --- src/backend/utils/misc/guc.c 5 Oct 2003 03:10:58 -0000 *************** *** 128,134 **** int log_min_messages = NOTICE; int client_min_messages = NOTICE; ! int log_min_duration_statement = 0; /* --- 128,134 ---- int log_min_messages = NOTICE; int client_min_messages = NOTICE; ! int log_min_duration_statement = -1; /* *************** *** 1185,1194 **** {"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN, gettext_noop("minimum execution time in milliseconds above which statements will " "be logged"), ! gettext_noop("The default is 0 (turning this feature off).") }, &log_min_duration_statement, ! 0, 0, INT_MAX / 1000, NULL, NULL }, /* End-of-list marker */ --- 1185,1194 ---- {"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN, gettext_noop("minimum execution time in milliseconds above which statements will " "be logged"), ! gettext_noop("Zero prints all queries. The default is -1 (turning this feature off).") }, &log_min_duration_statement, ! -1, -1, INT_MAX / 1000, NULL, NULL }, /* End-of-list marker */ Index: src/backend/utils/misc/postgresql.conf.sample =================================================================== RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v retrieving revision 1.91 diff -c -c -r1.91 postgresql.conf.sample *** src/backend/utils/misc/postgresql.conf.sample 3 Oct 2003 19:26:49 -0000 1.91 --- src/backend/utils/misc/postgresql.conf.sample 5 Oct 2003 03:10:58 -0000 *************** *** 157,165 **** # debug5, debug4, debug3, debug2, debug1, # info, notice, warning, error, panic(off) ! #log_min_duration_statement = 0 # Log all statements whose # execution time exceeds the value, in ! # milliseconds. Zero disables. #silent_mode = false # DO NOT USE without Syslog! --- 157,166 ---- # debug5, debug4, debug3, debug2, debug1, # info, notice, warning, error, panic(off) ! #log_min_duration_statement = -1 # Log all statements whose # execution time exceeds the value, in ! # milliseconds. Zero prints all queries. ! # Minus-one disables. #silent_mode = false # DO NOT USE without Syslog!
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> 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.
The behavior I had in mind was to dump the statement at the end of the
query if (a) the duration needs to be printed and (b) the statement
wasn't already dumped at the start --- ie, log_statement was not on
at the start.
The historical behavior of log_min_error_statement has been to make two
separate log entries: the failing query and the error. This has worked
well enough AFAIK; why not keep that behavior for log_min_duration?
BTW, there's a separate set of problems that have yet to be addressed,
which is how any of these logging options apply for V3-protocol query
operations. The existing code only seems to work for the old-style
query path.
regards, tom lane
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > 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.
>
> The behavior I had in mind was to dump the statement at the end of the
> query if (a) the duration needs to be printed and (b) the statement
> wasn't already dumped at the start --- ie, log_statement was not on
> at the start.
>
> The historical behavior of log_min_error_statement has been to make two
> separate log entries: the failing query and the error. This has worked
> well enough AFAIK; why not keep that behavior for log_min_duration?
I think separate entries work for log_min_error_statement because the
error string and query are both long, and you can pretty much guess
which error goes with which query, and you are looking at errors, which
are pretty rare events, hopefully.
I think they fit pretty nicely on one line, and lot of folks want that
information. I realize it looks like bloatware because it duplicates
some existing functionality, but I think it is a combination of duration
and statement output that can't be done easily separately.
Also, I don't see us combining any other log_* operations:
#log_connections = false
#log_duration = false
#log_pid = false
#log_statement = false
#log_timestamp = false
#log_hostname = false
#log_source_port = false
> BTW, there's a separate set of problems that have yet to be addressed,
> which is how any of these logging options apply for V3-protocol query
> operations. The existing code only seems to work for the old-style
> query path.
You mean how are they passed to the client? I assumed that would work
for pre-V3 clients.
--
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, Pennsylvania 19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> I think they fit pretty nicely on one line, and lot of folks want that
> information. I realize it looks like bloatware because it duplicates
> some existing functionality, but I think it is a combination of duration
> and statement output that can't be done easily separately.
Sure it can. You're essentially arguing that DBAs are too dumb to match
up matching query and duration log outputs. I don't buy that. I think
they'll be analyzing their logs with little Perl scripts anyway, and
that consistency of log output format will be worth more to those
scripts than sometimes having related items all on one log line.
>> BTW, there's a separate set of problems that have yet to be addressed,
>> which is how any of these logging options apply for V3-protocol query
>> operations. The existing code only seems to work for the old-style
>> query path.
> You mean how are they passed to the client? I assumed that would work
> for pre-V3 clients.
No, I mean the functionality isn't in the extended-query code path at
all, and it's not immediately clear where to insert it (eg, which steps
of parse/bind/execute do what logging, or where you measure duration).
regards, tom lane
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.us> writes: > > I think they fit pretty nicely on one line, and lot of folks want that > > information. I realize it looks like bloatware because it duplicates > > some existing functionality, but I think it is a combination of duration > > and statement output that can't be done easily separately. > > Sure it can. You're essentially arguing that DBAs are too dumb to match > up matching query and duration log outputs. I don't buy that. I think > they'll be analyzing their logs with little Perl scripts anyway, and > that consistency of log output format will be worth more to those > scripts than sometimes having related items all on one log line. Yes, I am arguing that we shouldn't make people jump through Perl hoops to get a statement/duration line in their log files. I think it is asked for enough that a nice printed line will help them. If we already have the parameter, why not make it easy. If they are using Perl, they can already use log_statement and log_duration to print only queries taking over a certain amount of time. > >> BTW, there's a separate set of problems that have yet to be addressed, > >> which is how any of these logging options apply for V3-protocol query > >> operations. The existing code only seems to work for the old-style > >> query path. > > > You mean how are they passed to the client? I assumed that would work > > for pre-V3 clients. > > No, I mean the functionality isn't in the extended-query code path at > all, and it's not immediately clear where to insert it (eg, which steps > of parse/bind/execute do what logging, or where you measure duration). I assume it would be all executor stuff, but I see what you mean that the perpare isn't going through the normal query path. -- 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, Pennsylvania 19073
Tom Lane writes: > Sure it can. You're essentially arguing that DBAs are too dumb to match > up matching query and duration log outputs. I don't buy that. I think > they'll be analyzing their logs with little Perl scripts anyway, and > that consistency of log output format will be worth more to those > scripts than sometimes having related items all on one log line. When you're dealing with a large installation, these little Perl scripts become difficult. I've just had to deal with a similar issue with a popular MTA which spreads the relevant log information over several lines. If you're generating 500 MB of log output a day, it becomes a problem. -- Peter Eisentraut peter_e@gmx.net
Tom Lane writes: > I would prefer to see the log entries look like > > LOG: query: select * from pg_class; > LOG: duration: nn.nnn msec I'm not fond of the abbrevation "msec" or even "msecs". The official abbreviation is "ms". Btw., I was wondering, are we kidding ourselves when we display microsecond precision to the user? What accuracy do these measurements have in respect to what they are actually supposed to measure? -- Peter Eisentraut peter_e@gmx.net
Peter Eisentraut wrote: > Tom Lane writes: > > > Sure it can. You're essentially arguing that DBAs are too dumb to match > > up matching query and duration log outputs. I don't buy that. I think > > they'll be analyzing their logs with little Perl scripts anyway, and > > that consistency of log output format will be worth more to those > > scripts than sometimes having related items all on one log line. > > When you're dealing with a large installation, these little Perl scripts > become difficult. I've just had to deal with a similar issue with a > popular MTA which spreads the relevant log information over several lines. > If you're generating 500 MB of log output a day, it becomes a problem. I can imagine. I wasn't sure how I would write Perl code to join things via pid. I am sure it can be done (load into hash), but it wasn't trivial like grep. Peter, any problems with pid wrap-around? I am thinking we need to prepend a "wrap count" on the front of the pid output for 7.5. -- 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, Pennsylvania 19073
Peter Eisentraut wrote:
> Tom Lane writes:
>
> > I would prefer to see the log entries look like
> >
> > LOG: query: select * from pg_class;
> > LOG: duration: nn.nnn msec
>
> I'm not fond of the abbrevation "msec" or even "msecs". The official
> abbreviation is "ms".
Yep. Someone suggested "msec" in their example, so I used that, but I
like "ms" better too:
LOG: duration: 0.950 ms; select 1;
LOG: duration: 0.269 ms; set log_min_duration_statement = 1;
Patch attached.
> Btw., I was wondering, are we kidding ourselves when we display
> microsecond precision to the user? What accuracy do these measurements
> have in respect to what they are actually supposed to measure?
Not sure. I think the microsecond stuff is accurate to some degree, but
not sure how much. I think the tick is 10ms, but I thought the timing
was much more accurate than that.
--
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, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 -0000 1.210
--- doc/src/sgml/runtime.sgml 5 Oct 2003 14:12:20 -0000
***************
*** 1691,1702 ****
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero (the default)
! disables time-based logging. For example, if you set it
to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this
! option can be useful in tracking down unoptimized queries in
! your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
</para>
--- 1691,1702 ----
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero will print
! all queries with their durations. Minus-one (the default)
! disables time-based logging. For example, if you set it
to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this option can be useful
! in tracking down unoptimized queries in your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
</para>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 -0000 1.370
--- src/backend/tcop/postgres.c 5 Oct 2003 14:12:23 -0000
***************
*** 694,700 ****
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
--- 694,700 ----
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
***************
*** 940,946 ****
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
{
long usecs;
bool print_statement;
--- 940,946 ----
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
{
long usecs;
bool print_statement;
***************
*** 957,971 ****
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000);
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration(secs): %ld.%06ld%s%s",
! (long) (stop_t.tv_sec - start_t.tv_sec),
! (long) (stop_t.tv_usec - start_t.tv_usec),
! print_statement ? " " : "",
print_statement ? query_string : "")));
}
--- 957,973 ----
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement == 0 ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000));
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms%s%s",
! (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
! (stop_t.tv_usec - start_t.tv_usec) / 1000),
! (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! print_statement ? "; " : "",
print_statement ? query_string : "")));
}
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.162
diff -c -c -r1.162 guc.c
*** src/backend/utils/misc/guc.c 3 Oct 2003 19:26:49 -0000 1.162
--- src/backend/utils/misc/guc.c 5 Oct 2003 14:12:28 -0000
***************
*** 128,134 ****
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = 0;
/*
--- 128,134 ----
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = -1;
/*
***************
*** 1185,1194 ****
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("The default is 0 (turning this feature off).")
},
&log_min_duration_statement,
! 0, 0, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
--- 1185,1194 ----
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("Zero prints all queries. The default is -1 (turning this feature off).")
},
&log_min_duration_statement,
! -1, -1, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.91
diff -c -c -r1.91 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 3 Oct 2003 19:26:49 -0000 1.91
--- src/backend/utils/misc/postgresql.conf.sample 5 Oct 2003 14:12:29 -0000
***************
*** 157,165 ****
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = 0 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero disables.
#silent_mode = false # DO NOT USE without Syslog!
--- 157,166 ----
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = -1 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero prints all queries.
! # Minus-one disables.
#silent_mode = false # DO NOT USE without Syslog!
Bruce Momjian wrote: > > >>Btw., I was wondering, are we kidding ourselves when we display >>microsecond precision to the user? What accuracy do these measurements >>have in respect to what they are actually supposed to measure? >> >> > >Not sure. I think the microsecond stuff is accurate to some degree, but >not sure how much. I think the tick is 10ms, but I thought the timing >was much more accurate than that. > > > On my (slow) linux box the apparent time delay between 2 immediately successive calls to gettimeofday() is 3 or 4 microsecs. Presumably the clock tick is something much larger than that - I forget where to look to find that out. I think the real question is what granularity of reporting will be most useful. For the session duration patch I restricted it to 1/100th of a second, and didn't bother rounding the last place there because it wasn't worth it (I thought). For query duration presumably something smaller seems appropriate, but I'm not sure how small. I suspect anything much below a millisec (or at most 100 microsecs) is of comparatively little value. OTOH truncating it is also probably of little value - if you can read 3 or 4 decimal places you can read 6 just as easily - just be aware that the low values have little information value. cheers andrew
Peter Eisentraut <peter_e@gmx.net> writes:
> When you're dealing with a large installation, these little Perl scripts
> become difficult. I've just had to deal with a similar issue with a
> popular MTA which spreads the relevant log information over several lines.
> If you're generating 500 MB of log output a day, it becomes a problem.
True, but it would take really serious revisions of our log output
formatting to fix things so that a naive "grep" will be useful for much
of anything.
To take just the most obvious limitation in what Bruce is proposing: a
grep for "duration" will yield the duration and the first line of the
SQL command. If an installation is in the habit of breaking their SQL
into multiple lines, this will be less than useful. Some people like
to format their code like this:
SELECT
a, b, c
FROM
...
in which case showing just the first line will be quite content-free.
There are already similar problems with extracting error information
from the logs (and the 7.4 redesign of error formatting has made 'em
worse).
If we are going to try to design the log output so that you don't need
reassembly scripts to link related lines together, then we have got lots
bigger problems to fix than log_duration. I'm not convinced it's an
appropriate goal at all, though.
regards, tom lane
Peter Eisentraut <peter_e@gmx.net> writes:
> Btw., I was wondering, are we kidding ourselves when we display
> microsecond precision to the user? What accuracy do these measurements
> have in respect to what they are actually supposed to measure?
<shrug> The operating system API we are using is spec'd at microsecond
precision. It's likely on any given hardware that some of the low order
digits might be bogus, but it is not our business to guess how many.
If we throw away low-order digits we may be losing useful information.
(This becomes more and more likely as machines get faster.)
We have EXPLAIN ANALYZE output showing two fractional digits of msec,
so it is discarding one potentially significant digit. I did that for
consistency with the historical behavior of showing two fractional
digits of cost estimates, but could probably be talked into the idea
that three digits should be shown instead.
BTW, EXPLAIN ANALYZE puts out
Total runtime: 406.53 msec
Do you want to make an exception to the string freeze to change this
to "ms"?
regards, tom lane
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Peter, any problems with pid wrap-around? I am thinking we need to
> prepend a "wrap count" on the front of the pid output for 7.5.
Why? And how would you know when the PIDs have wrapped anyway?
The OS already guarantees that no two concurrently running procs have
the same PID. That seems sufficient to me. It's conceivable that a PID
could be recycled quickly enough that it wasn't obvious from the logs
that this was a new backend process and not the same old one, but do you
care? (And if you did care, wouldn't you be monitoring log_connections,
which would tip you off?)
I think this is a red herring.
regards, tom lane
Tom Lane writes: > BTW, EXPLAIN ANALYZE puts out > Total runtime: 406.53 msec > Do you want to make an exception to the string freeze to change this > to "ms"? I just realized, all the things that are sent as a query result instead of an error or notice are not gettext-enabled. I guess we'll have to do without that in this release. So, making the above change does not pose a problem. -- Peter Eisentraut peter_e@gmx.net
On Sat, 4 Oct 2003, Tom Lane wrote: > Date: Sat, 04 Oct 2003 15:43:34 -0400 > From: Tom Lane <tgl@sss.pgh.pa.us> > To: Bruce Momjian <pgman@candle.pha.pa.us> > Cc: Peter Eisentraut <peter_e@gmx.net>, Neil Conway <neilc@samurai.com>, > PostgreSQL Patches <pgsql-patches@postgresql.org> > Subject: Re: [PATCHES] fix log_min_duration_statement logic error > > Bruce Momjian <pgman@candle.pha.pa.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. Sorry to jump in... the log_pid is NOT ENOUGH where you have more than 30000 connections a day (witch is my case) There has been discussion as to have 1 Log file/database where are we on that? Is it dead? Thanks > > regards, tom lane > > ---------------------------(end of broadcast)--------------------------- > TIP 9: the planner will ignore your desire to choose an index scan if your > joining column's datatypes do not match > -- Olivier PRENANT Tel: +33-5-61-50-97-00 (Work) 6, Chemin d'Harraud Turrou +33-5-61-50-97-01 (Fax) 31190 AUTERIVE +33-6-07-63-80-64 (GSM) FRANCE Email: ohp@pyrenet.fr ------------------------------------------------------------------------------ Make your life a dream, make your dream a reality. (St Exupery)
> > That was true already with log_statement and log_duration as separate > > operations. People use log_pid to deal with it. > Sorry to jump in... the log_pid is NOT ENOUGH where you have more than > 30000 connections a day (witch is my case) log_pid isn't enough, but log_pid + log_connections certainly is. log_connections tells you when a new connection was made, so guessing isn't required. > There has been discussion as to have 1 Log file/database where are we on > that? Is it dead? Well, this wouldn't help either unless you happen to have several not so active databases that makes for a busy system.
Attachment
Tom Lane wrote: > Peter Eisentraut <peter_e@gmx.net> writes: > > When you're dealing with a large installation, these little Perl scripts > > become difficult. I've just had to deal with a similar issue with a > > popular MTA which spreads the relevant log information over several lines. > > If you're generating 500 MB of log output a day, it becomes a problem. > > True, but it would take really serious revisions of our log output > formatting to fix things so that a naive "grep" will be useful for much > of anything. > > To take just the most obvious limitation in what Bruce is proposing: a > grep for "duration" will yield the duration and the first line of the > SQL command. If an installation is in the habit of breaking their SQL > into multiple lines, this will be less than useful. Some people like > to format their code like this: > > SELECT > a, b, c > FROM > ... > > in which case showing just the first line will be quite content-free. > It is pretty easy to continue pulling lines after the 'duration' hit to see the full query, perhap using awk, or even grep with a + arg. I just don't see why we should make it harder for folks by splitting it over several lines. For folks that want to use perl, they can use the existing log_* outputs to join by pid and get whatever they want. If you want to call this option an option for dummies that don't want to deal with Perl (and Peter has expressed that it isn't easy), that's fine. Does someone want to show us a Perl script do join lines for this must-requested output? I don't feel like sending it to everyone who needs to find the slow queries in their application. Do you? If you want, we can have vote on it. Frankly, the code was designed and submitted as one line output, and I think a vote will show one-line output as the winner. > There are already similar problems with extracting error information > from the logs (and the 7.4 redesign of error formatting has made 'em > worse). > > If we are going to try to design the log output so that you don't need > reassembly scripts to link related lines together, then we have got lots > bigger problems to fix than log_duration. I'm not convinced it's an > appropriate goal at all, though. Again, it is cost/benefit --- how many people want easy reporting of queries and their durations. -- 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, Pennsylvania 19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> It is pretty easy to continue pulling lines after the 'duration' hit to
> see the full query, perhap using awk, or even grep with a + arg. I just
> don't see why we should make it harder for folks by splitting it over
> several lines.
Somehow I fail to see how that's a consistent position.
regards, tom lane
On Sun, 5 Oct 2003, Rod Taylor wrote: > Date: Sun, 05 Oct 2003 13:05:32 -0400 > From: Rod Taylor <rbt@rbt.ca> > To: ohp@pyrenet.fr > Cc: Tom Lane <tgl@sss.pgh.pa.us>, Bruce Momjian <pgman@candle.pha.pa.us>, > Peter Eisentraut <peter_e@gmx.net>, Neil Conway <neilc@samurai.com>, > PostgreSQL Patches <pgsql-patches@postgresql.org> > Subject: Re: [PATCHES] fix log_min_duration_statement logic error > > > > That was true already with log_statement and log_duration as separate > > > operations. People use log_pid to deal with it. > > Sorry to jump in... the log_pid is NOT ENOUGH where you have more than > > 30000 connections a day (witch is my case) > > log_pid isn't enough, but log_pid + log_connections certainly is. > > log_connections tells you when a new connection was made, so guessing > isn't required. > > > There has been discussion as to have 1 Log file/database where are we on > > that? Is it dead? > > Well, this wouldn't help either unless you happen to have several not so > active databases that makes for a busy system. > Only that I could give the log file to the customer owning the database(s) that would make my job esier. Also I'd love to see the log_query being settable per database... -- Olivier PRENANT Tel: +33-5-61-50-97-00 (Work) 6, Chemin d'Harraud Turrou +33-5-61-50-97-01 (Fax) 31190 AUTERIVE +33-6-07-63-80-64 (GSM) FRANCE Email: ohp@pyrenet.fr ------------------------------------------------------------------------------ Make your life a dream, make your dream a reality. (St Exupery)
Peter Eisentraut <peter_e@gmx.net> writes:
> Tom Lane writes:
>> BTW, EXPLAIN ANALYZE puts out
>> Total runtime: 406.53 msec
>> Do you want to make an exception to the string freeze to change this
>> to "ms"?
> I just realized, all the things that are sent as a query result instead of
> an error or notice are not gettext-enabled. I guess we'll have to do
> without that in this release. So, making the above change does not pose a
> problem.
Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue?
regards, tom lane
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.us> writes: > > It is pretty easy to continue pulling lines after the 'duration' hit to > > see the full query, perhap using awk, or even grep with a + arg. I just > > don't see why we should make it harder for folks by splitting it over > > several lines. > > Somehow I fail to see how that's a consistent position. It is easier than making things split across lines. It is a common request so I want to make it as easy as possible --- that seems consistent. If you can think of a way to make it even easier, please let me know. I have not heard from you why we should make it harder (split across two lines), except for consistency with log_statement and log_duration outputs. -- 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, Pennsylvania 19073
Tom Lane wrote: > Peter Eisentraut <peter_e@gmx.net> writes: > > Tom Lane writes: > >> BTW, EXPLAIN ANALYZE puts out > >> Total runtime: 406.53 msec > >> Do you want to make an exception to the string freeze to change this > >> to "ms"? > > > I just realized, all the things that are sent as a query result instead of > > an error or notice are not gettext-enabled. I guess we'll have to do > > without that in this release. So, making the above change does not pose a > > problem. > > Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue? I think three is the only reasonable number --- when you are in digits to the right of the decimal, it should be grouped by three. To group by two makes it look like a US dollar amount, and I can't see a rational for two digits. -- 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, Pennsylvania 19073
ohp@pyrenet.fr writes:
> Also I'd love to see the log_query being settable per database...
AFAIK you can do that now.
regards, tom lane
Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > It is pretty easy to continue pulling lines after the 'duration' hit to
> > > see the full query, perhap using awk, or even grep with a + arg. I just
> > > don't see why we should make it harder for folks by splitting it over
> > > several lines.
> >
> > Somehow I fail to see how that's a consistent position.
>
> It is easier than making things split across lines. It is a common
> request so I want to make it as easy as possible --- that seems
> consistent. If you can think of a way to make it even easier, please
> let me know.
>
> I have not heard from you why we should make it harder (split across two
> lines), except for consistency with log_statement and log_duration
> outputs.
Also, now that you mention queries output as multiple lines:
LOG: duration: 3.938 ms; select *
from pg_language;
Should we instead convert newlines to "\n" and output the query as a
single line? Do we have lots of other multi-line outputs in the log
files?
--
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, Pennsylvania 19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> I have not heard from you why we should make it harder (split across two
> lines), except for consistency with log_statement and log_duration
> outputs.
That is exactly my argument. I'll freely admit that it's not a strong
point, but I find the claim that the inconsistent formats will be easier
to parse to be a much weaker argument, in the absence of any attempt to
make them *actually* easier to parse (like really truly one line).
[ later ]
> Should we instead convert newlines to "\n" and output the query as a
> single line?
That would shore up your position considerably. It needs a little
thought as to whether this would induce any confusion, and whether we
really care if so.
regards, tom lane
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.us> writes: > > I have not heard from you why we should make it harder (split across two > > lines), except for consistency with log_statement and log_duration > > outputs. > > That is exactly my argument. I'll freely admit that it's not a strong > point, but I find the claim that the inconsistent formats will be easier > to parse to be a much weaker argument, in the absence of any attempt to > make them *actually* easier to parse (like really truly one line). > > [ later ] > > Should we instead convert newlines to "\n" and output the query as a > > single line? > > That would shore up your position considerably. It needs a little > thought as to whether this would induce any confusion, and whether we > really care if so. Good, we are moving forward with something we both like. Let me work up a patch and post it. -- 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, Pennsylvania 19073
> > I have not heard from you why we should make it harder (split across two > > lines), except for consistency with log_statement and log_duration > > outputs. I think this is a perfectly good argument. Don't make writing the tools to parse the log more difficult than necessary. Rather than making the log files look nice, lets add a module to PgAdmin that can read it and display it in a user friendly manner (with abilities like sorting queries by execution time!). > Should we instead convert newlines to "\n" and output the query as a > single line? Do we have lots of other multi-line outputs in the log > files? Please don't. Or if you do, don't data unless you intend to escape special characters (in this case \) at the same time so we can convert it back to the original state.
Attachment
Rod Taylor wrote:
-- Start of PGP signed section.
> > > I have not heard from you why we should make it harder (split across two
> > > lines), except for consistency with log_statement and log_duration
> > > outputs.
>
> I think this is a perfectly good argument. Don't make writing the tools
> to parse the log more difficult than necessary.
>
> Rather than making the log files look nice, lets add a module to PgAdmin
> that can read it and display it in a user friendly manner (with
> abilities like sorting queries by execution time!).
>
> > Should we instead convert newlines to "\n" and output the query as a
> > single line? Do we have lots of other multi-line outputs in the log
> > files?
>
> Please don't. Or if you do, don't data unless you intend to escape
> special characters (in this case \) at the same time so we can convert
> it back to the original state.
OK, I coded to convert newline to "\n", carriage return to "\r", and
backslash to "\\". This might cause confusion if you are doing:
INSERT INTO tab VALUES ('\b');
which outputs as:
INSERT INTO tab VALUES ('\\b');
but I see your point that we should be accurate. Actual output is:
LOG: duration: 1.762 ms; insert into ii values ('\\b');
Another example:
LOG: duration: 4.228 ms; select *\nfrom pg_language;
--
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, Pennsylvania 19073
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > I have not heard from you why we should make it harder (split across two
> > lines), except for consistency with log_statement and log_duration
> > outputs.
>
> That is exactly my argument. I'll freely admit that it's not a strong
> point, but I find the claim that the inconsistent formats will be easier
> to parse to be a much weaker argument, in the absence of any attempt to
> make them *actually* easier to parse (like really truly one line).
>
> [ later ]
> > Should we instead convert newlines to "\n" and output the query as a
> > single line?
>
> That would shore up your position considerably. It needs a little
> thought as to whether this would induce any confusion, and whether we
> really care if so.
OK, patch attached. It does the single-line log_min_duration_statement,
and adds a zero value to always print the duration and statement. I
have also added code to convert end-of-line characters to \n and \r, and
doubles backslashes. It also makes log_statement print as one line, and
shows pg_stat_activity as one line. Without this fix, you get:
test=> select * from pg_stat_activity;
datid | datname | procpid | usesysid | usename | current_query | query_start
-------+---------+---------+----------+----------+-----------------------------------+-------------------------------
17139 | test | 19167 | 1 | postgres | |
17139 | test | 19131 | 1 | postgres | select *
from pg_class, pg_proc; | 2003-10-05 15:14:05.338268-04
New output is:
test=> select * from pg_stat_activity;
datid | datname | procpid | usesysid | usename | current_query | query_start
-------+---------+---------+----------+----------+-----------------------------------+-------------------------------
17139 | test | 20391 | 1 | postgres | |
17139 | test | 20344 | 1 | postgres | select *\nfrom pg_proc, pg_class; | 2003-10-05
16:25:07.610427-04
(2 rows)
--
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, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 -0000 1.210
--- doc/src/sgml/runtime.sgml 5 Oct 2003 20:26:09 -0000
***************
*** 1691,1702 ****
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero (the default)
! disables time-based logging. For example, if you set it
to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this
! option can be useful in tracking down unoptimized queries in
! your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
</para>
--- 1691,1702 ----
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero will print
! all queries with their durations. Minus-one (the default)
! disables time-based logging. For example, if you set it
to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this option can be useful
! in tracking down unoptimized queries in your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
</para>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 -0000 1.370
--- src/backend/tcop/postgres.c 5 Oct 2003 20:26:12 -0000
***************
*** 150,156 ****
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
static void FloatExceptionHandler(SIGNAL_ARGS);
!
/* ----------------------------------------------------------------
* routines to obtain user input
--- 150,156 ----
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
static void FloatExceptionHandler(SIGNAL_ARGS);
! static char *str_add_symbolic_eol(const char *str);
/* ----------------------------------------------------------------
* routines to obtain user input
***************
*** 461,467 ****
if (log_statement)
ereport(LOG,
! (errmsg("query: %s", query_string)));
if (log_parser_stats)
ResetUsage();
--- 461,467 ----
if (log_statement)
ereport(LOG,
! (errmsg("query: %s", str_add_symbolic_eol(query_string))));
if (log_parser_stats)
ResetUsage();
***************
*** 686,692 ****
*/
debug_query_string = query_string;
! pgstat_report_activity(query_string);
/*
* We use save_log_* so "SET log_duration = true" and "SET
--- 686,692 ----
*/
debug_query_string = query_string;
! pgstat_report_activity(str_add_symbolic_eol(query_string));
/*
* We use save_log_* so "SET log_duration = true" and "SET
***************
*** 694,700 ****
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
--- 694,700 ----
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
***************
*** 940,946 ****
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
{
long usecs;
bool print_statement;
--- 940,946 ----
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
{
long usecs;
bool print_statement;
***************
*** 957,972 ****
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000);
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration(secs): %ld.%06ld%s%s",
! (long) (stop_t.tv_sec - start_t.tv_sec),
! (long) (stop_t.tv_usec - start_t.tv_usec),
! print_statement ? " " : "",
! print_statement ? query_string : "")));
}
if (save_log_statement_stats)
--- 957,974 ----
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement == 0 ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000));
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms%s%s",
! (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
! (stop_t.tv_usec - start_t.tv_usec) / 1000),
! (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! print_statement ? "; " : "",
! print_statement ? str_add_symbolic_eol(query_string) : "")));
}
if (save_log_statement_stats)
***************
*** 1000,1006 ****
*/
debug_query_string = query_string;
! pgstat_report_activity(query_string);
set_ps_display("PARSE");
--- 1002,1008 ----
*/
debug_query_string = query_string;
! pgstat_report_activity(str_add_symbolic_eol(query_string));
set_ps_display("PARSE");
***************
*** 3196,3198 ****
--- 3198,3236 ----
pfree(str.data);
}
+
+ /*
+ * str_add_symbolic_eol
+ *
+ * This string coverts literal newlines to "\n" for log output.
+ */
+ static char *str_add_symbolic_eol(const char *str)
+ {
+ char *outstr = palloc(strlen(str) * 2 + 1);
+ int len = strlen(str);
+ int i, outlen = 0;
+
+ for (i = 0; i < len; i++)
+ {
+ if (str[i] == '\n')
+ {
+ outstr[outlen++] = '\\';
+ outstr[outlen++] = 'n';
+ }
+ else if (str[i] == '\r')
+ {
+ outstr[outlen++] = '\\';
+ outstr[outlen++] = 'r';
+ }
+ else if (str[i] == '\\')
+ {
+ outstr[outlen++] = '\\';
+ outstr[outlen++] = '\\';
+ }
+ else
+ outstr[outlen++] = str[i];
+ }
+ outstr[outlen++] = '\0';
+ return outstr;
+ }
+
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.162
diff -c -c -r1.162 guc.c
*** src/backend/utils/misc/guc.c 3 Oct 2003 19:26:49 -0000 1.162
--- src/backend/utils/misc/guc.c 5 Oct 2003 20:26:19 -0000
***************
*** 128,134 ****
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = 0;
/*
--- 128,134 ----
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = -1;
/*
***************
*** 1185,1194 ****
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("The default is 0 (turning this feature off).")
},
&log_min_duration_statement,
! 0, 0, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
--- 1185,1194 ----
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("Zero prints all queries. The default is -1 (turning this feature off).")
},
&log_min_duration_statement,
! -1, -1, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.91
diff -c -c -r1.91 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 3 Oct 2003 19:26:49 -0000 1.91
--- src/backend/utils/misc/postgresql.conf.sample 5 Oct 2003 20:26:20 -0000
***************
*** 157,165 ****
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = 0 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero disables.
#silent_mode = false # DO NOT USE without Syslog!
--- 157,166 ----
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = -1 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero prints all queries.
! # Minus-one disables.
#silent_mode = false # DO NOT USE without Syslog!
> have also added code to convert end-of-line characters to \n and \r, and > doubles backslashes. It also makes log_statement print as one line, and > shows pg_stat_activity as one line. Without this fix, you get: And how does it look with what was originally a fairly readable 30 or 40 line query?
Attachment
Rod Taylor wrote: -- Start of PGP signed section. > > have also added code to convert end-of-line characters to \n and \r, and > > doubles backslashes. It also makes log_statement print as one line, and > > shows pg_stat_activity as one line. Without this fix, you get: > > And how does it look with what was originally a fairly readable 30 or 40 > line query? Probably pretty long. I think the pg_stat_activity case really needs the "\n" because if not the query breaks the table output format. Not sure about log_statement or log_min_duration_statement. Having it be one line makes grep easy, and is probably easier for processing via tools, but reading the log could be harder: LOG: duration: 7.466 ms; select *\nfrom pg_class\nwhere oid = 3 and\nrelname = 'abcd' and\nrelkind = 'r'\norder by relname; The old format output was: LOG: duration: 7.466 ms; select * from pg_class where oid = 3 and relname = 'abcd' and relkind = 'r' order by relname; It is hard to understand how a tool would grab the query from the above log except to look for another TAG: entry and stop there. -- 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, Pennsylvania 19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Another example:
> LOG: duration: 4.228 ms; select *\nfrom pg_language;
Minor quibble: would it read better as
LOG: duration n.nnn ms: query
or
LOG: duration n.nnn ms for query
regards, tom lane
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Another example:
> > LOG: duration: 4.228 ms; select *\nfrom pg_language;
>
> Minor quibble: would it read better as
>
> LOG: duration n.nnn ms: query
> or
> LOG: duration n.nnn ms for query
I like it:
LOG: duration: 4.056 ms for select * \nfrom pg_language;
Another idea if you like consistency would be:
LOG: duration: 4.056 ms query: select * \nfrom pg_language;
Patch for "query:" version attached.
Do I need to pfree the memory returned by str_make_symbolic_eol() or is
that cleaned up automatically?
--
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, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 -0000 1.210
--- doc/src/sgml/runtime.sgml 5 Oct 2003 21:17:30 -0000
***************
*** 1691,1702 ****
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero (the default)
! disables time-based logging. For example, if you set it
to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this
! option can be useful in tracking down unoptimized queries in
! your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
</para>
--- 1691,1702 ----
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero will print
! all queries with their durations. Minus-one (the default)
! disables time-based logging. For example, if you set it
to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this option can be useful
! in tracking down unoptimized queries in your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
</para>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 -0000 1.370
--- src/backend/tcop/postgres.c 5 Oct 2003 21:17:33 -0000
***************
*** 150,156 ****
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
static void FloatExceptionHandler(SIGNAL_ARGS);
!
/* ----------------------------------------------------------------
* routines to obtain user input
--- 150,156 ----
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
static void FloatExceptionHandler(SIGNAL_ARGS);
! static char *str_make_symbolic_eol(const char *str);
/* ----------------------------------------------------------------
* routines to obtain user input
***************
*** 461,467 ****
if (log_statement)
ereport(LOG,
! (errmsg("query: %s", query_string)));
if (log_parser_stats)
ResetUsage();
--- 461,467 ----
if (log_statement)
ereport(LOG,
! (errmsg("query: %s", str_make_symbolic_eol(query_string))));
if (log_parser_stats)
ResetUsage();
***************
*** 686,692 ****
*/
debug_query_string = query_string;
! pgstat_report_activity(query_string);
/*
* We use save_log_* so "SET log_duration = true" and "SET
--- 686,692 ----
*/
debug_query_string = query_string;
! pgstat_report_activity(str_make_symbolic_eol(query_string));
/*
* We use save_log_* so "SET log_duration = true" and "SET
***************
*** 694,700 ****
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
--- 694,700 ----
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
***************
*** 940,946 ****
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
{
long usecs;
bool print_statement;
--- 940,946 ----
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
{
long usecs;
bool print_statement;
***************
*** 957,972 ****
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000);
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration(secs): %ld.%06ld%s%s",
! (long) (stop_t.tv_sec - start_t.tv_sec),
! (long) (stop_t.tv_usec - start_t.tv_usec),
! print_statement ? " " : "",
! print_statement ? query_string : "")));
}
if (save_log_statement_stats)
--- 957,974 ----
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement == 0 ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000));
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms%s%s",
! (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
! (stop_t.tv_usec - start_t.tv_usec) / 1000),
! (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! print_statement ? " query: " : "",
! print_statement ? str_make_symbolic_eol(query_string) : "")));
}
if (save_log_statement_stats)
***************
*** 1000,1006 ****
*/
debug_query_string = query_string;
! pgstat_report_activity(query_string);
set_ps_display("PARSE");
--- 1002,1008 ----
*/
debug_query_string = query_string;
! pgstat_report_activity(str_make_symbolic_eol(query_string));
set_ps_display("PARSE");
***************
*** 3196,3198 ****
--- 3198,3236 ----
pfree(str.data);
}
+
+ /*
+ * str_make_symbolic_eol
+ *
+ * This string coverts literal newlines to "\n" for log output.
+ */
+ static char *str_make_symbolic_eol(const char *str)
+ {
+ char *outstr = palloc(strlen(str) * 2 + 1);
+ int len = strlen(str);
+ int i, outlen = 0;
+
+ for (i = 0; i < len; i++)
+ {
+ if (str[i] == '\n')
+ {
+ outstr[outlen++] = '\\';
+ outstr[outlen++] = 'n';
+ }
+ else if (str[i] == '\r')
+ {
+ outstr[outlen++] = '\\';
+ outstr[outlen++] = 'r';
+ }
+ else if (str[i] == '\\')
+ {
+ outstr[outlen++] = '\\';
+ outstr[outlen++] = '\\';
+ }
+ else
+ outstr[outlen++] = str[i];
+ }
+ outstr[outlen++] = '\0';
+ return outstr;
+ }
+
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.162
diff -c -c -r1.162 guc.c
*** src/backend/utils/misc/guc.c 3 Oct 2003 19:26:49 -0000 1.162
--- src/backend/utils/misc/guc.c 5 Oct 2003 21:17:37 -0000
***************
*** 128,134 ****
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = 0;
/*
--- 128,134 ----
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = -1;
/*
***************
*** 1185,1194 ****
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("The default is 0 (turning this feature off).")
},
&log_min_duration_statement,
! 0, 0, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
--- 1185,1194 ----
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("Zero prints all queries. The default is -1 (turning this feature off).")
},
&log_min_duration_statement,
! -1, -1, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.91
diff -c -c -r1.91 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 3 Oct 2003 19:26:49 -0000 1.91
--- src/backend/utils/misc/postgresql.conf.sample 5 Oct 2003 21:17:37 -0000
***************
*** 157,165 ****
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = 0 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero disables.
#silent_mode = false # DO NOT USE without Syslog!
--- 157,166 ----
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = -1 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero prints all queries.
! # Minus-one disables.
#silent_mode = false # DO NOT USE without Syslog!
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> It is hard to understand how a tool would grab the query from the above
> log except to look for another TAG: entry and stop there.
That was pretty much the centerpiece of my complaint --- up to now it's
been tremendously difficult to parse the PG logs automatically, and I
think something along this line would make it much easier.
I am inclined to think though that Bruce has done this in the wrong
place. If we are going to try to enforce "no real newlines inserted as
part of logged strings", then it ought to be done at a low level in
elog.c where it will apply to *everything* that goes into the log, not
just log_statement/log_duration. For example, we presently allow
embedded newlines in DETAIL/HINT messages, which is fine for frontend
messages but helps to render the log unparsable. Those should be
\n-ified too if we are really interested in making the log easy to
process.
regards, tom lane
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Sets a minimum statement execution time (in milliseconds)
> above which a statement will be logged. All SQL statements
> that run longer than the time specified will be logged together
> ! with their actual duration. Setting this to zero will print
> ! all queries with their durations. Minus-one (the default)
> ! disables time-based logging. For example, if you set it
> to <literal>250</literal> then all SQL statements that run longer
> ! than 250ms will be logged.
You're being very unclear, not to say self-contradictory, as to whether
the condition is "> value" or ">= value". I suspect it is really the
latter but this description sure doesn't convey the fact.
> Only superusers can increase this or set it to zero if this option
> is set to non-zero by the administrator.
If you're changing the "off" state to -1 then this last sentence is now
wrong, no? Also, do the non-superuser adjustment constraints in guc.c
still work correctly with this meaning (probably so, but it needs to be
checked)?
regards, tom lane
> Probably pretty long. I think the pg_stat_activity case really needs > the "\n" because if not the query breaks the table output format. Not I was actually thinking exactly the opposite. pg_stat_activity viewed in pgadmin GUI is going to format the table perfectly fine, but with everthing on one line it will be next to impossible to understand anything complex. I would imagine psql will also be easier to read using human placed \n's rather than random ones at the terminal width. Perhaps the environment I work in isn't the normal case, but usually if I'm trying to track something down, it's the complex 10 table join, multi-subselect report style query that someone in account management just happens to be running but poorly formed. > It is hard to understand how a tool would grab the query from the above > log except to look for another TAG: entry and stop there. Yup.. Same way you group entries by PID, then reset the PID the next time you see a new connection formed with it.
Attachment
Rod Taylor wrote: -- Start of PGP signed section. > > Probably pretty long. I think the pg_stat_activity case really needs > > the "\n" because if not the query breaks the table output format. Not > > I was actually thinking exactly the opposite. pg_stat_activity viewed in > pgadmin GUI is going to format the table perfectly fine, but with > everthing on one line it will be next to impossible to understand > anything complex. You are right. It is psql that is at fault for causing the \n value to start at the beginning of the next line and not at the proper column on the next line. I will not change the pg_stat_activity values. Tom's idea of doing it in elog is better, of course. > I would imagine psql will also be easier to read using human placed \n's > rather than random ones at the terminal width. Right. -- 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, Pennsylvania 19073
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Sets a minimum statement execution time (in milliseconds)
> > above which a statement will be logged. All SQL statements
> > that run longer than the time specified will be logged together
> > ! with their actual duration. Setting this to zero will print
> > ! all queries with their durations. Minus-one (the default)
> > ! disables time-based logging. For example, if you set it
> > to <literal>250</literal> then all SQL statements that run longer
> > ! than 250ms will be logged.
>
> You're being very unclear, not to say self-contradictory, as to whether
> the condition is "> value" or ">= value". I suspect it is really the
> latter but this description sure doesn't convey the fact.
>
> > Only superusers can increase this or set it to zero if this option
> > is set to non-zero by the administrator.
>
> If you're changing the "off" state to -1 then this last sentence is now
> wrong, no? Also, do the non-superuser adjustment constraints in guc.c
> still work correctly with this meaning (probably so, but it needs to be
> checked)?
OK, new text:
<varlistentry>
<term><varname>log_min_duration_statement</varname> (<type>integer</type>)</term>
<listitem>
<para>
Sets a minimum statement execution time (in milliseconds)
for statement to be logged. All SQL statements
that run in the time specified or longer will be logged with
their duration. Setting this to zero will print
all queries and their durations. Minus-one (the default)
disables this. For example, if you set it to
<literal>250</literal> then all SQL statements that run 250ms
or longer will be logged. Enabling this option can be
useful in tracking down unoptimized queries in your applications.
Only superusers can increase this or set it to minus-one if this
option is set by the administrator.
</para>
</listitem>
</varlistentry>
--
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, Pennsylvania 19073
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.us> writes: > > It is hard to understand how a tool would grab the query from the above > > log except to look for another TAG: entry and stop there. > > That was pretty much the centerpiece of my complaint --- up to now it's > been tremendously difficult to parse the PG logs automatically, and I > think something along this line would make it much easier. > > I am inclined to think though that Bruce has done this in the wrong > place. If we are going to try to enforce "no real newlines inserted as > part of logged strings", then it ought to be done at a low level in > elog.c where it will apply to *everything* that goes into the log, not > just log_statement/log_duration. For example, we presently allow > embedded newlines in DETAIL/HINT messages, which is fine for frontend > messages but helps to render the log unparsable. Those should be > \n-ified too if we are really interested in making the log easy to > process. Agreed. elog is the proper place, because then you guarantee that it is all on one line. Is that OK? Do we have elogs that we want over several lines? Is this something we can do at this stage in beta? Also, my change to pg_stat_activity was wrong, as Rod pointed out --- it is psql that should handle \n properly, because pgadmin already does. -- 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, Pennsylvania 19073
Tom Lane wrote:
> Peter Eisentraut <peter_e@gmx.net> writes:
> > Tom Lane writes:
> >> BTW, EXPLAIN ANALYZE puts out
> >> Total runtime: 406.53 msec
> >> Do you want to make an exception to the string freeze to change this
> >> to "ms"?
>
> > I just realized, all the things that are sent as a query result instead of
> > an error or notice are not gettext-enabled. I guess we'll have to do
> > without that in this release. So, making the above change does not pose a
> > problem.
>
> Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue?
I just committed a fix so psql \timing shows three digits:
test=> \timing
Timing is on.
test=> select 1;
?column?
----------
1
(1 row)
Time: 1.306 ms
--
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, Pennsylvania 19073
? psql
Index: common.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/bin/psql/common.c,v
retrieving revision 1.74
diff -c -c -r1.74 common.c
*** common.c 16 Sep 2003 17:59:02 -0000 1.74
--- common.c 5 Oct 2003 22:31:26 -0000
***************
*** 550,556 ****
/* Possible microtiming output */
if (pset.timing && success)
! printf(gettext("Time: %.2f ms\n"), DIFF_MSEC(after, before));
return success;
}
--- 550,556 ----
/* Possible microtiming output */
if (pset.timing && success)
! printf(gettext("Time: %.3f ms\n"), DIFF_MSEC(after, before));
return success;
}
Tom Lane wrote:
> Peter Eisentraut <peter_e@gmx.net> writes:
> > Tom Lane writes:
> >> BTW, EXPLAIN ANALYZE puts out
> >> Total runtime: 406.53 msec
> >> Do you want to make an exception to the string freeze to change this
> >> to "ms"?
>
> > I just realized, all the things that are sent as a query result instead of
> > an error or notice are not gettext-enabled. I guess we'll have to do
> > without that in this release. So, making the above change does not pose a
> > problem.
>
> Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue?
Here is the patch that makes psql \timing display three digits:
test=> \timing
Timing is on.
test=> select 1;
?column?
----------
1
(1 row)
Time: 1.306 ms
--
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, Pennsylvania 19073
? psql
Index: common.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/bin/psql/common.c,v
retrieving revision 1.74
diff -c -c -r1.74 common.c
*** common.c 16 Sep 2003 17:59:02 -0000 1.74
--- common.c 5 Oct 2003 22:31:26 -0000
***************
*** 550,556 ****
/* Possible microtiming output */
if (pset.timing && success)
! printf(gettext("Time: %.2f ms\n"), DIFF_MSEC(after, before));
return success;
}
--- 550,556 ----
/* Possible microtiming output */
if (pset.timing && success)
! printf(gettext("Time: %.3f ms\n"), DIFF_MSEC(after, before));
return success;
}
> The problem with two lines is that another log message could get between > them. I agree milliseconds makes more sense for output. That's not a huge problem. I've run our servers like that for ages, and there's not really any time when a human can't tell what's going on. You can also turn on PID logging as well. (Should that even be on by default? Chris
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Agreed. elog is the proper place, because then you guarantee that it is
> all on one line. Is that OK? Do we have elogs that we want over
> several lines? Is this something we can do at this stage in beta?
As to the latter: sure. We've already hacked the formatting of the log
output quite a bit since 7.3. Better to hit them with this too now,
than spread the pain over multiple releases.
As to the former: the only thing that seems debatable to me is what to
do about the layout of the new multi-part ereport() messages. I would
be inclined to go for one line per part, viz
ERROR: blah blah blah
DETAIL: blah blah\nblah blah
HINT: blah blah\nblah blah\nblah blah
but perhaps someone would like to argue for somehow collapsing all this
to one line? If so, how exactly?
regards, tom lane
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Agreed. elog is the proper place, because then you guarantee that it is
> > all on one line. Is that OK? Do we have elogs that we want over
> > several lines? Is this something we can do at this stage in beta?
>
> As to the latter: sure. We've already hacked the formatting of the log
> output quite a bit since 7.3. Better to hit them with this too now,
> than spread the pain over multiple releases.
>
> As to the former: the only thing that seems debatable to me is what to
> do about the layout of the new multi-part ereport() messages. I would
> be inclined to go for one line per part, viz
> ERROR: blah blah blah
> DETAIL: blah blah\nblah blah
> HINT: blah blah\nblah blah\nblah blah
> but perhaps someone would like to argue for somehow collapsing all this
> to one line? If so, how exactly?
Are those lines sent to the elog as one write() or separate ones --- do
they always appear together in the log?
I had a new idea on output format. Instead of converting newline to
"\n", and double-escaping backslashes, we add a tab after any newline,
so the output looks like:
LOG: duration: 4.035 ms query: select *
from pg_language;
This makes the logs look better, and it is easier for script to grab
queries. Grep doesn't work as well, but I think that is OK.
--
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, Pennsylvania 19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Are those lines sent to the elog as one write() or separate ones --- do
> they always appear together in the log?
Currently they are sent in a single fprintf(stderr), which might or
might not be good enough to ensure atomicity. We could hack this
to a direct write() if you don't mind depending on fileno(stderr),
but I think that'd create some portability issues on non-Unix
platforms.
If you're using syslog then I think all bets are off anyway.
> I had a new idea on output format. Instead of converting newline to
> "\n", and double-escaping backslashes, we add a tab after any newline,
That's a thought... seems less invasive than the backslashing. Not sure
how well it'll work for syslog output though.
regards, tom lane
On Mon, Oct 06, 2003 at 10:42:57AM -0400, Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > I had a new idea on output format. Instead of converting newline to
> > "\n", and double-escaping backslashes, we add a tab after any newline,
>
> That's a thought... seems less invasive than the backslashing. Not sure
> how well it'll work for syslog output though.
Not good. Some syslogs will replace the literal tab with a ^I.
Maybe it should be a bunch of spaces when using syslog.
It seems a good idea to me anyway.
How would it handle multiple fields? Say
LOG: blah blah
DETAIL: something
HINT: something else
Will it be
LOG: blah blah
DETAIL: something else
HINT: something else
?
--
Alvaro Herrera (<alvherre[@]dcc.uchile.cl>)
"Find a bug in a program, and fix it, and the program will work today.
Show the program how to find and fix a bug, and the program
will work forever" (Oliver Silfridge)
Alvaro Herrera Munoz <alvherre@dcc.uchile.cl> writes:
>> Bruce Momjian <pgman@candle.pha.pa.us> writes:
>> I had a new idea on output format. Instead of converting newline to
>> "\n", and double-escaping backslashes, we add a tab after any newline,
> Not good. Some syslogs will replace the literal tab with a ^I.
That seems okay. We just want to make sure continuation lines are
easily distinguishable. (But leading spaces would be okay with me too.)
> How would it handle multiple fields? Say
> LOG: blah blah
> DETAIL: something
> HINT: something else
> Will it be
> LOG: blah blah
> DETAIL: something else
> HINT: something else
No, one would hope no tab before DETAIL/HINT/etc. The idea is to be
able to recognize when the contents of one of these entries spans lines.
regards, tom lane
Tom Lane wrote: > Alvaro Herrera Munoz <alvherre@dcc.uchile.cl> writes: > >> Bruce Momjian <pgman@candle.pha.pa.us> writes: > >> I had a new idea on output format. Instead of converting newline to > >> "\n", and double-escaping backslashes, we add a tab after any newline, > > > Not good. Some syslogs will replace the literal tab with a ^I. > > That seems okay. We just want to make sure continuation lines are > easily distinguishable. (But leading spaces would be okay with me too.) Agreed. It is easy to strip off the tab to rebuild the original query --- striping off 8 spaces seems less logical. -- 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, Pennsylvania 19073
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Are those lines sent to the elog as one write() or separate ones --- do
> > they always appear together in the log?
>
> Currently they are sent in a single fprintf(stderr), which might or
> might not be good enough to ensure atomicity. We could hack this
> to a direct write() if you don't mind depending on fileno(stderr),
> but I think that'd create some portability issues on non-Unix
> platforms.
>
> If you're using syslog then I think all bets are off anyway.
>
> > I had a new idea on output format. Instead of converting newline to
> > "\n", and double-escaping backslashes, we add a tab after any newline,
>
> That's a thought... seems less invasive than the backslashing. Not sure
> how well it'll work for syslog output though.
OK, new version attached that puts a tab before any elog continuation
line in the server logs. This will give us consistent multi-line server
log output. It does not affect the client output, which I think is
correct.
Output looks like:
LOG: duration: 4.138 ms query: select *
from pg_language;
LOG: duration: 7.560 ms query: select * from pg_class;
Now, this does not address Tom's objection that you have can't use grep
anyway to pull lines from the server logs, but it is closer to usable
for scripts, and easier for people to read in the file.
The problem with doing statement and duration on separate lines is this:
LOG: duration: 4.138 ms
LOG: query: select *
from pg_language;
LOG: duration: 7.560 ms
LOG: query: select * from pg_class;
It isn't clear which duration goes with which line, even if they don't
intermingle. If you output on separate lines, you would have to use
log_pid. However, since people can use log_duration and log_statement
separately already anyway, I think this merged line is easier for casual
users.
--
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, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 -0000 1.210
--- doc/src/sgml/runtime.sgml 6 Oct 2003 21:33:06 -0000
***************
*** 1689,1704 ****
<listitem>
<para>
Sets a minimum statement execution time (in milliseconds)
! above which a statement will be logged. All SQL statements
! that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero (the default)
! disables time-based logging. For example, if you set it
! to <literal>250</literal> then all SQL statements that run longer
! than 250ms will be logged. Enabling this
! option can be useful in tracking down unoptimized queries in
! your applications.
! Only superusers can increase this or set it to zero if this option
! is set to non-zero by the administrator.
</para>
</listitem>
</varlistentry>
--- 1689,1704 ----
<listitem>
<para>
Sets a minimum statement execution time (in milliseconds)
! for statement to be logged. All SQL statements
! that run in the time specified or longer will be logged with
! their duration. Setting this to zero will print
! all queries and their durations. Minus-one (the default)
! disables this. For example, if you set it to
! <literal>250</literal> then all SQL statements that run 250ms
! or longer will be logged. Enabling this option can be
! useful in tracking down unoptimized queries in your applications.
! Only superusers can increase this or set it to minus-one if this
! option is set by the administrator.
</para>
</listitem>
</varlistentry>
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 -0000 1.370
--- src/backend/tcop/postgres.c 6 Oct 2003 21:33:11 -0000
***************
*** 694,700 ****
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
--- 694,700 ----
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
gettimeofday(&start_t, NULL);
if (save_log_statement_stats)
***************
*** 940,946 ****
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement > 0)
{
long usecs;
bool print_statement;
--- 940,946 ----
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
{
long usecs;
bool print_statement;
***************
*** 957,971 ****
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000);
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration(secs): %ld.%06ld%s%s",
! (long) (stop_t.tv_sec - start_t.tv_sec),
! (long) (stop_t.tv_usec - start_t.tv_usec),
! print_statement ? " " : "",
print_statement ? query_string : "")));
}
--- 957,973 ----
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement == 0 ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000));
if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms%s%s",
! (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
! (stop_t.tv_usec - start_t.tv_usec) / 1000),
! (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! print_statement ? " query: " : "",
print_statement ? query_string : "")));
}
***************
*** 3196,3198 ****
--- 3198,3201 ----
pfree(str.data);
}
+
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/error/elog.c,v
retrieving revision 1.123
diff -c -c -r1.123 elog.c
*** src/backend/utils/error/elog.c 25 Sep 2003 06:58:05 -0000 1.123
--- src/backend/utils/error/elog.c 6 Oct 2003 21:33:12 -0000
***************
*** 145,150 ****
--- 145,151 ----
static const char *error_severity(int elevel);
static const char *print_timestamp(void);
static const char *print_pid(void);
+ static char *str_prepend_tabs(const char *str);
/*
***************
*** 1135,1140 ****
--- 1136,1143 ----
/* Write to stderr, if enabled */
if (Use_syslog <= 1 || whereToSendOutput == Debug)
{
+ char *p = str_prepend_tabs(buf.data);
+
/*
* Timestamp and PID are only used for stderr output --- we assume
* the syslog daemon will supply them for us in the other case.
***************
*** 1142,1148 ****
fprintf(stderr, "%s%s%s",
Log_timestamp ? print_timestamp() : "",
Log_pid ? print_pid() : "",
! buf.data);
}
pfree(buf.data);
--- 1145,1152 ----
fprintf(stderr, "%s%s%s",
Log_timestamp ? print_timestamp() : "",
Log_pid ? print_pid() : "",
! p);
! pfree(p);
}
pfree(buf.data);
***************
*** 1449,1452 ****
--- 1453,1477 ----
snprintf(buf, sizeof(buf), "[%d] ", (int) MyProcPid);
return buf;
+ }
+
+ /*
+ * str_prepend_tabs
+ *
+ * This string prepends a tab to message continuation lines.
+ */
+ static char *str_prepend_tabs(const char *str)
+ {
+ char *outstr = palloc(strlen(str) * 2 + 1);
+ int len = strlen(str);
+ int i, outlen = 0;
+
+ for (i = 0; i < len; i++)
+ {
+ outstr[outlen++] = str[i];
+ if (str[i] == '\n' && str[i+1] != '\0' )
+ outstr[outlen++] = '\t';
+ }
+ outstr[outlen++] = '\0';
+ return outstr;
}
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.162
diff -c -c -r1.162 guc.c
*** src/backend/utils/misc/guc.c 3 Oct 2003 19:26:49 -0000 1.162
--- src/backend/utils/misc/guc.c 6 Oct 2003 21:33:17 -0000
***************
*** 128,134 ****
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = 0;
/*
--- 128,134 ----
int log_min_messages = NOTICE;
int client_min_messages = NOTICE;
! int log_min_duration_statement = -1;
/*
***************
*** 1185,1194 ****
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("The default is 0 (turning this feature off).")
},
&log_min_duration_statement,
! 0, 0, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
--- 1185,1194 ----
{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
gettext_noop("minimum execution time in milliseconds above which statements will "
"be logged"),
! gettext_noop("Zero prints all queries. The default is -1 (turning this feature off).")
},
&log_min_duration_statement,
! -1, -1, INT_MAX / 1000, NULL, NULL
},
/* End-of-list marker */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.91
diff -c -c -r1.91 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample 3 Oct 2003 19:26:49 -0000 1.91
--- src/backend/utils/misc/postgresql.conf.sample 6 Oct 2003 21:33:17 -0000
***************
*** 157,165 ****
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = 0 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero disables.
#silent_mode = false # DO NOT USE without Syslog!
--- 157,166 ----
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
! #log_min_duration_statement = -1 # Log all statements whose
# execution time exceeds the value, in
! # milliseconds. Zero prints all queries.
! # Minus-one disables.
#silent_mode = false # DO NOT USE without Syslog!
Bruce Momjian writes: > I had a new idea on output format. Instead of converting newline to > "\n", and double-escaping backslashes, we add a tab after any newline, Then how would you identify the real tabs in the data? -- Peter Eisentraut peter_e@gmx.net
Bruce Momjian writes: > Another idea if you like consistency would be: > > LOG: duration: 4.056 ms query: select * \nfrom pg_language; Speaking of consistency... Imagine someone always having log_statement on and doing some sort of aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that someone (or maybe the admin on the night shift, to make it more dramatic) also turns on log_min_statement_duration (or whatever it's spelled), say to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head -10. In order to guarantee the consistency of both results, you'd have to log each query twice in this case. -- Peter Eisentraut peter_e@gmx.net
Peter Eisentraut wrote: > Bruce Momjian writes: > > > I had a new idea on output format. Instead of converting newline to > > "\n", and double-escaping backslashes, we add a tab after any newline, > > Then how would you identify the real tabs in the data? Any log line that starts with a tab was added for readability of multi-line output. If the query line starts with a tab, it will be tab-tab in the file. -- 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, Pennsylvania 19073
Peter Eisentraut wrote: > Bruce Momjian writes: > > > Another idea if you like consistency would be: > > > > LOG: duration: 4.056 ms query: select * \nfrom pg_language; > > Speaking of consistency... > > Imagine someone always having log_statement on and doing some sort of > aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that > someone (or maybe the admin on the night shift, to make it more dramatic) > also turns on log_min_statement_duration (or whatever it's spelled), say > to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head > -10. In order to guarantee the consistency of both results, you'd have to > log each query twice in this case. I guess. -- 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, Pennsylvania 19073
Bruce Momjian writes: > > Imagine someone always having log_statement on and doing some sort of > > aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that > > someone (or maybe the admin on the night shift, to make it more dramatic) > > also turns on log_min_statement_duration (or whatever it's spelled), say > > to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head > > -10. In order to guarantee the consistency of both results, you'd have to > > log each query twice in this case. > > I guess. Can we agree to this? * If log_statement is on, then we log query: %s (Should it be "statement: %s"?) %s has newlines suitable escaped; exactly how is independent of this discussion. * If log_duration is on, then we log duration: x.xxx ms The user can use log_pid to link it to the statement. (If the user doesn't like this, he can use log_min_duration_statement=0.) * If log_min_duration_statement is triggered, then we log duration: x.xxx ms; query: %s * If log_statement is on and log_min_duration_statement is triggered, then we (pick one): (a) log both as per above, or (b) log only log_min_duration_statement * If log_duration is on and log_min_duration_statement is triggered, then we (pick one): (a) log both as per above, or (b) log only log_min_duration_statement -- Peter Eisentraut peter_e@gmx.net
Peter Eisentraut wrote:
> Bruce Momjian writes:
>
> > > Imagine someone always having log_statement on and doing some sort of
> > > aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that
> > > someone (or maybe the admin on the night shift, to make it more dramatic)
> > > also turns on log_min_statement_duration (or whatever it's spelled), say
> > > to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head
> > > -10. In order to guarantee the consistency of both results, you'd have to
> > > log each query twice in this case.
> >
> > I guess.
>
> Can we agree to this?
>
> * If log_statement is on, then we log
>
> query: %s
>
> (Should it be "statement: %s"?) %s has newlines suitable escaped; exactly
Yes, it should be 'statement'.
> how is independent of this discussion.
People didn't like the newlines changed because it makes large queries
hard to read (all on one line), and we had to double-escape backslashes,
meaning the logged query had different backslashing from the original.
> * If log_duration is on, then we log
>
> duration: x.xxx ms
>
> The user can use log_pid to link it to the statement. (If the user
> doesn't like this, he can use log_min_duration_statement=0.)
Exactly. log_min_duration_statement=0 delays the print of the statement
until it completes, but it prints them together.
> * If log_min_duration_statement is triggered, then we log
>
> duration: x.xxx ms; query: %s
>
> * If log_statement is on and log_min_duration_statement is triggered, then
> we (pick one):
>
> (a) log both as per above, or
I think we have to log both because perhaps they want the query printed
before it completes.
> (b) log only log_min_duration_statement
>
> * If log_duration is on and log_min_duration_statement is triggered, then
> we (pick one):
>
> (a) log both as per above, or
> (b) log only log_min_duration_statement
Good point. Right now we do only:
duration: x.xxx ms; query: %s
This seems wrong because it isn't consistent with log_statement. Glad
you pointed that out. The only argument for printing one one is that
there isn't any value to printing the duration separately, because it
isn't printing before the query. However, for consistency, I think you
are right we should print both.
--
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, Pennsylvania 19073
OK, patch attached and applied. Changes are:
"query:" now "statement:"
log_duration also now prints when log_min_duration_statement prints
---------------------------------------------------------------------------
Peter Eisentraut wrote:
> Bruce Momjian writes:
>
> > > Imagine someone always having log_statement on and doing some sort of
> > > aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that
> > > someone (or maybe the admin on the night shift, to make it more dramatic)
> > > also turns on log_min_statement_duration (or whatever it's spelled), say
> > > to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head
> > > -10. In order to guarantee the consistency of both results, you'd have to
> > > log each query twice in this case.
> >
> > I guess.
>
> Can we agree to this?
>
> * If log_statement is on, then we log
>
> query: %s
>
> (Should it be "statement: %s"?) %s has newlines suitable escaped; exactly
> how is independent of this discussion.
>
> * If log_duration is on, then we log
>
> duration: x.xxx ms
>
> The user can use log_pid to link it to the statement. (If the user
> doesn't like this, he can use log_min_duration_statement=0.)
>
> * If log_min_duration_statement is triggered, then we log
>
> duration: x.xxx ms; query: %s
>
> * If log_statement is on and log_min_duration_statement is triggered, then
> we (pick one):
>
> (a) log both as per above, or
> (b) log only log_min_duration_statement
>
> * If log_duration is on and log_min_duration_statement is triggered, then
> we (pick one):
>
> (a) log both as per above, or
> (b) log only log_min_duration_statement
>
> --
> Peter Eisentraut peter_e@gmx.net
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: you can get off all lists at once with the unregister command
> (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
>
--
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, Pennsylvania 19073
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.371
diff -c -c -r1.371 postgres.c
*** src/backend/tcop/postgres.c 8 Oct 2003 03:49:37 -0000 1.371
--- src/backend/tcop/postgres.c 9 Oct 2003 02:37:19 -0000
***************
*** 461,467 ****
if (log_statement)
ereport(LOG,
! (errmsg("query: %s", query_string)));
if (log_parser_stats)
ResetUsage();
--- 461,467 ----
if (log_statement)
ereport(LOG,
! (errmsg("statement: %s", query_string)));
if (log_parser_stats)
ResetUsage();
***************
*** 943,949 ****
if (save_log_duration || save_log_min_duration_statement != -1)
{
long usecs;
- bool print_statement;
gettimeofday(&stop_t, NULL);
if (stop_t.tv_usec < start_t.tv_usec)
--- 943,948 ----
***************
*** 953,974 ****
}
usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);
/*
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement == 0 ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000));
!
! if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms%s%s",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
(stop_t.tv_usec - start_t.tv_usec) / 1000),
(long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! print_statement ? " query: " : "",
! print_statement ? query_string : "")));
}
if (save_log_statement_stats)
--- 952,977 ----
}
usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);
+ if (save_log_duration)
+ ereport(LOG,
+ (errmsg("duration: %ld.%03ld ms",
+ (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+ (stop_t.tv_usec - start_t.tv_usec) / 1000),
+ (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+
/*
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! if (save_log_min_duration_statement == 0 ||
! (save_log_min_duration_statement > 0 &&
! usecs >= save_log_min_duration_statement * 1000))
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms statement: %s",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
(stop_t.tv_usec - start_t.tv_usec) / 1000),
(long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
! query_string)));
}
if (save_log_statement_stats)
pgman wrote: > > OK, patch attached and applied. Changes are: > > "query:" now "statement:" > log_duration also now prints when log_min_duration_statement prints Oh, sample is: LOG: statement: select 1; LOG: duration: 0.329 ms LOG: duration: 0.329 ms statement: select 1; -- 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, Pennsylvania 19073