Message-ID: <49217587.4030709@egsgroup.com>
Date: Mon, 17 Nov 2008 13:45:43 +0000
From: Ben Webber <ben.webber@egsgroup.com>
User-Agent: Thunderbird 2.0.0.17 (X11/20081109)
MIME-Version: 1.0
To: pgsql-admin@postgresql.org
Cc: Alexander Stanier <alexander.stanier@egsgroup.com>
Subject: Re: Change in logging behaviour between 8.1 and 8.2
References: <4901E4ED.7090301@egsgroup.com> <6092.1224892561@sss.pgh.pa.us>
In-Reply-To: <6092.1224892561@sss.pgh.pa.us>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit

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

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 script a 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. Here is 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 of the 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