log_min_duration_statement versus log_statement

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

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

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

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