fix log_min_duration_statement logic error

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

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

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

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