log_duration

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

regards, tom lane

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.

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.

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.

--
greg

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

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.

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.

Personally I would prefer a unique identifier. I guess the best way of
illustrating my intuition would be: "Imagine loading all this data into a
relational database, what would you need to full normalize it?".

Parsing log files programmatically is much easier if you have unique
identifiers instead of having to rely on the relative relationships of entries
in the log.

Not a big deal though, since I doubt anyone's actually parsing postgres logs.
Hm, brings up an interesting idea though, I wonder if it would be useful to
log directly into postgres tables.

--
greg

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?

Chris

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

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

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

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?

Fwiw here's the perl one-liner I used to tune sort_mem recently,
(run in the $PGDATA/base directory):

perl -e 'while (sleep(1)) {if ($s = -s <pgsql_tmp/*>) { if ($s > $m) { $m = $s; print "$s\n"; } } }'

When doing this I had precisely the same thought about having Postgres print
out the disk space usage for sorts.

--
greg

Greg Stark wrote:

Not a big deal though, since I doubt anyone's actually parsing
postgres logs. Hm, brings up an interesting idea though, I wonder
if it would be useful to log directly into postgres tables.

I was wondering roughly the same thing. If you ran an external
program to process the logs and put them into a PostgreSQL database,
you'd have problems with the transactions of the log processor landing
in the logs as well, at least if all transactions were logged. The
logging process would have to filter out its own transactions, which
might not be all that easy.

--
Kevin Brown kevin@sysexperts.com

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.

regards, tom lane

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

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