Обсуждение: log_min_duration_statement versus log_statement
Hello there,
I've just discovered that our postgresql.conf and the related
documentation are a bit unclear when explaining how log_min_duration_statement
works. From the wording
log_min_duration_statement = 1000 # Log all statements whose
# execution time exceeds the value, in
# milliseconds. -1 disables. Zero logs
# all statements.
I would think that if I enabled it, it would override/control the statements
being logged. However, that's not how it behaves (at least in
kiko@anthem:~$ psql -V
psql (PostgreSQL) 7.4.7
) -- if I enable it /and/ log_statement is enabled as well, I get all
statements logged. In other words, the trailing sentence:
# Zero logs all statements.
is confusing because it seems to imply that to log all statements you should
set log_min_duration_statement to zero.
I'd much prefer a behaviour change here (it would make it more obvious and
useful for log_min_duration_statement, which appears under "When to Log", to
control /when/ to log, and "What to log" to control /what/ to log :-), but I
think I'd have been less confused with a documentation change that explicitly
said that if log_statement or log_duration are on, then /all/ statements will
be logged, regardless of log_min_duration_statement.
Below is a snippet of that I have now (which is exactly what I want) in
my postgresql.conf. From visual inspection only, it would appear that
this configuration would print nothing (since nothing is defined under
"What to Log"). However, it does exactly what I want (only log
statements that run over 1s).
----------------------------------------------------------------------
# - When to Log -
#client_min_messages = notice # Values, in order of decreasing detail:
# debug5, debug4, debug3, debug2, debug1,
# log, info, notice, warning, error
#log_min_messages = notice # Values, in order of decreasing detail:
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, log, fatal,
# panic
#log_error_verbosity = default # terse, default, or verbose messages
#log_min_error_statement = panic # Values in order of increasing severity:
# debug5, debug4, debug3, debug2, debug1,
# info, notice, warning, error, panic(off)
log_min_duration_statement = 1000 # Log all statements whose
# execution time exceeds the value, in
# milliseconds. -1 disables. Zero logs
# all statements.
silent_mode = false # DO NOT USE without Syslog!
# - What to Log -
#debug_print_parse = false
#debug_print_rewritten = false
#debug_print_plan = false
#debug_pretty_print = false
#log_connections = false
#log_duration = false
#log_pid = false
#log_statement = false
#log_timestamp = false
#log_hostname = false
#log_source_port = false
----------------------------------------------------------------------
Opinions? Am I confused? Thanks for listening.
Take care,
--
Christian Robottom Reis | http://async.com.br/~kiko/ | [+55 16] 3376 0125
OK, what if we change the documentaiton to be:
log_min_duration_statement = 1000 # Log all statements whose
# execution time exceeds the value, in
# milliseconds. -1 disables. Zero logs
# all statements and their durations.
I think you are confused because log_min_duration_statement is really
about _when_ to log (duration > ? ms), and what to log (the statement).
Also, if you set log_min_duration_statement = 1000, it will print every
statement which takes over 1 second, and its duration. Are you not
seeing that happen?
---------------------------------------------------------------------------
Christian Robottom Reis wrote:
>
> Hello there,
>
> I've just discovered that our postgresql.conf and the related
> documentation are a bit unclear when explaining how log_min_duration_statement
> works. From the wording
>
> log_min_duration_statement = 1000 # Log all statements whose
> # execution time exceeds the value, in
> # milliseconds. -1 disables. Zero logs
> # all statements.
>
> I would think that if I enabled it, it would override/control the statements
> being logged. However, that's not how it behaves (at least in
>
> kiko@anthem:~$ psql -V
> psql (PostgreSQL) 7.4.7
>
> ) -- if I enable it /and/ log_statement is enabled as well, I get all
> statements logged. In other words, the trailing sentence:
>
> # Zero logs all statements.
>
> is confusing because it seems to imply that to log all statements you should
> set log_min_duration_statement to zero.
>
> I'd much prefer a behaviour change here (it would make it more obvious and
> useful for log_min_duration_statement, which appears under "When to Log", to
> control /when/ to log, and "What to log" to control /what/ to log :-), but I
> think I'd have been less confused with a documentation change that explicitly
> said that if log_statement or log_duration are on, then /all/ statements will
> be logged, regardless of log_min_duration_statement.
>
> Below is a snippet of that I have now (which is exactly what I want) in
> my postgresql.conf. From visual inspection only, it would appear that
> this configuration would print nothing (since nothing is defined under
> "What to Log"). However, it does exactly what I want (only log
> statements that run over 1s).
>
> ----------------------------------------------------------------------
> # - When to Log -
>
> #client_min_messages = notice # Values, in order of decreasing detail:
> # debug5, debug4, debug3, debug2, debug1,
> # log, info, notice, warning, error
>
> #log_min_messages = notice # Values, in order of decreasing detail:
> # debug5, debug4, debug3, debug2, debug1,
> # info, notice, warning, error, log, fatal,
> # panic
>
> #log_error_verbosity = default # terse, default, or verbose messages
>
> #log_min_error_statement = panic # Values in order of increasing severity:
> # debug5, debug4, debug3, debug2, debug1,
> # info, notice, warning, error, panic(off)
>
> log_min_duration_statement = 1000 # Log all statements whose
> # execution time exceeds the value, in
> # milliseconds. -1 disables. Zero logs
> # all statements.
>
> silent_mode = false # DO NOT USE without Syslog!
>
> # - What to Log -
>
> #debug_print_parse = false
> #debug_print_rewritten = false
> #debug_print_plan = false
> #debug_pretty_print = false
> #log_connections = false
> #log_duration = false
> #log_pid = false
> #log_statement = false
> #log_timestamp = false
> #log_hostname = false
> #log_source_port = false
> ----------------------------------------------------------------------
>
> Opinions? Am I confused? Thanks for listening.
>
> Take care,
> --
> Christian Robottom Reis | http://async.com.br/~kiko/ | [+55 16] 3376 0125
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/docs/faq
>
--
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,
> OK, what if we change the documentaiton to be:
>
> log_min_duration_statement = 1000 # Log all statements whose
> # execution time exceeds the value, in
> # milliseconds. -1 disables. Zero logs
> # all statements and their durations.
>
> I think you are confused because log_min_duration_statement is really
> about _when_ to log (duration > ? ms), and what to log (the statement).
No, I see what Christian is complaining about. If one sets
log_statement="All", then all statements will be logged regardless of
duration or the setting in log_min_duration_statement. So it should
actually read:
log_min_duration_statement = 1000 # Log all statements whose
# execution time exceeds the value, in
# milliseconds. -1 disables. This is in addition to
# any statements logged according to
log_statement.
I'm with Christian on wanting to change the behavior so that it does what
the comments says it does currently, but I don't think we'll get that done
today.
--Josh
--
--Josh
Josh Berkus
Aglio Database Solutions
San Francisco
On Tue, Jun 28, 2005 at 09:22:55PM -0400, Bruce Momjian wrote:
> I think you are confused because log_min_duration_statement is really
> about _when_ to log (duration > ? ms), and what to log (the statement).
Right. In a way it is an "additional option" that acts independently of
log_statement and log_duration, and as such, should be described or even
categorized separately.
> OK, what if we change the documentaiton to be:
>
> log_min_duration_statement = 1000 # Log all statements whose
> # execution time exceeds the value, in
> # milliseconds. -1 disables. Zero logs
> # all statements and their durations.
Well, I think the confusion that we had (interaction between
log_min_duration_statement and log_statement and log_duration) isn't
really cleared up (this isn't the first time I've seen people ask me
about it at the support center here).
> Also, if you set log_min_duration_statement = 1000, it will print every
> statement which takes over 1 second, and its duration. Are you not
> seeing that happen?
I do see it happen, but when log_duration and log_statement are enabled
you often fail to see the double-logging. log_min_duration_statement is
really an independent option that should be in a separate category.
My suggestion:
- Move log_min_duration_statement out of the "when/what" to log
categories, and put it under an "Additional logging" heading.
- Change the comment to say:
# Log all statements whose execution time exceeds this value.
# Note that this setting is independent of the log_statement and
# log_duration options above; if you set both log_statement and
# log_min_duration_statement you will get statements logged as
# per the "When to log" options, with long-running statements
# possibly logged twice.
#
# Time in milliseconds. -1 disables. Zero logs all statements
# and their durations.
log_min_duration_statement = 1000
(sorry for the formatting fix, but it really improved
readability; it's not critical of course)
You could just use the second half of the suggestion, but moving it out
of the section probably matches better the mental model we are trying
to suggest to end-users.
I agree the comment still isn't the clearest, but the only way to really
clarify would be to change the behaviour of log_min_duration_statement
to really be a "When" type of option (i.e., only controlled when to log,
and having the "What" options define what).
Take care,
--
Christian Robottom Reis | http://async.com.br/~kiko/ | [+55 16] 3376 0125
Josh Berkus wrote: > Bruce, > > > OK, what if we change the documentaiton to be: > > > > log_min_duration_statement = 1000 # Log all statements whose > > # execution time exceeds the value, in > > # milliseconds. -1 disables. Zero logs > > # all statements and their durations. > > > > I think you are confused because log_min_duration_statement is really > > about _when_ to log (duration > ? ms), and what to log (the statement). > > No, I see what Christian is complaining about. If one sets > log_statement="All", then all statements will be logged regardless of > duration or the setting in log_min_duration_statement. So it should > actually read: > > log_min_duration_statement = 1000 # Log all statements whose > # execution time exceeds the value, in > # milliseconds. -1 disables. This is in addition to > # any statements logged according to > log_statement. > > I'm with Christian on wanting to change the behavior so that it does what > the comments says it does currently, but I don't think we'll get that done > today. I have updated the documentation to be clearer that this is a complex setting. The old docs were not very clear on this point. Attached and applied. I don't know we can ever combine this with log_statement and log_duration because log_statement prints when the statement starts, not when it completes. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania 19073 Index: doc/src/sgml/runtime.sgml =================================================================== RCS file: /cvsroot/pgsql/doc/src/sgml/runtime.sgml,v retrieving revision 1.332 diff -c -c -r1.332 runtime.sgml *** doc/src/sgml/runtime.sgml 26 Jun 2005 19:16:04 -0000 1.332 --- doc/src/sgml/runtime.sgml 1 Jul 2005 13:25:51 -0000 *************** *** 2628,2643 **** </indexterm> <listitem> <para> ! Sets a minimum statement execution time (in milliseconds) ! that causes a statement to be logged. All SQL statements ! that run for the time specified or longer will be logged with ! their duration. Setting this to zero will print ! all queries and their durations. Minus-one (the default) ! disables the feature. For example, if you set it to ! <literal>250</literal> then all SQL statements that run 250ms ! or longer will be logged. Enabling this option can be ! useful in tracking down unoptimized queries in your applications. ! Only superusers can change this setting. </para> </listitem> </varlistentry> --- 2628,2644 ---- </indexterm> <listitem> <para> ! Logs the statement and its duration on a single log line if its ! duration is greater than or equal to the specified number of ! milliseconds. Setting this to zero will print all statements ! and their durations. Minus-one (the default) disables the ! feature. For example, if you set it to <literal>250</literal> ! then all SQL statements that run 250ms or longer will be ! logged. Enabling this option can be useful in tracking down ! unoptimized queries in your applications. This setting is ! independent of <varname>log_statement</varname> and ! <varname>log_duration</varname>. Only superusers can change ! this setting. </para> </listitem> </varlistentry> Index: src/backend/utils/misc/postgresql.conf.sample =================================================================== RCS file: /cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v retrieving revision 1.148 diff -c -c -r1.148 postgresql.conf.sample *** src/backend/utils/misc/postgresql.conf.sample 26 Jun 2005 03:03:41 -0000 1.148 --- src/backend/utils/misc/postgresql.conf.sample 1 Jul 2005 13:25:53 -0000 *************** *** 227,233 **** # debug5, debug4, debug3, debug2, debug1, # info, notice, warning, error, panic(off) ! #log_min_duration_statement = -1 # -1 is disabled, in milliseconds. #silent_mode = false # DO NOT USE without syslog or redirect_stderr --- 227,234 ---- # debug5, debug4, debug3, debug2, debug1, # info, notice, warning, error, panic(off) ! #log_min_duration_statement = -1 # -1 is disabled, 0 logs all statements ! # and their durations, in milliseconds. #silent_mode = false # DO NOT USE without syslog or redirect_stderr