Re: Change in logging behaviour between 8.1 and 8.2

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(dot)stanier(at)egsgroup(dot)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