Thread: Change in logging behaviour between 8.1 and 8.2

Change in logging behaviour between 8.1 and 8.2

From
Alexander Stanier
Date:
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

Re: Change in logging behaviour between 8.1 and 8.2

From
Tom Lane
Date:
Alexander Stanier <alexander.stanier@egsgroup.com> writes:
> We have the following parameters in our postgresql.conf:
> log_min_duration_statement = 10000
> log_duration = on
> log_statement = 'all'

> 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?

Yes.  People complained about double logging of the full statement text.

            regards, tom lane

Re: Change in logging behaviour between 8.1 and 8.2

From
Ben Webber
Date:
Hi,

I wrote a shell script to find the duration and the related statement in the log file and place them one after the
otherif the duration is over a specified time like this:- 

2008-10-31 02:00:49 GMT [23683] [mp_live] LOG:  statement: CLUSTER;
2008-10-31 02:04:42 GMT [23683] [mp_live] LOG: duration: 232783.684 ms

It is worth noting that we have log_line_prefix set to '%t [%p] [%d] ' in postgresql.conf, so you may need to edit the
scripta little if your log_line_prefix is different to ours. 
It assumes the logfile is gzipped. You will need to adjust TMP_PATH to point to where you want it to gunzip the file.
Hereis the script in case anybody is interested:- 

#!/bin/bash
TMP_PATH=/data/tmp
if [ -z ${1} ] || [ -z ${2} ] ; then
        echo "usage: ${0} [min_query_time_in_ms] [absolute_path_to_logfile]"
        exit 1
fi
PG_LOG_FILE_NAME=$(basename ${2%.gz})
QUEREY_TIME=${1}
exit_function() {
        echo -n "Cleaning up... "
        rm -f ${TMP_PATH}/${PG_LOG_FILE_NAME}*
        echo " ...done"
        exit
}
trap 'echo SIGINT trap caught; exit_function' 2
trap 'echo SIGKILL trap caught; exit_function' 9
trap 'echo SIGTERM trap caught; exit_function' 15
[ -e ${2} ] || exit 1
cd ${TMP_PATH}
if [ -e ${PG_LOG_FILE_NAME}.gz ] || [ ! -e ${PG_LOG_FILE_NAME} ] ; then
        echo -n "Copying logfile to "${TMP_PATH}"... "
        cp ${2} .
        echo " ...done"
fi
if [ ! -e ${PG_LOG_FILE_NAME} ] ; then
        echo -n "Gunziping logfile... "
        gunzip ${PG_LOG_FILE_NAME}
        echo " ...done"
fi
echo
grep -n duration ${PG_LOG_FILE_NAME} | awk -F ":" '{print $1}' | while read DURATION_LINE_NUM ; do
        CURRENT_LINE=$(head -n${DURATION_LINE_NUM} ${PG_LOG_FILE_NAME} | tail -n1)
        if [ $(echo ${CURRENT_LINE} | awk '{print $8}' | awk -F "." '{print $1}') -ge ${QUEREY_TIME} ] ; then
                head -n${DURATION_LINE_NUM} ${PG_LOG_FILE_NAME} | tail -n$(echo ${DURATION_LINE_NUM} -
${PREV_DURATION_LINE_NUM}| bc) \ 
                        | grep statement | grep $(echo "${CURRENT_LINE}" | awk '{print $4}' | sed
's/\(\[\)\(.*\)\(\]\)/\\\1\2\\\3/g')| head -n1 
                echo ${CURRENT_LINE}
        fi
        PREV_DURATION_LINE_NUM=${DURATION_LINE_NUM}
done

One problem I noticed is that if the statement has a carriage return in it, the script will only show up to the point
ofthe carriage return, not really a massive issue for me, but worth noting also. 

Ben Webber.

Tom Lane wrote:
> Alexander Stanier <alexander.stanier@egsgroup.com> writes:
>> We have the following parameters in our postgresql.conf:
>> log_min_duration_statement = 10000
>> log_duration = on
>> log_statement = 'all'
>
>> 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?
>
> Yes.  People complained about double logging of the full statement text.
>
>             regards, tom lane
>


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

Re: Change in logging behaviour between 8.1 and 8.2

From
Alvaro Herrera
Date:
Ben Webber wrote:
> Hi,
>
> I wrote a shell script to find the duration and the related statement in the log file and place them one after the
otherif the duration is over a specified time like this:- 
>
> 2008-10-31 02:00:49 GMT [23683] [mp_live] LOG:  statement: CLUSTER;
> 2008-10-31 02:04:42 GMT [23683] [mp_live] LOG: duration: 232783.684 ms

I wonder if you'd benefit from doing CSV logs and then storing them into
a table.  Querying using SQL is probably going to be easier (and more
robust -- it'd work even with embedded newlines etc).

--
Alvaro Herrera                                http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.

Re: Change in logging behaviour between 8.1 and 8.2

From
Ben Webber
Date:
Sorry, meant 2 gigs, not 10.

An interesting suggestion, but the problem with storing the logfiles in
a table for us would be that uncompressed, the log file for a day is
about 10 gigs. This would mean that an unacceptable amount of excess
data would accumulate in the database. It would be feasible however to
write a script to import the archived logfile into a new temporary
database on a different server, then use SQL to search it and delete the
db when finished.

Thanks for the suggestion though.

Ben.



Alvaro Herrera wrote:
> Ben Webber wrote:
>> Hi,
>>
>> I wrote a shell script to find the duration and the related statement in the log file and place them one after the
otherif the duration is over a specified time like this:- 
>>
>> 2008-10-31 02:00:49 GMT [23683] [mp_live] LOG:  statement: CLUSTER;
>> 2008-10-31 02:04:42 GMT [23683] [mp_live] LOG: duration: 232783.684 ms
>
> I wonder if you'd benefit from doing CSV logs and then storing them into
> a table.  Querying using SQL is probably going to be easier (and more
> robust -- it'd work even with embedded newlines etc).
>



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

Re: Change in logging behaviour between 8.1 and 8.2

From
Ben Webber
Date:
Arrrghhh, it was was actually 10 (not that it really makes any
difference), should have actually waited for file to unzip before posting!!!

Ben Webber wrote:
> Sorry, meant 2 gigs, not 10.
>
> An interesting suggestion, but the problem with storing the logfiles in
> a table for us would be that uncompressed, the log file for a day is
> about 10 gigs. This would mean that an unacceptable amount of excess
> data would accumulate in the database. It would be feasible however to
> write a script to import the archived logfile into a new temporary
> database on a different server, then use SQL to search it and delete the
> db when finished.
>
> Thanks for the suggestion though.
>
> Ben.
>
>
>
> Alvaro Herrera wrote:
>> Ben Webber wrote:
>>> Hi,
>>>
>>> I wrote a shell script to find the duration and the related statement
>>> in the log file and place them one after the other if the duration is
>>> over a specified time like this:-
>>>
>>> 2008-10-31 02:00:49 GMT [23683] [mp_live] LOG:  statement: CLUSTER;
>>> 2008-10-31 02:04:42 GMT [23683] [mp_live] LOG: duration: 232783.684 ms
>>
>> I wonder if you'd benefit from doing CSV logs and then storing them into
>> a table.  Querying using SQL is probably going to be easier (and more
>> robust -- it'd work even with embedded newlines etc).
>>
>
>
>
> This message has been scanned for malware by SurfControl plc.
> www.surfcontrol.com
>

Re: Change in logging behaviour between 8.1 and 8.2

From
Ben Webber
Date:
An interesting suggestion, but the problem with storing the logfiles in
a table for us would be that uncompressed, the log file for a day is
about 10 gigs. This would mean that an unacceptable amount of excess
data would accumulate in the database. It would be feasible however to
write a script to import the archived logfile into a new temporary
database on a different server, then use SQL to search it and delete the
db when finished.

Thanks for the suggestion though.

Ben.



Alvaro Herrera wrote:
> Ben Webber wrote:
>> Hi,
>>
>> I wrote a shell script to find the duration and the related statement in the log file and place them one after the
otherif the duration is over a specified time like this:- 
>>
>> 2008-10-31 02:00:49 GMT [23683] [mp_live] LOG:  statement: CLUSTER;
>> 2008-10-31 02:04:42 GMT [23683] [mp_live] LOG: duration: 232783.684 ms
>
> I wonder if you'd benefit from doing CSV logs and then storing them into
> a table.  Querying using SQL is probably going to be easier (and more
> robust -- it'd work even with embedded newlines etc).
>


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