Subject: log_min_duration_statement versus log_statement

From: Christian Robottom Reis <[email-masked]>
Date: Tue, 21 Jun 2005 15:18:32 -0300

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

---

From: Bruce Momjian <[email-masked]>
Date: Tue, 28 Jun 2005 21:22:55 -0400 (EDT)

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:
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
> 
>                http://www.postgresql.org/docs/faq
> 

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  [email-masked]               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073

---

From: Christian Robottom Reis <[email-masked]>
Date: Wed, 29 Jun 2005 16:40:20 -0300

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

> 	                 # 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).

> statement which takes over 1 second, and its duration.  Are you not

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,

---

From: Josh Berkus <[email-masked]>
Date: Wed, 29 Jun 2005 14:32:55 -0700

Bruce,

> 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

---

From: Bruce Momjian <[email-masked]>
Date: Fri, 1 Jul 2005 09:32:13 -0400 (EDT)

> the comments says it does currently, but I don't think we'll get that done 

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
  [email-masked]               |  (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 ----
  				 
! #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