How to read log files
Hi,
I am currently trying to debug an issue we are experiencing and i have
turned the server logging onto debug level 5 and filtering out the LOG
messages, i still need some advice on how to interpret them. I an extract
from the log is:
2006-08-03 09:37:21.643 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.644 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.644 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.647 CEST LOG: statement: PREPARE S_1 AS BEGIN
2006-08-03 09:37:21.648 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.648 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.648 CEST LOG: statement: PREPARE <unnamed> AS select
nextval ('hibernate_sequence')
2006-08-03 09:37:21.649 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.649 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select nextval ('hibernate_sequence')] //get the number in sequence (1)
2006-08-03 09:37:21.746 CEST LOG: statement: PREPARE <unnamed> AS insert
into SampleData (mBuffer, mID) values ($1, $2)
2006-08-03 09:37:21.747 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.747 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
insert into SampleData (mBuffer, mID) values ($1, $2)]
2006-08-03 09:37:21.761 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.762 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.762 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.763 CEST LOG: statement: PREPARE S_1 AS BEGIN
2006-08-03 09:37:21.764 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.764 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.764 CEST LOG: statement: PREPARE <unnamed> AS select
sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1
2006-08-03 09:37:21.766 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.767 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1]
2006-08-03 09:37:21.784 CEST LOG: statement: PREPARE S_2 AS COMMIT
2006-08-03 09:37:21.785 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.785 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.796 CEST LOG: statement: PREPARE S_2 AS COMMIT
2006-08-03 09:37:21.796 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.796 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.827 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.827 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.827 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.828 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.828 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.829 CEST LOG: statement: PREPARE <unnamed> AS select
nextval ('hibernate_sequence')
2006-08-03 09:37:21.829 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.829 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select nextval ('hibernate_sequence')]//get the number in sequence (2)
2006-08-03 09:37:21.850 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.850 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.850 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.851 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.851 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.852 CEST LOG: statement: PREPARE <unnamed> AS select
sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1
2006-08-03 09:37:21.852 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.853 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1]
2006-08-03 09:37:21.856 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.856 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.864 CEST LOG: statement: PREPARE <unnamed> AS insert
into SampleData (mBuffer, mID) values ($1, $2)
2006-08-03 09:37:21.864 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.865 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
insert into SampleData (mBuffer, mID) values ($1, $2)]
2006-08-03 09:37:21.865 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.865 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.868 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.868 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.868 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.868 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.868 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.869 CEST LOG: statement: PREPARE <unnamed> AS select
nextval ('hibernate_sequence')
2006-08-03 09:37:21.869 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.870 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select nextval ('hibernate_sequence')]//get the number in sequence (3)
2006-08-03 09:37:21.875 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.875 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.875 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.875 CEST LOG: statement: PREPARE <unnamed> AS insert
into SampleData (mBuffer, mID) values ($1, $2)
2006-08-03 09:37:21.876 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.876 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.876 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.876 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
insert into SampleData (mBuffer, mID) values ($1, $2)]
2006-08-03 09:37:21.877 CEST LOG: statement: PREPARE <unnamed> AS select
sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1
2006-08-03 09:37:21.877 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.877 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.877 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.878 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1]
2006-08-03 09:37:21.879 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.879 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.879 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.880 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.880 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.880 CEST LOG: statement: PREPARE <unnamed> AS select
nextval ('hibernate_sequence')
2006-08-03 09:37:21.881 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.881 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select nextval ('hibernate_sequence')]//get the number in sequence (4)
2006-08-03 09:37:21.889 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.889 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.897 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.897 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.897 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.897 CEST LOG: statement: PREPARE <unnamed> AS insert
into SampleData (mBuffer, mID) values ($1, $2)
2006-08-03 09:37:21.897 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.897 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.897 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.898 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
insert into SampleData (mBuffer, mID) values ($1, $2)]
2006-08-03 09:37:21.898 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.898 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
COMMIT]
2006-08-03 09:37:21.898 CEST LOG: statement: PREPARE <unnamed> AS select
sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1
2006-08-03 09:37:21.899 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.899 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select sampledata0_.mID as mID0_0_, sampledata0_.mBuffer as mBuffer0_0_ from
SampleData sampledata0_ where sampledata0_.mID=$1]
2006-08-03 09:37:21.910 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.910 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
BEGIN]
2006-08-03 09:37:21.910 CEST LOG: statement: PREPARE <unnamed> AS SELECT 1
2006-08-03 09:37:21.910 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.911 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
SELECT 1]
2006-08-03 09:37:21.911 CEST LOG: statement: PREPARE <unnamed> AS select
nextval ('hibernate_sequence')
2006-08-03 09:37:21.912 CEST LOG: statement: <BIND>
2006-08-03 09:37:21.912 CEST LOG: statement: EXECUTE <unnamed> [PREPARE:
select nextval ('hibernate_sequence')]//get the number in sequence (5)
2006-08-03 09:37:21.921 CEST LOG: statement: <BIND>
The main difficulty i am having at the moment is knowing which commit
belongs to which statement (especially when you have 2 or more statements),
does it work like a stack structure where the last statement is committed
first, or more like a queue where that statements are committed in the order
in which the were issued. Also as you can see from the above log extract it
has a lot of $1 and $2 is there anyway to print these out in the log as well
?
Thanks,
Andy
On Aug 3, 2006, at 8:33 AM, Andy Dale wrote:
I am currently trying to debug an issue we are experiencing and i
have turned the server logging onto debug level 5 and filtering out
the LOG messages, i still need some advice on how to interpret
them. I an extract from the log is:
[snip]
The main difficulty i am having at the moment is knowing which
commit belongs to which statement (especially when you have 2 or
more statements), does it work like a stack structure where the
last statement is committed first, or more like a queue where that
statements are committed in the order in which the were issued.
Also as you can see from the above log extract it has a lot of $1
and $2 is there anyway to print these out in the log as well ?
Have you tried running with log_statement enabled? I find that
incredibly useful for tracking application behavior from the postgres
logs.
http://www.postgresql.org/docs/8.1/static/runtime-config-
logging.html#RUNTIME-CONFIG-LOGGING-WHAT
--
Thomas F. O'Connell
Sitening, LLC
http://www.sitening.com/
3004B Poston Avenue
Nashville, TN 37203-1314
615-469-5150 x802
615-469-5151 (fax)
I have tried messing with the logging settings in postgres.conf but it
always displays $1, i have set every level to debug 5 and logging all
statements, but i still have had no success.
Andy
Show quoted text
On 8/3/06, Thomas F. O'Connell <tfo@sitening.com> wrote:
On Aug 3, 2006, at 8:33 AM, Andy Dale wrote:
I am currently trying to debug an issue we are experiencing and i
have turned the server logging onto debug level 5 and filtering out
the LOG messages, i still need some advice on how to interpret
them. I an extract from the log is:[snip]
The main difficulty i am having at the moment is knowing which
commit belongs to which statement (especially when you have 2 or
more statements), does it work like a stack structure where the
last statement is committed first, or more like a queue where that
statements are committed in the order in which the were issued.
Also as you can see from the above log extract it has a lot of $1
and $2 is there anyway to print these out in the log as well ?Have you tried running with log_statement enabled? I find that
incredibly useful for tracking application behavior from the postgres
logs.http://www.postgresql.org/docs/8.1/static/runtime-config-
logging.html#RUNTIME-CONFIG-LOGGING-WHAT--
Thomas F. O'Connell
Sitening, LLChttp://www.sitening.com/
3004B Poston Avenue
Nashville, TN 37203-1314
615-469-5150 x802
615-469-5151 (fax)