Change in logging behaviour between 8.1 and 8.2

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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

--
Sent via pgsql-admin mailing list (pgsql-admin@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

[Index of Archives]     [KVM ARM]     [KVM ia64]     [KVM ppc]     [Virtualization Tools]     [Spice Development]     [Libvirt]     [Libvirt Users]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite Questions]     [Linux Kernel]     [Linux SCSI]     [XFree86]

  Powered by Linux