Thread: 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