| From: | "Andy Dale" <andy(dot)dale(at)gmail(dot)com> |
|---|---|
| To: | pgsql-general(at)postgresql(dot)org |
| Subject: | How to read log files |
| Date: | 2006-08-03 13:33:40 |
| Message-ID: | faa313130608030633l341f798dx6c924e6276c87655@mail.gmail.com |
| Views: | Raw Message | Whole Thread | Download mbox | Resend email |
| Thread: | |
| Lists: | pgsql-general |
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
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Thomas F. O'Connell | 2006-08-03 14:21:14 | Re: How to read log files |
| Previous Message | Tom Lane | 2006-08-03 13:08:44 | Re: Rebuilding DB from broken hardrive. |