How to read log files - Mailing list pgsql-general

From Andy Dale
Subject How to read log files
Date
Msg-id faa313130608030633l341f798dx6c924e6276c87655@mail.gmail.com
Whole thread Raw
Responses Re: How to read log files  ("Thomas F. O'Connell" <tfo@sitening.com>)
List 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

pgsql-general by date:

Previous
From: Hannes Dorbath
Date:
Subject: Re: TSearch: Need debug help
Next
From: "Thomas F. O'Connell"
Date:
Subject: Re: How to read log files