Thread: log_duration
Hi guys, 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. Basically, what I'd be interested in is "please log the SQL query and duration of all queries that last longer than 500ms". That way I can quickly find badly formed queries, index them, etc... Idea? Chris
"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 = falselog_hostname = falselog_source_port = falselog_pid = falselog_statement= falselog_duration = falselog_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, Pennsylvania19073
> > 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, Pennsylvania19073
> 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, Pennsylvania19073
> 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, Pennsylvania19073
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
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 = falselog_hostname = falselog_source_port = falselog_pid = falselog_statement= falselog_duration = falselog_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, Pennsylvania19073
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, Pennsylvania19073
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
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, Pennsylvania19073
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
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
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, Pennsylvania19073
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, Pennsylvania19073
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
--ELM1065322164-13056-0_--
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, Pennsylvania19073 --ELM1065322164-13056-0_--