Thread: Change in logging behaviour between 8.1 and 8.2
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
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
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
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.
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
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 >
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