Thread: log_duration / log_min_duration_statement differences between 8.1.8 and 8.2.4

Hi,

We're starting to migrate from postgres 8.1.8 to 8.2.4
and noticing behavioral differences in what they log (via syslog to /var/log/pgsql)

The behavior we have on 8.1.8 is:
* log all data-modification queries (with duration)
* log all queries that take longer than 1000 millisec (with duration)


We'd like to have that behavior on 8.2.x as well.

Instead we're getting:
* log all data-modification queries (with duration)
* log all queries that take longer than 1000 millisec (with duration)
  PLUS
*  (unwanted)  log durations only for fast, non-mod queries
example:
Sep 26 09:03:50 db02 postgres[3882]: [78-1] db=our_db; user=app_writer; host=a.b.c.d; LOG:  duration: 0.030 ms

When I set
    log_duration = off
I avoid the unwanted durations of fast SELECTs, but also lose the durations of the data-modification queries.

* log all data-modification queries (  WITHOUT   duration)
* log all queries that take longer than 1000 millisec (with duration)


Any suggestions ?

 - scottb



    from our 8.1.8 postgresql.conf:

#---------------------------------------------------------------------------
# ERROR REPORTING AND LOGGING
#---------------------------------------------------------------------------

# - Where to Log -
log_destination = 'syslog'
redirect_stderr = off

#silent_mode = off

# These are relevant when logging to syslog:
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'

# - When to Log -
client_min_messages = warning
log_min_messages = warning
log_error_verbosity = default
log_min_error_statement = error
log_min_duration_statement  = 1000

# - What to Log -
#debug_print_parse = off
#debug_print_rewritten = off
#debug_print_plan = off
#debug_pretty_print = off

log_connections = on
#log_disconnections = off
log_duration  = on
log_line_prefix = 'db=%d; user=%u; host=%h; '

log_statement = 'mod'



    from our postgres 8.2.4   postgresql.conf:

#---------------------------------------------------------------------------
# ERROR REPORTING AND LOGGING
#---------------------------------------------------------------------------

# - Where to Log -
log_destination = 'syslog'
redirect_stderr = off

#silent_mode = off

# These are relevant when logging to syslog:
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'

# - When to Log -
client_min_messages = warning
log_min_messages = warning
log_error_verbosity = default
log_min_error_statement = error
log_min_duration_statement = 1000

# - What to Log -
#debug_print_parse = off
#debug_print_rewritten = off
#debug_print_plan = off
#debug_pretty_print = off

log_connections = on
#log_disconnections = off


log_duration = off    ##  logs just the queries we want (mod + slow), but without durations
##  XOR
log_duration = on     ##  logs the queries we want, with durations, PLUS duration loglines for all the fast SELECTs


log_line_prefix = 'db=%d; user=%u; host=%h; '

log_statement = 'mod'

scottb@intercastingcorp.com wrote:
> Hi,
>
> We're starting to migrate from postgres 8.1.8 to 8.2.4
> and noticing behavioral differences in what they log (via syslog to /var/log/pgsql)
>
> The behavior we have on 8.1.8 is:
> * log all data-modification queries (with duration)
> * log all queries that take longer than 1000 millisec (with duration)
>
>
> We'd like to have that behavior on 8.2.x as well.
>
> Instead we're getting:
> * log all data-modification queries (with duration)
> * log all queries that take longer than 1000 millisec (with duration)
>   PLUS
> *  (unwanted)  log durations only for fast, non-mod queries
> example:
> Sep 26 09:03:50 db02 postgres[3882]: [78-1] db=our_db; user=app_writer; host=a.b.c.d; LOG:  duration: 0.030 ms
>
> When I set
>     log_duration = off
> I avoid the unwanted durations of fast SELECTs, but also lose the durations of the data-modification queries.
>
> * log all data-modification queries (  WITHOUT   duration)
> * log all queries that take longer than 1000 millisec (with duration)
>
>
> Any suggestions ?

Uh, not sure. It is this change in 8.2 that is causing the issue:

     * Change log_duration to output even if the query is not output (Tom)

       In prior releases, log_duration only printed if the query
       appeared earlier in the log.

We had a pretty long discussion about it:

    http://archives.postgresql.org/pgsql-hackers/2006-09/msg00681.php

My guess is that you were using that the behavior about the querying
having to appear earlier in the log.   I don't think we have a solution
for this anymore, but the API is cleaner.  ;-)

--
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://postgres.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +