pg.ddx.io pgsql-admin@postgresql.org mailing list archive
help / color / mirror / Atom feedChange in logging behaviour between 8.1 and 8.2
7+ messages / 4 participants
[nested] [flat]
* Change in logging behaviour between 8.1 and 8.2
@ 2008-10-24 15:08 Alexander Stanier <alexander.stanier@egsgroup.com>
0 siblings, 1 reply; 7+ messages in thread
From: Alexander Stanier @ 2008-10-24 15:08 UTC (permalink / raw)
To: pgsql-admin
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Change in logging behaviour between 8.1 and 8.2
@ 2008-10-24 23:56 Tom Lane <tgl@sss.pgh.pa.us>
parent: Alexander Stanier <alexander.stanier@egsgroup.com>
0 siblings, 1 reply; 7+ messages in thread
From: Tom Lane @ 2008-10-24 23:56 UTC (permalink / raw)
To: Alexander Stanier <alexander.stanier@egsgroup.com>; +Cc: pgsql-admin
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Change in logging behaviour between 8.1 and 8.2
@ 2008-11-17 13:45 Ben Webber <ben.webber@egsgroup.com>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 7+ messages in thread
From: Ben Webber @ 2008-11-17 13:45 UTC (permalink / raw)
To: pgsql-admin; +Cc: Alexander Stanier <alexander.stanier@egsgroup.com>
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Change in logging behaviour between 8.1 and 8.2
@ 2008-11-17 14:58 Alvaro Herrera <alvherre@commandprompt.com>
parent: Ben Webber <ben.webber@egsgroup.com>
0 siblings, 2 replies; 7+ messages in thread
From: Alvaro Herrera @ 2008-11-17 14:58 UTC (permalink / raw)
To: Ben Webber <ben.webber@egsgroup.com>; +Cc: pgsql-admin@postgresql.org, Alexander Stanier <alexander.stanier@egsgroup.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 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).
--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Change in logging behaviour between 8.1 and 8.2
@ 2008-11-17 15:18 Ben Webber <ben.webber@egsgroup.com>
parent: Alvaro Herrera <alvherre@commandprompt.com>
1 sibling, 0 replies; 7+ messages in thread
From: Ben Webber @ 2008-11-17 15:18 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: pgsql-admin@postgresql.org, Alexander Stanier <alexander.stanier@egsgroup.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 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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Change in logging behaviour between 8.1 and 8.2
@ 2008-11-17 15:24 Ben Webber <ben.webber@egsgroup.com>
parent: Alvaro Herrera <alvherre@commandprompt.com>
1 sibling, 1 reply; 7+ messages in thread
From: Ben Webber @ 2008-11-17 15:24 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: pgsql-admin@postgresql.org, Alexander Stanier <alexander.stanier@egsgroup.com>
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Change in logging behaviour between 8.1 and 8.2
@ 2008-11-17 15:31 Ben Webber <ben.webber@egsgroup.com>
parent: Ben Webber <ben.webber@egsgroup.com>
0 siblings, 0 replies; 7+ messages in thread
From: Ben Webber @ 2008-11-17 15:31 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: pgsql-admin@postgresql.org, Alexander Stanier <alexander.stanier@egsgroup.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
>
^ permalink raw reply [nested|flat] 7+ messages in thread
end of thread, other threads:[~2008-11-17 15:31 UTC | newest]
Thread overview: 7+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2008-10-24 15:08 Change in logging behaviour between 8.1 and 8.2 Alexander Stanier <alexander.stanier@egsgroup.com>
2008-10-24 23:56 ` Tom Lane <tgl@sss.pgh.pa.us>
2008-11-17 13:45 ` Ben Webber <ben.webber@egsgroup.com>
2008-11-17 14:58 ` Alvaro Herrera <alvherre@commandprompt.com>
2008-11-17 15:18 ` Ben Webber <ben.webber@egsgroup.com>
2008-11-17 15:24 ` Ben Webber <ben.webber@egsgroup.com>
2008-11-17 15:31 ` Ben Webber <ben.webber@egsgroup.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox