Message-ID: <4901E4ED.7090301@egsgroup.com>
Date: Fri, 24 Oct 2008 16:08:29 +0100
From: Alexander Stanier <alexander.stanier@egsgroup.com>
Organization: EGS Ltd
User-Agent: Thunderbird 2.0.0.17 (Windows/20080914)
MIME-Version: 1.0
To: pgsql-admin@postgresql.org
Subject: Change in logging behaviour between 8.1 and 8.2
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

We have just migrated our databases from version 8.1.11 to 8.2.10. The 
O/S is RHEL 5.2.

We have noticed a difference in the way statement durations are logged. 
We have the following parameters in our postgresql.conf:

log_min_duration_statement = 10000
log_duration = on
log_line_prefix = '%t [%p] [%d] '
log_statement = 'all'

We have the log_statement set to "all" so that firstly we can audit all 
statements executed on the database and secondly so that in combination 
with the durations (provided by log_duration = on) we can use a pg log 
analyser to tell us which statements are most costly, most frequent and 
slowest.

However, another tack that we take is to use log_min_duration_statement 
to flag up queries whose duration is over 10 seconds. In PostgreSQL 8.1, 
as mentioned by the documentation, this parameter "Logs the statement 
and its duration on a single log line......". This was super-useful as 
you could a command like this to find all the statements flagged by this 
parameter:

grep "ms  statement" postgresql-2008-10-24_000000.log

which would give output like this, for example:

2008-10-24 00:21:43 BST [23917] [mp_test1] LOG:  duration: 108618.981 
ms  statement: CLUSTER;
2008-10-24 00:24:38 BST [23930] [mp_test3] LOG:  duration: 172646.839 
ms  statement: VACUUM FULL VERBOSE ANALYZE;

We use this if we get peak on CPU/load and a slow down in performance to 
try and see if there is a particular query that is causing the problem. 
Whilst it is not terribly scientific it often points you in the right 
direction very quickly.

In PostgreSQL 8.2, it seems the statement and duration are no longer 
logged together (i.e. not on the same log line) which means that you 
can't easily decipher those durations/statements which have been logged 
by log_duration/log_statement from those that have been logged by 
log_min_duration_statement. The fact that they were on one line made 
them very easy to pull out of the logs.

Was this change intentional? Is there any way around it? We could write 
a script which finds durations greater than 10000 ms and then reverse 
search for the statement but I am not sure it will be terribly efficient 
as we tend to generate nearly 10GB of logs each day. Would be grateful 
for any thoughts/help.

Regards,
Alex Stanier.


This message has been scanned for malware by SurfControl plc. www.surfcontrol.com