Re: Change in logging behaviour between 8.1 and 8.2 - Mailing list pgsql-admin

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