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