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
