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 <[EMAIL PROTECTED]> writes:
> > > Tom Lane wrote:
> > >> I would prefer to see the log entries look like
> > >>
> > >> LOG: query: select * from pg_class;
> > >> LOG: duration: nn.nnn msec
> >
> > > The problem with two lines is that another log message could get between
> > > them.
> >
> > That was true already with log_statement and log_duration as separate
> > operations. People use log_pid to deal with it.
>
> Attached are some emails I sent while we were discussing this feature in
> March.
>
> The idea was for the parameter to show query and duration --- a
> combination that is asked for frequently and easily grep'ed, unlike
> joining on pid, which because of pid wrap-around, isn't even fool-proof.
>
> One thing that isn't implemented in current CVS is to allow 0 to always
> print the duration and query (-1 disables it and is the default). I can
> see that being _very_ valuable, and used enough to warrant the fact that
> it isn't orthoginal (we already have log_statement). The reason we
> needed to do it this way was so we could print the statement _after_ it
> completes so we could include the duration.
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <[EMAIL PROTECTED]>
> To: Greg Stark <[EMAIL PROTECTED]>
> Date: Wed, 12 Feb 2003 16:49:58 -0500 (EST)
> cc: [EMAIL PROTECTED]
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length: 3288
> Status: OR
>
> Greg Stark wrote:
> > Tom Lane <[EMAIL PROTECTED]> writes:
> >
> > > "Christopher Kings-Lynne" <[EMAIL PROTECTED]> writes:
> > > > Looking at the log_duration postgresql.conf option. How about adding an
> > > > option log_duration_min which is a value in milliseconds that is the minimum
> > > > time a query must run for before being logged.
> > >
> > > Fine with me --- but you'll need to add more logic than that. Right
> > > now, log_duration *only* causes the query duration to be printed out;
> > > if you ain't got log_statement on, you're in the dark as to what the
> > > query itself was. You'll need to add some code to print the query
> > > (the log_min_error_statement logic might be a useful source of
> > > inspiration). Not sure how this should interact with the case where
> > > log_duration is set and the min-duration isn't. But maybe that case
> > > is silly, and we should just redefine log_duration as a minimum runtime
> > > that causes the query *and* its runtime to be printed to the log.
>
> Tom is right here. log_duration _just_ prints the duration, so we would
> need to basically create a merged param that does log_duration and
> log_statement and have it activate only if the statement takes more than
> X milliseconds, something like log_long_statement, or something like
> that.
>
> Here are the log_* params we have:
>
> log_connections = false
> log_hostname = false
> log_source_port = false
> log_pid = false
> log_statement = false
> log_duration = false
> log_timestamp = false
>
> Basically, log_pid pulls them all together. Without that, you don't
> have any way to pull together individual lines in the log, and with pid
> wraparound, you can't even do that 100%. I wonder if we should put a
> number before the pid and increment it on every pid wraparound.
>
> One nice thing is that each element is orthoginal. But, for the
> functionality desired, we have to merge log_statement and log_duration
> and have it print for statements taking over X milliseconds. I have no
> problem adding it, but it has to be clear it isn't orthoginal but is a
> conditional combination of two other parameters.
>
> > Is it even guaranteed to be properly ordered on a busy server with multiple
> > processors anyways?
> >
> > One option is to have log_query output an identifier with the query such as a
> > hash of the query or the pointer value for the plan, suppressing duplicates.
> > Then log_duration prints the identifier with the duration.
> >
> > This means on a busy server running lots of prepared queries you would see a
> > whole bunch of queries on startup, then hopefully no durations. Any durations
> > printed could cause alarms to go off. To find the query you grep the logs for
> > the identifier in the duration message.
>
> Actually, log_pid is the proper way to do this. You can then add log
> connections, and get a full snapshot of what is happening for that
> session.
>
> > This only really works if you're using prepared queries everywhere. But in the
> > long run that will be the case for OLTP systems, which is where log_duration
> > is really useful.
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <[EMAIL PROTECTED]>
> To: Christopher Kings-Lynne <[EMAIL PROTECTED]>
> Date: Wed, 12 Feb 2003 21:32:05 -0500 (EST)
> cc: Greg Stark <[EMAIL PROTECTED]>, [EMAIL PROTECTED]
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length: 1245
> Status: OR
>
> Christopher Kings-Lynne wrote:
> > > Tom is right here. log_duration _just_ prints the duration, so we would
> > > need to basically create a merged param that does log_duration and
> > > log_statement and have it activate only if the statement takes more than
> > > X milliseconds, something like log_long_statement, or something like
> > > that.
> > >
> > > Here are the log_* params we have:
> > >
> > > log_connections = false
> > > log_hostname = false
> > > log_source_port = false
> > > log_pid = false
> > > log_statement = false
> > > log_duration = false
> > > log_timestamp = false
> >
> > OK, while I'm doing all this benchmarking and stuff - is there any sort of
> > option where I can see it logged when a sort doesn't have enought sort
> > memory and hence hits the disk? eg. an elog(LOG) is emitted?
>
> Someone asked about this at FOSDEM. The only way I know to do it is look
> in the pgsql_temp directory, but they disappear pretty quickly. Folks,
> do we need something to report sort file usage?
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <[EMAIL PROTECTED]>
> To: Christopher Kings-Lynne <[EMAIL PROTECTED]>
> Date: Wed, 12 Feb 2003 22:07:04 -0500 (EST)
> cc: Greg Stark <[EMAIL PROTECTED]>, [EMAIL PROTECTED]
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length: 1366
> Status: OR
>
>
> Well, part of the issue here is that it isn't always bad to use sort
> file; certainly it is better to use them than to swap.
>
> We have a checkpoint_warning in 7.4 that will warn about excessive
> checkpointing. What would our criteria be for warning about sort_mem?
> Seems we would have to know how much free memory there is available, and
> in fact, if there is lots of free memory, the sort files will just sit
> in the kernel disk cache anyway.
>
> I am not saying this is a bad idea --- we just need to define it clearer.
>
> ---------------------------------------------------------------------------
>
> Christopher Kings-Lynne wrote:
> > > Someone asked about this at FOSDEM. The only way I know to do it is look
> > > in the pgsql_temp directory, but they disappear pretty quickly. Folks,
> > > do we need something to report sort file usage?
> >
> > How about a new GUC variable: log_sort_tempfiles
> >
> > And in the code that creates the temp file, if the GUC variable is true,
> > then do:
> >
> > elog(LOG, "Sort needed temp file. Sort required 2456K. Try increasing
> > sort_mem.");
> >
> > Or something?
> >
> > Chris
> >
> >
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
>
> >From pgman Wed Feb 12 15:03:03 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <[EMAIL PROTECTED]>
> To: Tom Lane <[EMAIL PROTECTED]>
> Date: Wed, 12 Feb 2003 23:46:11 -0500 (EST)
> cc: Greg Stark <[EMAIL PROTECTED]>, [EMAIL PROTECTED]
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length: 1792
> Status: OR
>
> Tom Lane wrote:
> > Bruce Momjian <[EMAIL PROTECTED]> writes:
> > > One nice thing is that each element is orthoginal. But, for the
> > > functionality desired, we have to merge log_statement and log_duration
> > > and have it print for statements taking over X milliseconds. I have no
> > > problem adding it, but it has to be clear it isn't orthoginal but is a
> > > conditional combination of two other parameters.
> >
> > Actually, I was wondering if we shouldn't *replace* the current
> > log_duration with a combined form (that specifies a minimum interesting
> > duration). I can't quite see the need for orthogonality here. The
> > only reason you'd care about query duration is that you're looking for
> > the slow ones, no? So why bother logging the fast ones? Besides, you
> > can specify min-duration zero if you really want 'em all.
>
> We did talk about this a while ago, and folks wanted the query printed
> _before_ it was executed, so they could see the query in the logs at the
> time it was issued, both for monitoring and for showing the time the
> query started when log_timestamp is enabled.
>
> Seems the clearest option would be for log_duration to print the query
> string too, and convert it to an integer field. I can see zero meaning
> print all queries and durations. What value do we use to turn it off?
> -1?
>
> This would give us log_statement that prints at query start, and
> log_duration that prints query and duration at query end. How is that?
>
> Maybe we should rename them as log_statement_start and
> log_statement_duration.
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
>
> >From pgman Fri Mar 14 09:01:29 2003
> Subject: Re: [HACKERS] log_duration
> In-Reply-To: <[EMAIL PROTECTED]>
> To: Bruce Momjian <[EMAIL PROTECTED]>
> Date: Fri, 14 Mar 2003 14:27:38 -0500 (EST)
> cc: Tom Lane <[EMAIL PROTECTED]>, Greg Stark <[EMAIL PROTECTED]>,
> [EMAIL PROTECTED]
> X-Mailer: ELM [version 2.4ME+ PL99 (25)]
> MIME-Version: 1.0
> Content-Transfer-Encoding: 7bit
> Content-Type: text/plain; charset=US-ASCII
> Content-Length: 2472
> Status: OR
>
>
> Added to TODO:
>
> * Add GUC log_statement_duration to print statement and >= min duration
>
> ---------------------------------------------------------------------------
>
> Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <[EMAIL PROTECTED]> writes:
> > > > One nice thing is that each element is orthoginal. But, for the
> > > > functionality desired, we have to merge log_statement and log_duration
> > > > and have it print for statements taking over X milliseconds. I have no
> > > > problem adding it, but it has to be clear it isn't orthoginal but is a
> > > > conditional combination of two other parameters.
> > >
> > > Actually, I was wondering if we shouldn't *replace* the current
> > > log_duration with a combined form (that specifies a minimum interesting
> > > duration). I can't quite see the need for orthogonality here. The
> > > only reason you'd care about query duration is that you're looking for
> > > the slow ones, no? So why bother logging the fast ones? Besides, you
> > > can specify min-duration zero if you really want 'em all.
> >
> > We did talk about this a while ago, and folks wanted the query printed
> > _before_ it was executed, so they could see the query in the logs at the
> > time it was issued, both for monitoring and for showing the time the
> > query started when log_timestamp is enabled.
> >
> > Seems the clearest option would be for log_duration to print the query
> > string too, and convert it to an integer field. I can see zero meaning
> > print all queries and durations. What value do we use to turn it off?
> > -1?
> >
> > This would give us log_statement that prints at query start, and
> > log_duration that prints query and duration at query end. How is that?
> >
> > Maybe we should rename them as log_statement_start and
> > log_statement_duration.
> >
> > --
> > Bruce Momjian | http://candle.pha.pa.us
> > [EMAIL PROTECTED] | (610) 359-1001
> > + If your life is a hard drive, | 13 Roberts Road
> > + Christ can be your backup. | Newtown Square, Pennsylvania 19073
> >
> > ---------------------------(end of broadcast)---------------------------
> > TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
> >
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> [EMAIL PROTECTED] | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster
--
Bruce Momjian | http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
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!
---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to [EMAIL PROTECTED] so that your
message can get through to the mailing list cleanly
