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@xxxxxxxxxxxx> 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
--
Sent via pgsql-admin mailing list (pgsql-admin@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin
