From: Alexander Stanier <alexander.stanier@egsgroup.com>
To: pgsql-admin@postgresql.org
Subject: Change in logging behaviour between 8.1 and 8.2
Date: Fri, 24 Oct 2008 16:08:29 +0100
Message-ID: <4901E4ED.7090301@egsgroup.com> (raw)
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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-admin@postgresql.org
Cc: alexander.stanier@egsgroup.com
Subject: Re: Change in logging behaviour between 8.1 and 8.2
In-Reply-To: <4901E4ED.7090301@egsgroup.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox